diff --git a/openhands/core/logger.py b/openhands/core/logger.py index 28fba6390ca6..3bde50da8cda 100644 --- a/openhands/core/logger.py +++ b/openhands/core/logger.py @@ -6,18 +6,24 @@ import traceback from datetime import datetime from types import TracebackType -from typing import Any, Literal, Mapping +from typing import Any, Literal, Mapping, TextIO import warnings with warnings.catch_warnings(): warnings.simplefilter('ignore') import litellm +from pythonjsonlogger.json import JsonFormatter from termcolor import colored LOG_LEVEL = os.getenv('LOG_LEVEL', 'INFO').upper() DEBUG = os.getenv('DEBUG', '').lower() in ['true', '1'] DEBUG_LLM = os.getenv('DEBUG_LLM', '').lower() in ['true', '1'] +# 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( @@ -303,10 +309,36 @@ def get_file_handler( f.write('') 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) @@ -344,7 +376,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.addFilter(RedactDataUriFilter()) openhands_logger.propagate = False diff --git a/poetry.lock b/poetry.lock index 8dd0c4fa39ad..7520c17399b3 100644 --- a/poetry.lock +++ b/poetry.lock @@ -7598,7 +7598,7 @@ version = "3.2.1" description = "JSON Log Formatter for the Python Logging Package" optional = false python-versions = ">=3.8" -groups = ["runtime"] +groups = ["main", "runtime"] files = [ {file = "python_json_logger-3.2.1-py3-none-any.whl", hash = "sha256:cdc17047eb5374bd311e748b42f99d71223f3b0e186f4206cc5d52aefe85b090"}, {file = "python_json_logger-3.2.1.tar.gz", hash = "sha256:8eb0554ea17cb75b05d2848bc14fb02fbdbd9d6972120781b974380bfa162008"}, @@ -8938,7 +8938,7 @@ files = [ [package.dependencies] greenlet = [ - {version = "!=0.4.17", markers = "python_version < \"3.14\" and (platform_machine == \"aarch64\" or platform_machine == \"ppc64le\" or platform_machine == \"x86_64\" or platform_machine == \"amd64\" or platform_machine == \"AMD64\" or platform_machine == \"win32\" or platform_machine == \"WIN32\")"}, + {version = "!=0.4.17", optional = true, markers = "python_version < \"3.14\" and (platform_machine == \"aarch64\" or platform_machine == \"ppc64le\" or platform_machine == \"x86_64\" or platform_machine == \"amd64\" or platform_machine == \"AMD64\" or platform_machine == \"win32\" or platform_machine == \"WIN32\") or extra == \"asyncio\""}, {version = "!=0.4.17", optional = true, markers = "python_version < \"3.14\" and (platform_machine == \"aarch64\" or platform_machine == \"ppc64le\" or platform_machine == \"x86_64\" or platform_machine == \"amd64\" or platform_machine == \"AMD64\" or platform_machine == \"win32\" or platform_machine == \"WIN32\") or extra == \"asyncio\""}, ] typing-extensions = ">=4.6.0" @@ -10855,4 +10855,4 @@ testing = ["coverage[toml]", "zope.event", "zope.testing"] [metadata] lock-version = "2.1" python-versions = "^3.12" -content-hash = "86ed19317e08fe0393af44fbc9b3df0da54e48ca40898e3ab23f935ac406349d" +content-hash = "83da0b681253a79417c9842862cdd102c1ab6e8770d9dd9e0c42bc7994be2cd0" diff --git a/pyproject.toml b/pyproject.toml index 0a2087d4501c..9e6d51be0257 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -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 = "*" diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index e225313a0710..54d602def3a1 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -1,3 +1,4 @@ +import json import logging from io import StringIO from unittest.mock import patch @@ -5,6 +6,7 @@ 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', + }