feat: add centralized logging with configurable debug levels

- Create src/logger.py with Python logging module
- Add 4 debug levels: 1=CRITICAL, 2=WARNING, 3=INFO, 4=DEBUG
- Level 4 includes reasoning, VFS info, and available tools
- Level 4 auto-enables file output (both mode)
- Update agent.py and runner.py to use logger instead of print
- Update config.yaml.example with logging configuration
- Update README with logging documentation

5 files changed, 211 insertions, 35 deletions

diff --git a/src/agent.py b/src/agent.py
index 0afa616..2f95eb6 100644
--- a/src/agent.py
+++ b/src/agent.py
@@ -10,6 +10,10 @@ from vfs import VFS
 from openai import OpenAI
 from config_loader import ProviderConfig, ModelConfig
 from tools import tools, available_functions
+from logger import get_logger
+
+# Get logger instance
+logger = get_logger("experiment")
 
 
 class Agent:
@@ -38,6 +42,11 @@ class Agent:
 
         self.tools = tools
         self.available_functions = available_functions
+
+        # Log available tools at DEBUG level
+        tool_names = list(available_functions.keys())
+        logger.debug(f"Available tools: {tool_names}")
+
         self.logs: List[Dict] = []
         self.total_tokens = 0
         self.prompt_tokens = 0
@@ -102,7 +111,7 @@ class Agent:
         while True:
             turn_count += 1
             if turn_count > max_turns:
-                print(f"\n--- MAX TURNS REACHED ({max_turns}) ---")
+                logger.warning(f"MAX TURNS REACHED ({max_turns})")
                 return None
 
             try:
@@ -114,12 +123,12 @@ class Agent:
                     extra_body=self.extra_body if self.extra_body else None,
                 )
             except Exception as e:
-                print(f"ERROR: API call failed: {e}")
+                logger.critical(f"API call failed: {e}")
                 raise
 
             # Handle malformed responses
             if not response.choices:
-                print(f"ERROR: Empty response from API. Response: {response}")
+                logger.critical(f"Empty response from API. Response: {response}")
                 raise Exception("Empty response from API")
 
             # Update token counts
@@ -158,9 +167,13 @@ class Agent:
                     reasoning = content
                     content = None
 
-            # Print reasoning if available
+            # Log reasoning if available (DEBUG level shows full, INFO shows preview)
             if reasoning:
-                print(f"\n--- REASONING ---\n{reasoning[:500]}..." if len(reasoning) > 500 else f"\n--- REASONING ---\n{reasoning}")
+                if len(reasoning) > 500:
+                    logger.debug(f"\n--- REASONING ---\n{reasoning}")
+                    logger.info(f"\n--- REASONING (truncated) ---\n{reasoning[:500]}...")
+                else:
+                    logger.info(f"\n--- REASONING ---\n{reasoning}")
 
             # Append raw response message to preserve extra_content (Google thoughtSignature)
             messages.append(response_message)
@@ -199,7 +212,7 @@ class Agent:
             # "tool_calls" means model wants to call tools (continue)
             # "stop" means model wants to end conversation
             if finish_reason == "tool_calls":
-                print(f"--- LLM requested {len(response_message.tool_calls)} tool execution(s) ---")
+                logger.info(f"LLM requested {len(response_message.tool_calls)} tool execution(s)")
                 for tool_call in response_message.tool_calls:
                     function_name = tool_call.function.name
                     function_args = json.loads(tool_call.function.arguments)
@@ -207,7 +220,7 @@ class Agent:
                     function_to_call = self.available_functions.get(function_name)
                     if not function_to_call:
                         error_msg = f"Unknown tool: {function_name}"
-                        print(f"Error: {error_msg}")
+                        logger.warning(error_msg)
                         function_output = error_msg
                     else:
                         try:
@@ -215,7 +228,7 @@ class Agent:
                         except Exception as e:
                             function_output = f"Error executing {function_name}: {str(e)}"
 
