Refactor logging in pr_reviewer.py, litellm_ai_handler.py, and pr_description.py for improved debugging

mrT23 · mrT23 · commit b40894b9dbbf · 2024-02-24T20:38:31.000+02:00
diff --git a/pr_agent/algo/ai_handlers/litellm_ai_handler.py b/pr_agent/algo/ai_handlers/litellm_ai_handler.py
@@ -113,6 +113,10 @@ async def chat_completion(self, model: str, system: str, user: str, temperature:
             }
             if self.aws_bedrock_client:
                 kwargs["aws_bedrock_client"] = self.aws_bedrock_client
+
+            get_logger().debug(f"\nSystem prompt:\n{system}")
+            get_logger().debug(f"\nUser prompt:\n{user}")
+
             response = await acompletion(**kwargs)
         except (APIError, Timeout, TryAgain) as e:
             get_logger().error("Error during OpenAI inference: ", e)
@@ -127,7 +131,9 @@ async def chat_completion(self, model: str, system: str, user: str, temperature:
             raise TryAgain
         resp = response["choices"][0]['message']['content']
         finish_reason = response["choices"][0]["finish_reason"]
-        usage = response.get("usage")
-        get_logger().info("AI response", response=resp, messages=messages, finish_reason=finish_reason,
-                          model=model, usage=usage)
+
+        # usage = response.get("usage")
+        get_logger().debug(f"\nAI response:\n{resp}")
+        get_logger().debug("\nAI response extra details", response=response)
+
         return resp, finish_reason
diff --git a/pr_agent/algo/pr_processing.py b/pr_agent/algo/pr_processing.py
@@ -225,11 +225,10 @@ async def retry_with_fallback_models(f: Callable, model_type: ModelType = ModelT
     # try each (model, deployment_id) pair until one is successful, otherwise raise exception
     for i, (model, deployment_id) in enumerate(zip(all_models, all_deployments)):
         try:
-            if get_settings().config.verbosity_level >= 2:
-                get_logger().debug(
-                    f"Generating prediction with {model}"
-                    f"{(' from deployment ' + deployment_id) if deployment_id else ''}"
-                )
+            get_logger().debug(
+                f"Generating prediction with {model}"
+                f"{(' from deployment ' + deployment_id) if deployment_id else ''}"
+            )
             get_settings().set("openai.deployment_id", deployment_id)
             return await f(model)
         except Exception as e:
diff --git a/pr_agent/cli.py b/pr_agent/cli.py
@@ -6,7 +6,8 @@
 from pr_agent.config_loader import get_settings
 from pr_agent.log import setup_logger
 
-setup_logger()
+log_level = os.environ.get("LOG_LEVEL", "INFO")
+setup_logger(log_level)
 
 
 
diff --git a/pr_agent/git_providers/git_provider.py b/pr_agent/git_providers/git_provider.py
@@ -57,9 +57,12 @@ def get_pr_description(self, *, full: bool = True) -> str:
         return description
 
     def get_user_description(self) -> str:
+        if hasattr(self, 'user_description') and not (self.user_description is None):
+            return self.user_description
+
         description = (self.get_pr_description_full() or "").strip()
         description_lowercase = description.lower()
-        get_logger().info(f"Existing description:\n{description_lowercase}")
+        get_logger().debug(f"Existing description:\n{description_lowercase}")
 
         # if the existing description wasn't generated by the pr-agent, just return it as-is
         if not self._is_generated_by_pr_agent(description_lowercase):
@@ -94,6 +97,7 @@ def get_user_description(self) -> str:
                 original_user_description = original_user_description[len(user_description_header):].strip()
 
         get_logger().info(f"Extracted user description from existing description:\n{original_user_description}")
+        self.user_description = original_user_description
         return original_user_description
 
     def _possible_headers(self):
diff --git a/pr_agent/git_providers/utils.py b/pr_agent/git_providers/utils.py
@@ -38,7 +38,7 @@ def apply_repo_settings(pr_url):
                         section_dict[key] = value
                     get_settings().unset(section)
                     get_settings().set(section, section_dict, merge=False)
-                    get_logger().info(f"Applying repo settings for section {section}, contents: {contents}")
+                get_logger().info(f"Applying repo settings:\n{new_settings.as_dict()}")
         except Exception as e:
             get_logger().exception("Failed to apply repo settings", e)
         finally:
diff --git a/pr_agent/log/__init__.py b/pr_agent/log/__init__.py
@@ -1,5 +1,6 @@
 import json
 import logging
+import os
 import sys
 from enum import Enum
 
@@ -20,7 +21,7 @@ def setup_logger(level: str = "INFO", fmt: LoggingFormat = LoggingFormat.CONSOLE
     if type(level) is not int:
         level = logging.INFO
 
-    if fmt == LoggingFormat.JSON:
+    if fmt == LoggingFormat.JSON and os.getenv("LOG_SANE", "0").lower() == "0":  # better debugging github_app
         logger.remove(None)
         logger.add(
             sys.stdout,
diff --git a/pr_agent/tools/pr_code_suggestions.py b/pr_agent/tools/pr_code_suggestions.py
@@ -72,14 +72,16 @@ def __init__(self, pr_url: str, cli_mode=False, args: list = None,
     async def run(self):
         try:
             get_logger().info('Generating code suggestions for PR...')
+            relevant_configs = {'pr_code_suggestions': dict(get_settings().pr_code_suggestions),
+                                'config': dict(get_settings().config)}
+            get_logger().debug(f"Relevant configs:\n{relevant_configs}")
 
             if get_settings().config.publish_output:
                 if self.git_provider.is_supported("gfm_markdown"):
                     self.progress_response = self.git_provider.publish_comment(self.progress)
                 else:
                     self.git_provider.publish_comment("Preparing suggestions...", is_temporary=True)
 
-            get_logger().info('Preparing PR code suggestions...')
             if not self.is_extended:
                 await retry_with_fallback_models(self._prepare_prediction, ModelType.TURBO)
                 data = self._prepare_pr_code_suggestions()
@@ -97,10 +99,8 @@ async def run(self):
                 data['code_suggestions'] = await self.rank_suggestions(data['code_suggestions'])
 
             if get_settings().config.publish_output:
-                get_logger().info('Pushing PR code suggestions...')
                 self.git_provider.remove_initial_comment()
                 if get_settings().pr_code_suggestions.summarize and self.git_provider.is_supported("gfm_markdown"):
-                    get_logger().info('Pushing summarize code suggestions...')
 
                     # generate summarized suggestions
                     pr_body = self.generate_summarized_suggestions(data)
@@ -117,7 +117,6 @@ async def run(self):
                         self.git_provider.publish_comment(pr_body)
 
                 else:
-                    get_logger().info('Pushing inline code suggestions...')
                     self.push_inline_code_suggestions(data)
                     if self.progress_response:
                         self.progress_response.delete()
@@ -133,25 +132,23 @@ async def _prepare_prediction(self, model: str):
                                         model,
                                         add_line_numbers_to_hunks=True,
                                         disable_extra_lines=True)
-
-        get_logger().info('Getting AI prediction...')
-        self.prediction = await self._get_prediction(model, patches_diff)
+        if self.patches_diff:
+            get_logger().debug(f"PR diff:\n{self.patches_diff}")
+            self.prediction = await self._get_prediction(model, patches_diff)
+        else:
+            get_logger().error(f"Error getting PR diff")
+            self.prediction = None
 
     async def _get_prediction(self, model: str, patches_diff: str):
         variables = copy.deepcopy(self.vars)
         variables["diff"] = patches_diff  # update diff
         environment = Environment(undefined=StrictUndefined)
         system_prompt = environment.from_string(get_settings().pr_code_suggestions_prompt.system).render(variables)
         user_prompt = environment.from_string(get_settings().pr_code_suggestions_prompt.user).render(variables)
-        if get_settings().config.verbosity_level >= 2:
-            get_logger().info(f"\nSystem prompt:\n{system_prompt}")
-            get_logger().info(f"\nUser prompt:\n{user_prompt}")
+
         response, finish_reason = await self.ai_handler.chat_completion(model=model, temperature=0.2,
                                                                         system=system_prompt, user=user_prompt)
 
-        if get_settings().config.verbosity_level >= 2:
-            get_logger().info(f"\nAI response:\n{response}")
-
         return response
 
     def _prepare_pr_code_suggestions(self) -> Dict:
@@ -185,8 +182,6 @@ def push_inline_code_suggestions(self, data):
 
         for d in data['code_suggestions']:
             try:
-                if get_settings().config.verbosity_level >= 2:
-                    get_logger().info(f"suggestion: {d}")
                 relevant_file = d['relevant_file'].strip()
                 relevant_lines_start = int(d['relevant_lines_start'])  # absolute position
                 relevant_lines_end = int(d['relevant_lines_end'])
@@ -202,8 +197,7 @@ def push_inline_code_suggestions(self, data):
                                              'relevant_lines_start': relevant_lines_start,
                                              'relevant_lines_end': relevant_lines_end})
             except Exception:
-                if get_settings().config.verbosity_level >= 2:
-                    get_logger().info(f"Could not parse suggestion: {d}")
+                get_logger().info(f"Could not parse suggestion: {d}")
 
         is_successful = self.git_provider.publish_code_suggestions(code_suggestions)
         if not is_successful:
@@ -229,8 +223,7 @@ def dedent_code(self, relevant_file, relevant_lines_start, new_code_snippet):
                 if delta_spaces > 0:
                     new_code_snippet = textwrap.indent(new_code_snippet, delta_spaces * " ").rstrip('\n')
         except Exception as e:
-            if get_settings().config.verbosity_level >= 2:
-                get_logger().info(f"Could not dedent code snippet for file {relevant_file}, error: {e}")
+            get_logger().error(f"Could not dedent code snippet for file {relevant_file}, error: {e}")
 
         return new_code_snippet
 
@@ -245,32 +238,33 @@ def _get_is_extended(self, args: list[str]) -> bool:
         return False
 
     async def _prepare_prediction_extended(self, model: str) -> dict:
-        get_logger().info('Getting PR diff...')
         patches_diff_list = get_pr_multi_diffs(self.git_provider, self.token_handler, model,
                                                max_calls=get_settings().pr_code_suggestions.max_number_of_calls)
+        if patches_diff_list:
+            get_logger().debug(f"PR diff:\n{patches_diff_list}")
 
-        # parallelize calls to AI:
-        if get_settings().pr_code_suggestions.parallel_calls:
-            get_logger().info('Getting multi AI predictions in parallel...')
-            prediction_list = await asyncio.gather(*[self._get_prediction(model, patches_diff) for patches_diff in patches_diff_list])
-            self.prediction_list = prediction_list
-        else:
-            get_logger().info('Getting multi AI predictions...')
-            prediction_list = []
-            for i, patches_diff in enumerate(patches_diff_list):
-                get_logger().info(f"Processing chunk {i + 1} of {len(patches_diff_list)}")
-                prediction = await self._get_prediction(model, patches_diff)
-                prediction_list.append(prediction)
-
-        data = {}
-        for prediction in prediction_list:
-            self.prediction = prediction
-            data_per_chunk = self._prepare_pr_code_suggestions()
-            if "code_suggestions" in data:
-                data["code_suggestions"].extend(data_per_chunk["code_suggestions"])
+            # parallelize calls to AI:
+            if get_settings().pr_code_suggestions.parallel_calls:
+                prediction_list = await asyncio.gather(*[self._get_prediction(model, patches_diff) for patches_diff in patches_diff_list])
+                self.prediction_list = prediction_list
             else:
-                data.update(data_per_chunk)
-        self.data = data
+                prediction_list = []
+                for i, patches_diff in enumerate(patches_diff_list):
+                    prediction = await self._get_prediction(model, patches_diff)
+                    prediction_list.append(prediction)
+
+            data = {}
+            for prediction in prediction_list:
+                self.prediction = prediction
+                data_per_chunk = self._prepare_pr_code_suggestions()
+                if "code_suggestions" in data:
+                    data["code_suggestions"].extend(data_per_chunk["code_suggestions"])
+                else:
+                    data.update(data_per_chunk)
+            self.data = data
+        else:
+            get_logger().error(f"Error getting PR diff")
+            self.data = data = None
         return data
 
     async def rank_suggestions(self, data: List) -> List:
@@ -305,9 +299,7 @@ async def rank_suggestions(self, data: List) -> List:
             system_prompt = environment.from_string(get_settings().pr_sort_code_suggestions_prompt.system).render(
                 variables)
             user_prompt = environment.from_string(get_settings().pr_sort_code_suggestions_prompt.user).render(variables)
-            if get_settings().config.verbosity_level >= 2:
-                get_logger().info(f"\nSystem prompt:\n{system_prompt}")
-                get_logger().info(f"\nUser prompt:\n{user_prompt}")
+
             response, finish_reason = await self.ai_handler.chat_completion(model=model, system=system_prompt,
                                                                             user=user_prompt)
 
diff --git a/pr_agent/tools/pr_description.py b/pr_agent/tools/pr_description.py
diff --git a/pr_agent/tools/pr_reviewer.py b/pr_agent/tools/pr_reviewer.py
