Structured logging mode (#7034)

Author: raymyers

openhands/core/logger.py

@@ -6,15 +6,21 @@
 import traceback
 from datetime import datetime
 from types import TracebackType
-from typing import Any, Literal, Mapping
+from typing import Any, Literal, Mapping, TextIO
 
 import litellm
+from pythonjsonlogger.json import JsonFormatter
 from termcolor import colored
 
 LOG_LEVEL = os.getenv('LOG_LEVEL', 'INFO').upper()
 DEBUG = os.getenv('DEBUG', 'False').lower() in ['true', '1', 'yes']
 DEBUG_LLM = os.getenv('DEBUG_LLM', 'False').lower() in ['true', '1', 'yes']
 
+# Structured logs with JSON, disabled by default
+LOG_JSON = os.getenv('LOG_JSON', 'False').lower() in ['true', '1', 'yes']
+LOG_JSON_LEVEL_KEY = os.getenv('LOG_JSON_LEVEL_KEY', 'level')
+
+
 # Configure litellm logging based on DEBUG_LLM
 if DEBUG_LLM:
     confirmation = input(
@@ -294,10 +300,36 @@ def get_file_handler(
     file_name = f'openhands_{timestamp}.log'
     file_handler = logging.FileHandler(os.path.join(log_dir, file_name))
     file_handler.setLevel(log_level)
-    file_handler.setFormatter(file_formatter)
+    if LOG_JSON:
+        file_handler.setFormatter(json_formatter())
+    else:
+        file_handler.setFormatter(file_formatter)
     return file_handler
 
 
+def json_formatter():
+    return JsonFormatter(
+        '{message}{levelname}',
+        style='{',
+        rename_fields={'levelname': LOG_JSON_LEVEL_KEY},
+        timestamp=True,
+    )
+
+
+def json_log_handler(
+    level: int = logging.INFO,
+    _out: TextIO = sys.stdout,
+) -> logging.Handler:
+    """
+    Configure logger instance for structured logging as json lines.
+    """
+
+    handler = logging.StreamHandler(_out)
+    handler.setLevel(level)
+    handler.setFormatter(json_formatter())
+    return handler
+
+
 # Set up logging
 logging.basicConfig(level=logging.ERROR)
 
@@ -335,7 +367,11 @@ def log_uncaught_exceptions(
     LOG_TO_FILE = True
     openhands_logger.debug('DEBUG mode enabled.')
 
-openhands_logger.addHandler(get_console_handler(current_log_level))
+if LOG_JSON:
+    openhands_logger.addHandler(json_log_handler(current_log_level))
+else:
+    openhands_logger.addHandler(get_console_handler(current_log_level))
+
 openhands_logger.addFilter(SensitiveDataFilter(openhands_logger.name))
 openhands_logger.propagate = False
 openhands_logger.debug('Logging initialized')

poetry.lock

@@ -77,6 +77,7 @@ ipywidgets = "^8.1.5"
 qtconsole = "^5.6.1"
 memory-profiler = "^0.61.0"
 daytona-sdk = "0.9.1"
+python-json-logger = "^3.2.1"
 
 [tool.poetry.group.llama-index.dependencies]
 llama-index = "*"
@@ -109,6 +110,7 @@ reportlab = "*"
 [tool.coverage.run]
 concurrency = ["gevent"]
 
+
 [tool.poetry.group.runtime.dependencies]
 jupyterlab = "*"
 notebook = "*"
@@ -137,6 +139,7 @@ ignore = ["D1"]
 [tool.ruff.lint.pydocstyle]
 convention = "google"
 
+
 [tool.poetry.group.evaluation.dependencies]
 streamlit = "*"
 whatthepatch = "*"

pyproject.toml

@@ -1,10 +1,12 @@
+import json
 import logging
 from io import StringIO
 from unittest.mock import patch
 
 import pytest
 
 from openhands.core.config import AppConfig, LLMConfig
+from openhands.core.logger import json_log_handler
 from openhands.core.logger import openhands_logger as openhands_logger
 
 
@@ -20,6 +22,15 @@ def test_handler():
     openhands_logger.removeHandler(handler)
 
 
+@pytest.fixture
+def json_handler():
+    stream = StringIO()
+    json_handler = json_log_handler(logging.INFO, _out=stream)
+    openhands_logger.addHandler(json_handler)
+    yield openhands_logger, stream
+    openhands_logger.removeHandler(json_handler)
+
+
 def test_openai_api_key_masking(test_handler):
     logger, stream = test_handler
 
@@ -118,3 +129,34 @@ def test_special_cases_masking(test_handler):
         log_output = stream.getvalue()
         for attr, value in environ.items():
             assert value not in log_output
+
+
+class TestLogOutput:
+    def test_info(self, json_handler):
+        logger, string_io = json_handler
+
+        logger.info('Test message')
+        output = json.loads(string_io.getvalue())
+        assert 'timestamp' in output
+        del output['timestamp']
+        assert output == {'message': 'Test message', 'level': 'INFO'}
+
+    def test_error(self, json_handler):
+        logger, string_io = json_handler
+
+        logger.error('Test message')
+        output = json.loads(string_io.getvalue())
+        del output['timestamp']
+        assert output == {'message': 'Test message', 'level': 'ERROR'}
+
+    def test_extra_fields(self, json_handler):
+        logger, string_io = json_handler
+
+        logger.info('Test message', extra={'key': '..val..'})
+        output = json.loads(string_io.getvalue())
+        del output['timestamp']
+        assert output == {
+            'key': '..val..',
+            'message': 'Test message',
+            'level': 'INFO',
+        }