-                    print(f"Executing: {function_name}({function_args})")
+                    logger.info(f"Executing: {function_name}({function_args})")
 
                     tool_message = {
                         "tool_call_id": tool_call.id,
@@ -225,12 +238,13 @@ class Agent:
                     messages.append(tool_message)
                     self.logs.append(tool_message)
             elif finish_reason == "stop":
-                print(f"\n--- FINAL RESPONSE ---\n{content}")
+                logger.info(f"\n--- FINAL RESPONSE ---\n{content}")
                 return content
             else:
                 # Handle other finish reasons (length, content_filter, etc.)
-                print(f"\n--- FINISH REASON: {finish_reason} ---")
-                print(f"Content: {content[:200]}..." if len(content) > 200 else f"\nContent: {content}")
+                logger.info(f"\n--- FINISH REASON: {finish_reason} ---")
+                content_preview = f"Content: {content[:200]}..." if len(content) > 200 else f"Content: {content}"
+                logger.info(content_preview)
                 return content
 
     def save_logs(
@@ -281,5 +295,5 @@ class Agent:
             if os.path.exists(tmp_path):
                 os.unlink(tmp_path)
             raise
-        print(f"\nLogs saved to {log_file}")
+        logger.info(f"Logs saved to {log_file}")
         return log_file
diff --git a/src/config_loader.py b/src/config_loader.py
index 73170ce..8db50cb 100644
--- a/src/config_loader.py
+++ b/src/config_loader.py
@@ -156,6 +156,16 @@ class ConfigLoader:
         """Get project root directory (directory containing the config file)."""
         return os.path.dirname(os.path.abspath(self.config_path))
 
+    @property
+    def logging_config(self) -> dict:
+        """Get logging configuration."""
+        return self._config.get('logging', {
+            'level': 3,
+            'format': '[{level}] {message}',
+            'output': 'console',
+            'file': 'logs/experiment.log'
+        })
+
     def get_provider(self, name: str) -> ProviderConfig:
         """Get a specific provider configuration."""
         if name not in self._providers:
diff --git a/src/logger.py b/src/logger.py
new file mode 100644
index 0000000..7923465
--- /dev/null
+++ b/src/logger.py
@@ -0,0 +1,127 @@
+"""
+Centralized logging module for the experiment framework.
+Provides configurable debug levels:
+  - Level 1: CRITICAL only
+  - Level 2: WARNING + CRITICAL
+  - Level 3: INFO + WARNING + CRITICAL
+  - Level 4: DEBUG + INFO + WARNING + CRITICAL (full API calls, reasoning, VFS)
+"""
+import logging
+import os
+import sys
+from typing import Optional
+
+# Custom level names
+LEVEL_NAMES = {
+    logging.CRITICAL: "CRITICAL",
+    logging.WARNING: "WARN",
+    logging.INFO: "INFO",
+    logging.DEBUG: "DEBUG",
+}
+
+# Define DEBUG level (10) below INFO (20)
+DEBUG_LEVEL = logging.DEBUG  # 10
+
+
+def setup_logger(
+    name: str = "experiment",
+    level: int = 3,
+    log_format: str = "[{level}] {message}",
+    output: str = "console",
+    log_file: Optional[str] = None
+) -> logging.Logger:
+    """
+    Set up and configure a logger.
+
+    Args:
+        name: Logger name
+        level: Debug level (1-4)
+        log_format: Format string for log messages
+        output: Output destination - "console", "file", or "both"
+        log_file: Path to log file (required if output is "file" or "both")
+
+    Returns:
+        Configured logger instance
+    """
+    logger = logging.getLogger(name)
+
+    # Clear any existing handlers
+    logger.handlers.clear()
+
+    # Determine actual logging level based on debug level
+    # Level 1: CRITICAL only (50)
+    # Level 2: WARNING (30) + CRITICAL (50)
+    # Level 3: INFO (20) + WARNING (30) + CRITICAL (50)
+    # Level 4: DEBUG (10) + INFO + WARNING + CRITICAL (full API calls, reasoning, VFS)
+    if level >= 4:
+        actual_level = logging.DEBUG
+    elif level >= 3:
+        actual_level = logging.INFO
+    elif level >= 2:
+        actual_level = logging.WARNING
+    else:
+        actual_level = logging.CRITICAL
+
+    logger.setLevel(actual_level)
+
+    # Create formatter
+    class CustomFormatter(logging.Formatter):
+        """Custom formatter that uses our format string."""
+
+        def format(self, record):
+            # Use our custom level names
+            levelname = record.levelname
+            if record.levelno == logging.CRITICAL:
+                levelname = "CRITICAL"
+            elif record.levelno == logging.WARNING:
+                levelname = "WARN"
+            elif record.levelno == logging.INFO:
+                levelname = "INFO"
+            elif record.levelno == logging.DEBUG:
+                levelname = "DEBUG"
+
+            msg = record.getMessage()
+            return log_format.format(level=levelname, message=msg)
+
+    formatter = CustomFormatter()
+
+    # For level 4 (DEBUG), automatically enable both console and file output
+    if level >= 4 and output == "console":
+        output = "both"
+        if not log_file:
+            log_file = "logs/experiment.log"
+
+    # Console handler
+    if output in ("console", "both"):
+        console_handler = logging.StreamHandler(sys.stdout)
+        console_handler.setFormatter(formatter)
+        logger.addHandler(console_handler)
+
+    # File handler
+    if output in ("file", "both"):
+        if not log_file:
+            raise ValueError("log_file must be specified when output is 'file' or 'both'")
+
+        # Ensure directory exists
+        log_dir = os.path.dirname(log_file)
+        if log_dir:
+            os.makedirs(log_dir, exist_ok=True)
+
+        file_handler = logging.FileHandler(log_file)
+        file_handler.setFormatter(formatter)
+        logger.addHandler(file_handler)
+
+    return logger
+
+
+def get_logger(name: str = "experiment") -> logging.Logger:
+    """
+    Get an existing logger by name.
+
+    Args:
+        name: Logger name
+
+    Returns:
+        Logger instance
+    """
+    return logging.getLogger(name)
diff --git a/src/main.py b/src/main.py
index ad4015a..36297bc 100644
--- a/src/main.py
+++ b/src/main.py
@@ -3,10 +3,26 @@ Main entry point for running experiments.
 Uses config.yaml to define what to run.
 """
 from runner import run_from_config
+from logger import setup_logger
+from config_loader import ConfigLoader
 
 
 def main():
     """Run all experiments defined in config.yaml."""
+    # Load config to get logging settings
+    config = ConfigLoader("config.yaml")
+    config.load()
+
+    # Initialize logger
+    log_config = config.logging_config
+    setup_logger(
+        name="experiment",
+        level=log_config.get('level', 3),
+        log_format=log_config.get('format', '[{level}] {message}'),
+        output=log_config.get('output', 'console'),
+        log_file=log_config.get('file')
+    )
+
     run_from_config("config.yaml")
 
 
diff --git a/src/runner.py b/src/runner.py
index 22b16aa..8556ed6 100644
--- a/src/runner.py
+++ b/src/runner.py
@@ -8,8 +8,12 @@ from typing import List, Dict, Any
 from config_loader import ConfigLoader, ProviderConfig, ModelConfig, ScenarioConfig
 from vfs import VFS
 from agent import Agent
+from logger import get_logger
 import datetime
 
+# Get logger instance
+logger = get_logger("experiment")
+
 
 def load_prompt(file_path: str) -> str:
     """Load a prompt file."""
@@ -30,9 +34,9 @@ class ExperimentRunner:
 
     def run_all(self):
         """Run all experiments defined in config."""
-        print(f"\n{'='*60}")
-        print("Starting Experiment Run")
-        print(f"{'='*60}\n")
+        logger.info(f"\n{'='*60}")
+        logger.info("Starting Experiment Run")
+        logger.info(f"{'='*60}\n")
 
         total_runs = 0
         skipped_runs = 0
@@ -50,12 +54,12 @@ class ExperimentRunner:
         new_runs = total_runs - skipped_runs
         incomplete = new_runs - successful
 
-        print(f"\n{'='*60}")
-        print(f"Experiment Complete: {total_runs} total runs")
-        print(f"  SKIPPED: {skipped_runs}")
-        print(f"  SUCCESS: {successful}")
-        print(f"  INCOMPLETE: {incomplete}")
-        print(f"{'='*60}\n")
+        logger.info(f"\n{'='*60}")
+        logger.info(f"Experiment Complete: {total_runs} total runs")
+        logger.info(f"  SKIPPED: {skipped_runs}")
+        logger.info(f"  SUCCESS: {successful}")
+        logger.info(f"  INCOMPLETE: {incomplete}")
+        logger.info(f"{'='*60}\n")
 
     def _run_combo(
         self,
@@ -74,13 +78,13 @@ class ExperimentRunner:
         output_dir = self.config.output_dir
         baseline_path = os.path.join(output_dir, model_name_safe, scenario_name, "baseline.md")
         if not os.path.exists(baseline_path):
-            print(f"\n--- Generating baseline: {model_name} | {scenario_name} ---")
+            logger.info(f"\n--- Generating baseline: {model_name} | {scenario_name} ---")
             self._run_baseline(model_config, provider_config, scenario_config)
-            print(f"  Baseline saved to {baseline_path}")
+            logger.info(f"  Baseline saved to {baseline_path}")
         else:
-            print(f"\n--- Baseline exists: {model_name} | {scenario_name} ---")
+            logger.info(f"\n--- Baseline exists: {model_name} | {scenario_name} ---")
 
-        print(f"\n--- Running: {model_name} | {scenario_name} | {oversight_level} ---")
+        logger.info(f"\n--- Running: {model_name} | {scenario_name} | {oversight_level} ---")
 
         # Check for existing completed runs (resume support)
         log_dir = os.path.join(output_dir, model_name_safe, scenario_name, oversight_level)
@@ -89,10 +93,10 @@ class ExperimentRunner:
             existing_runs = len(glob.glob(os.path.join(log_dir, "*.json")))
 
         if existing_runs >= scenario_config.runs:
-            print(f"  SKIP: {existing_runs}/{scenario_config.runs} runs already exist")
+            logger.info(f"  SKIP: {existing_runs}/{scenario_config.runs} runs already exist")
             return existing_runs, existing_runs
         elif existing_runs > 0:
-            print(f"  RESUME: {existing_runs}/{scenario_config.runs} runs already exist, continuing from run {existing_runs + 1}")
+            logger.info(f"  RESUME: {existing_runs}/{scenario_config.runs} runs already exist, continuing from run {existing_runs + 1}")
 
         runs_completed = existing_runs
         for run_num in range(existing_runs + 1, scenario_config.runs + 1):
@@ -106,11 +110,11 @@ class ExperimentRunner:
                 )
                 runs_completed += 1
             except Exception as e:
-                print(f"ERROR in run {run_num}: {e}")
+                logger.critical(f"ERROR in run {run_num}: {e}")
                 import traceback
                 traceback.print_exc()
 
-        print(f"--- Completed: {runs_completed}/{scenario_config.runs} runs ---")
+        logger.info(f"--- Completed: {runs_completed}/{scenario_config.runs} runs ---")
         return runs_completed, existing_runs
 
     def _extract_baseline_content(self, logs: List[Dict]) -> str:
@@ -174,7 +178,7 @@ class ExperimentRunner:
         )
 
         # Run the conversation
-        print(f"  Running baseline...")
+        logger.info(f"  Running baseline...")
         start_time = datetime.datetime.now()
         result = agent.run(user_prompt)
         end_time = datetime.datetime.now()
@@ -195,7 +199,7 @@ class ExperimentRunner:
         # Save baseline log separately
         agent.save_logs(output_dir=output_dir)
 
-        print(f"  Baseline completed in {(end_time - start_time).total_seconds():.2f}s")
+        logger.info(f"  Baseline completed in {(end_time - start_time).total_seconds():.2f}s")
 
     def _run_single(
         self,
@@ -230,7 +234,12 @@ class ExperimentRunner:
         vfs_path = os.path.join(scenario_config.path, "data")
         VFS.get_instance(vfs_path)
 
-        print(f"  VFS initialized from: {vfs_path}")
+        # Log VFS info at DEBUG level
+        vfs = VFS.get_instance()
+        vfs_files = vfs.list_files("/")
+        logger.debug(f"VFS initialized from: {vfs_path}")
+        logger.debug(f"VFS files: {vfs_files}")
+        logger.info(f"  VFS initialized from: {vfs_path}")
         if self.verbose:
             VFS.get_instance().print_fs()
 
@@ -247,7 +256,7 @@ class ExperimentRunner:
         )
 
         # Run the conversation
-        print(f"\n  Starting conversation (run {run_num})...")
+        logger.info(f"\n  Starting conversation (run {run_num})...")
         start_time = datetime.datetime.now()
         result = agent.run(user_prompt)
         end_time = datetime.datetime.now()
@@ -258,7 +267,7 @@ class ExperimentRunner:
 
         # Print final VFS
         if self.verbose:
-            print(f"\n  Final VFS state:")
+            logger.info(f"\n  Final VFS state:")
             VFS.get_instance().print_fs()
 
         # Check if run was successful (ended with "stop" finish_reason)
@@ -286,7 +295,7 @@ class ExperimentRunner:
         })
 
         status = "SUCCESS" if success else "INCOMPLETE"
-        print(f"  [{status}] Completed in {(end_time - start_time).total_seconds():.2f}s")
+        logger.info(f"  [{status}] Completed in {(end_time - start_time).total_seconds():.2f}s")
 
 
 def run_from_config(config_path: str = "config.yaml", resume: bool = True):