feat: improving logging coverage at main decision points

rbazin · rbazin · commit 43c66e7c67e7 · 2025-08-26T10:51:58.000-04:00
diff --git a/src/earth_reach/cli.py b/src/earth_reach/cli.py
@@ -210,15 +210,11 @@ def generate(
             ValueError: If arguments are invalid or conflicting
             RuntimeError: If description generation fails
         """
+        logger.info("Starting description generation...")
         try:
-            if verbose:
-                logger.info(f"Validating image: {image_path}")
             validated_image_path = validate_image_path(image_path)
             image = Image.open(validated_image_path)
 
-            if verbose:
-                logger.info("Resolving prompts...")
-
             system_prompt_text = resolve_prompt(
                 system_prompt,
                 system_prompt_file_path,
@@ -237,16 +233,23 @@ def generate(
             if verbose:
                 if system_prompt_text:
                     logger.info(
-                        f"System prompt length: {len(system_prompt_text)} characters",
+                        "System prompt length: %d characters", len(system_prompt_text)
                     )
 
                 if user_prompt_text:
                     logger.info(
-                        f"User prompt length: {len(user_prompt_text)} characters",
+                        "User prompt length: %d characters", len(user_prompt_text)
                     )
 
-            if verbose:
-                logger.info("Initializing LLM...")
+            logger.debug(
+                "CLI configuration for generation",
+                extra={
+                    "provider": os.getenv("LLM_PROVIDER", "groq"),
+                    "simple_mode": simple,
+                    "max_iterations": max_iterations,
+                    "criteria_threshold": criteria_threshold,
+                },
+            )
             llm = create_llm()
 
             if verbose:
@@ -278,7 +281,7 @@ def generate(
                 )
 
             if verbose:
-                logger.info(f"Generating description for: {validated_image_path.name}")
+                logger.info("Generating description for: %s", validated_image_path.name)
 
             if simple:
                 description = generator.generate(
@@ -290,21 +293,21 @@ def generate(
 
             if verbose and isinstance(description, str):
                 logger.info("Description generated successfully!")
-                logger.info(f"Description length: {len(description)} characters")
+                logger.info("Description length: %d characters", len(description))
                 logger.info("-" * 50)
 
             print(description)
 
             return
 
         except (OSError, FileNotFoundError, ValueError) as e:
-            logger.error(f"Could not load image file: {e}", exc_info=True)
+            logger.error("Could not load image file: %s", e, exc_info=True)
             sys.exit(1)
         except RuntimeError as e:
-            logger.error(f"Generation failed: {e}", exc_info=True)
+            logger.error("Generation failed: %s", e, exc_info=True)
             sys.exit(1)
         except Exception as e:
-            logger.error(f"Unexpected error: {e}", exc_info=True)
+            logger.error("Unexpected error: %s", e, exc_info=True)
             sys.exit(1)
 
     @staticmethod
@@ -333,19 +336,14 @@ def evaluate(
             ValueError: If arguments are invalid or conflicting
             RuntimeError: If evaluation fails
         """
+        logger.info("Starting description evaluation...")
+
         if criteria is None:
             criteria = ["coherence", "fluency", "consistency", "relevance"]
-
         try:
-            if verbose:
-                logger.info(f"Validating image: {image_path}")
-
             validated_image_path = validate_image_path(image_path)
             image = Image.open(validated_image_path)
 
-            if verbose:
-                logger.info("Resolving description...")
-
             description_text = resolve_description(
                 description,
                 description_file_path,
@@ -356,7 +354,7 @@ def evaluate(
                 )
 
             if verbose:
-                logger.info(f"Description length: {len(description_text)} characters")
+                logger.info("Description length: %d characters", len(description_text))
 
             if not criteria or len(criteria) == 0:
                 raise ValueError("Criteria list cannot be empty.")
@@ -369,10 +367,18 @@ def evaluate(
                 )
 
             if verbose:
-                logger.info(f"Evaluation criteria: {', '.join(criteria)}")
+                logger.info("Evaluation criteria: %s", ", ".join(criteria))
 
             if verbose:
                 logger.info("Initializing LLM...")
+
+            logger.debug(
+                "CLI configuration for evaluation",
+                extra={
+                    "provider": os.getenv("LLM_PROVIDER", "groq"),
+                    "criteria": criteria,
+                },
+            )
             llm = create_llm()
 
             if verbose:
@@ -383,15 +389,15 @@ def evaluate(
             )
 
             if verbose:
-                logger.info(f"Evaluating description for: {validated_image_path.name}")
+                logger.info("Evaluating description for: %s", validated_image_path.name)
             evaluation = evaluator.evaluate(
                 description=description_text,
                 image=image,
             )
 
             if verbose:
                 logger.info("Evaluation completed successfully!")
-                logger.info(f"Number of criteria evaluated: {len(evaluation)}")
+                logger.info("Number of criteria evaluated: %d", len(evaluation))
                 logger.info("-" * 50)
 
             for eval in evaluation:
@@ -404,13 +410,13 @@ def evaluate(
             return
 
         except FileNotFoundError as e:
-            logger.error(f"File not found: {e}", exc_info=True)
+            logger.error("File not found: %s", e, exc_info=True)
             sys.exit(1)
         except ValueError as e:
-            logger.error(f"Invalid input: {e}", exc_info=True)
+            logger.error("Invalid input: %s", e, exc_info=True)
             sys.exit(1)
         except Exception as e:
-            logger.error(f"Evaluation failed: {e}", exc_info=True)
+            logger.error("Evaluation failed: %s", e, exc_info=True)
             sys.exit(1)
 
 
diff --git a/src/earth_reach/core/evaluator.py b/src/earth_reach/core/evaluator.py
@@ -83,7 +83,6 @@ def evaluate(
                 "Only one of 'figure' or 'image' can be provided, not both.",
             )
         if figure is not None:
-            # TODO(medium): If metadata extraction fails, continue without it
             metadata = self._get_metadata_from_figure(figure)
             self.user_prompt = self._update_user_prompt_with_metadata(
                 self.user_prompt,
@@ -409,13 +408,23 @@ def evaluate(
         try:
             evaluations = []
             for evaluator in self.evaluators:
+                logger.debug("Evaluating criterion: %s", evaluator.criterion)
                 result = evaluator.evaluate(
                     description=description,
                     figure=figure,
                     image=image,
                 )
+                logger.debug(
+                    "Criterion evaluation completed",
+                    extra={
+                        "criterion": result.name,
+                        "score": result.score,
+                        "max_score": 5,
+                    },
+                )
                 evaluations.append(result)
 
+            logger.info("Evaluator successfully evaluated the description")
             return evaluations
         except Exception as e:
             raise RuntimeError(f"Failed to evaluate description: {e}") from e
diff --git a/src/earth_reach/core/generator.py b/src/earth_reach/core/generator.py
@@ -15,8 +15,11 @@
 from PIL import Image
 from PIL.ImageFile import ImageFile
 
+from earth_reach.config.logging import get_logger
 from earth_reach.core.llm import LLMInterface
 
+logger = get_logger(__name__)
+
 
 @dataclass
 class FigureMetadata:
@@ -164,7 +167,6 @@ def generate(
                 "Only one of 'figure' or 'image' can be provided, not both.",
             )
         if figure is not None:
-            # TODO(medium): If metadata extraction fails at any point, generate image and continue without figure metadata
             metadata = self._get_metadata_from_figure(figure)
             self.user_prompt = self._update_user_prompt_with_metadata(
                 self.user_prompt,
@@ -183,8 +185,16 @@ def generate(
                 image=image,
             )
 
+            logger.debug("Parsing LLM response for structured output")
             parsed_output = self.parse_llm_response(response)
             if not parsed_output.is_complete():
+                logger.warning(
+                    "LLM response parsing incomplete",
+                    extra={
+                        "missing_fields": parsed_output.get_missing_fields(),
+                        "total_fields": len(list(fields(parsed_output))),
+                    },
+                )
                 raise ValueError(
                     "Parsed output is incomplete. Missing fields: "
                     f"{parsed_output.get_missing_fields()}",
@@ -200,6 +210,7 @@ def generate(
         except Exception as e:
             raise RuntimeError(f"Failed to generate response: {e}") from e
 
+        logger.info("Generator successfully generated a description")
         return description
 
     def parse_llm_response(self, response: str) -> GeneratorOutput:
@@ -261,6 +272,17 @@ def _get_metadata_from_figure(self, figure: ekp.Figure) -> FigureMetadata:
         metadata.xlabel = axes[0].get_xlabel()
         metadata.ylabel = axes[0].get_ylabel()
         metadata.domain = figure._domain
+
+        logger.debug(
+            "Extracted metadata from figure",
+            extra={
+                "title": metadata.title or "None",
+                "domain": metadata.domain or "None",
+                "xlabel": metadata.xlabel or "None",
+                "ylabel": metadata.ylabel or "None",
+            },
+        )
+
         return metadata
 
     def _update_user_prompt_with_metadata(
diff --git a/src/earth_reach/core/llm.py b/src/earth_reach/core/llm.py
@@ -16,12 +16,20 @@
 from google.genai import types
 from PIL.ImageFile import ImageFile
 
+from earth_reach.config.logging import get_logger
 from earth_reach.core.utils import img_to_base64, img_to_bytes
 
+logger = get_logger(__name__)
+
 
 class LLMInterface(ABC):
     """Abstract base class defining the interface for all LLM provider implementations."""
 
+    @property
+    @abstractmethod
+    def provider_name(self) -> str:
+        """Must be implemented by subclasses to return the provider name."""
+
     @abstractmethod
     def generate(
         self,
@@ -73,6 +81,10 @@ def __init__(
             api_key=api_key,
         )
 
+    @property
+    def provider_name(self):
+        return "openAICompatible"
+
     def generate(
         self,
         user_prompt: str,
@@ -139,13 +151,31 @@ def generate(
                     "The generated response content is empty or not a string"
                 )
 
+            logger.info(
+                "LLM API call completed successfully",
+                extra={
+                    "provider": self.provider_name,
+                    "model": self.model_name,
+                    "input_length": len(user_prompt),
+                    "output_length": len(content),
+                    "has_image": image is not None,
+                },
+            )
+
             return content.strip()
 
         except ValueError:
             raise
         except Exception as e:
-            error_msg = f"API call failed: {type(e).__name__}: {e}"
-            raise RuntimeError(error_msg) from e
+            logger.error(
+                "LLM API call failed",
+                extra={
+                    "provider": self.provider_name,
+                    "model": self.model_name,
+                },
+                exc_info=True,
+            )
+            raise RuntimeError("LLM API call failed") from e
 
     def __repr__(self) -> str:
         return f"LLM(model_name={self.model_name}, base_url={self.base_url})"
@@ -180,6 +210,10 @@ def __init__(self, model_name: str, api_key: str | None = None) -> None:
             base_url="https://api.groq.com/openai/v1",
         )
 
+    @property
+    def provider_name(self):
+        return "groq"
+
 
 class OpenAILLM(OpenAICompatibleLLM):
     """Implementation of the LLMInterface for OpenAI API Provider."""
@@ -210,6 +244,10 @@ def __init__(self, model_name: str, api_key: str | None = None) -> None:
             base_url="https://api.openai.com/v1",
         )
 
+    @property
+    def provider_name(self):
+        return "openAI"
+
 
 class GeminiLLM(LLMInterface):
     """Implementation of the LLMInterface for Google Gemini API Provider."""
@@ -236,6 +274,10 @@ def __init__(self, model_name: str, api_key: str | None = None) -> None:
         self.api_key = api_key
         self.client = genai.Client(api_key=api_key)
 
+    @property
+    def provider_name(self):
+        return "gemini"
+
     def generate(
         self,
         user_prompt: str,
@@ -296,13 +338,31 @@ def generate(
                     "The generated response content is empty or not a string"
                 )
 
+            logger.info(
+                "LLM API call completed successfully",
+                extra={
+                    "provider": self.provider_name,
+                    "model": self.model_name,
+                    "input_length": len(user_prompt),
+                    "output_length": len(content),
+                    "has_image": image is not None,
+                },
+            )
+
             return content.strip()
 
         except ValueError:
             raise
         except Exception as e:
-            error_msg = f"API call failed: {type(e).__name__}: {e}"
-            raise RuntimeError(error_msg) from e
+            logger.error(
+                "LLM API call failed",
+                extra={
+                    "provider": self.provider_name,
+                    "model": self.model_name,
+                },
+                exc_info=True,
+            )
+            raise RuntimeError("LLM API call failed") from e
 
     def __repr__(self) -> str:
         return f"GeminiLLM(model_name={self.model_name})"
diff --git a/src/earth_reach/core/orchestrator.py b/src/earth_reach/core/orchestrator.py
diff --git a/src/earth_reach/main.py b/src/earth_reach/main.py
