diff --git a/JSON_LOGS_REPRODUCTION.md b/JSON_LOGS_REPRODUCTION.md new file mode 100644 index 00000000000..45eaea6eb3b --- /dev/null +++ b/JSON_LOGS_REPRODUCTION.md @@ -0,0 +1,123 @@ +# JSON Logs Issue - Reproduction and Findings + +## Issue Summary + +When `json_logs: true` is configured in litellm_settings, some logs appear as plain text instead of JSON format, particularly: +- Exception tracebacks +- Health check errors +- Database errors +- Various error logs + +## Investigation Findings + +### What Works ✅ +I created several reproducers that show JSON logging **DOES work correctly** in single-process environments: +- `test_json_logs_reproducer.py` - Tests JSON logs with early environment variable +- `test_json_logs_late_enable.py` - Tests enabling JSON logs after import +- `test_logging_handlers.py` - Tests logging handler hierarchy +- `test_proxy_json_logs_reproducer.py` - Simulates exact proxy startup + +**All tests show:** +- ✅ Regular error logs are formatted as JSON +- ✅ Exceptions with `.exception()` are formatted as JSON with stacktrace field +- ✅ Module loggers (like `health_check.py`) propagate to root and format as JSON +- ✅ The `_turn_on_json()` function correctly reconfigures loggers + +### Suspected Root Cause: Multi-Worker Issue 🎯 + +The user (dmc) is likely running litellm proxy with multiple workers (gunicorn/uvicorn workers). The probable issue: + +**Problem:** `_turn_on_json()` is called in the main process during config loading, but worker processes may not inherit this logging configuration. + +**Why this happens:** +1. Main process loads config and calls `_turn_on_json()` in `proxy_cli.py:682` +2. Logging configuration is **per-process**, not shared across workers +3. When gunicorn/uvicorn spawns worker processes, they import litellm modules fresh +4. Workers get default (non-JSON) logging configuration +5. Most logs come from worker processes, not the main process + +**Evidence from user logs:** +- "Using json logs. Setting log_config to None." appears in logs +- But subsequent error logs show plain text format like: + ``` + 15:46:06 - LiteLLM:ERROR: vertex_llm_base.py:495 - Failed to load vertex credentials... + Traceback (most recent call last): + ... + ``` +- This format matches the default formatter, not JSON formatter + +## How to Reproduce + +### Prerequisites +```bash +pip install litellm[proxy] +``` + +### Test 1: Single Process (Works) +```bash +python3 test_proxy_json_logs_reproducer.py +``` + +**Expected:** All logs after "Using json logs" are JSON formatted ✅ + +### Test 2: Multi-Worker Scenario (Likely Fails) + +Create config file `test_config.yaml`: +```yaml +model_list: + - model_name: test-model + litellm_params: + model: gpt-3.5-turbo + api_key: fake-key + +litellm_settings: + json_logs: true +``` + +Run with multiple workers: +```bash +litellm --config test_config.yaml --num_workers 2 --port 4000 +``` + +Then trigger errors (health checks, invalid models, etc.) and check if logs are JSON or plain text. + +## Test Scripts Created + +1. **test_json_logs_reproducer.py** - Basic JSON logging test with early env var +2. **test_json_logs_late_enable.py** - Tests enabling JSON logs after import +3. **test_logging_handlers.py** - Detailed handler hierarchy analysis +4. **test_proxy_json_logs_reproducer.py** - Comprehensive proxy startup simulation + +All scripts demonstrate that JSON logging works correctly in single-process mode. + +## Recommended Solution + +The `_turn_on_json()` function needs to be called in each worker process, not just the main process. Possible fixes: + +1. **Call `_turn_on_json()` in worker initialization hooks** (gunicorn `post_worker_init` hook) +2. **Set `JSON_LOGS` environment variable** before starting the server (so it's set during module import in all processes) +3. **Move json_logs configuration earlier** in the import chain so it's set before any logging happens + +## Code Locations + +- JSON logging implementation: `litellm/_logging.py` +- Config loading (CLI): `litellm/proxy/proxy_cli.py:672-682` +- Config loading (server): `litellm/proxy/proxy_server.py:2491-2493` +- JsonFormatter class: `litellm/_logging.py:22-41` +- _turn_on_json function: `litellm/_logging.py:169-179` + +## Next Steps + +1. ✅ Confirmed JSON logging works in single-process mode +2. ⚠️ Need to test with multi-worker setup to confirm the issue +3. 🔧 Implement fix to ensure `_turn_on_json()` is called in all worker processes +4. ✅ Add test case for multi-worker JSON logging + +## User Environment Details + +From slack conversation: +- LiteLLM version: 1.80.13-1.80.16 +- Python: 3.13 +- Deployment: Kubernetes +- Config: `json_logs: true` in `litellm_settings` +- Observed: Mix of JSON and plain text logs, especially exceptions diff --git a/test_json_logs_config.yaml b/test_json_logs_config.yaml new file mode 100644 index 00000000000..5eb90da90d0 --- /dev/null +++ b/test_json_logs_config.yaml @@ -0,0 +1,23 @@ +model_list: + - model_name: gpt-3.5-turbo + litellm_params: + model: gpt-3.5-turbo + api_key: fake-key-to-trigger-error + + # Azure model without credentials to trigger error + - model_name: azure-gpt + litellm_params: + model: azure/gpt-35-turbo + api_base: https://fake-endpoint.openai.azure.com + api_key: fake-key + + # Vertex AI model without credentials to trigger the vertex error + - model_name: vertex-test + litellm_params: + model: vertex_ai/gemini-pro + vertex_project: fake-project + vertex_location: us-central1 + +litellm_settings: + json_logs: true + drop_params: true diff --git a/test_json_logs_late_enable.py b/test_json_logs_late_enable.py new file mode 100644 index 00000000000..2ed8384a823 --- /dev/null +++ b/test_json_logs_late_enable.py @@ -0,0 +1,94 @@ +#!/usr/bin/env python3 +""" +Reproducer for json_logs issue when enabled AFTER litellm is imported. + +This simulates what happens when using litellm proxy with json_logs: true in config, +where the logging module is imported BEFORE json_logs is enabled. +""" + +import sys + +# DO NOT set JSON_LOGS environment variable - this simulates the proxy server startup +# where the env var is not set, and json_logs is enabled later via config + +print("=" * 80) +print("Simulating litellm proxy startup with json_logs in config (not env var)") +print("=" * 80) +print() + +# Import litellm (logging will be initialized with JSON_LOGS=False) +print("Step 1: Importing litellm (json_logs not yet enabled)...") +import litellm +from litellm._logging import verbose_logger, verbose_router_logger, verbose_proxy_logger + +print(f" json_logs status after import: {litellm.json_logs}") +print() + +# Simulate some early logging before json_logs is enabled +print("Step 2: Some early logging (before json_logs enabled)...") +verbose_logger.info("Early INFO log before json_logs enabled") +verbose_logger.error("Early ERROR log before json_logs enabled") +print() + +# Now enable json_logs like the proxy server does after reading config +print("Step 3: Enabling json_logs via config (like proxy_cli.py does)...") +litellm.json_logs = True +litellm._turn_on_json() +print(f" json_logs status after _turn_on_json(): {litellm.json_logs}") +print() + +# Test logging after json_logs is enabled +print("Step 4: Testing logs after json_logs enabled...") +print() + +print("Test 1: Regular INFO log (should be JSON)") +verbose_logger.info("This is an INFO message after json_logs enabled") +print() + +print("Test 2: Regular ERROR log (should be JSON)") +verbose_logger.error("This is an ERROR message after json_logs enabled") +print() + +print("Test 3: Exception log with logger.exception() (should be JSON)") +try: + raise ValueError("Test exception after json_logs enabled") +except Exception as e: + verbose_logger.exception(f"Caught exception: {e}") +print() + +print("Test 4: Simulating vertex_ai error") +try: + import json + json.loads("") # Will raise JSONDecodeError +except Exception as e: + verbose_logger.exception( + f"Failed to load vertex credentials. Error: {str(e)}" + ) +print() + +print("Test 5: Router error") +verbose_router_logger.error( + "Could not identify azure model 'test-model'. Set azure 'base_model'..." +) +print() + +# Test logging from other loggers that might not be configured +print("Test 6: Testing root logger (might not be configured)") +import logging +root_logger = logging.getLogger() +root_logger.setLevel(logging.DEBUG) +print() + +print("Test 7: Testing a random third-party style logger") +try: + raise RuntimeError("Third party error") +except Exception: + logging.error("This is from root logger with exception", exc_info=True) +print() + +print("=" * 80) +print("Analysis:") +print("- If all logs after Step 4 are single-line JSON: json_logs works correctly") +print("- If exceptions are multi-line plain text: BUG REPRODUCED") +print("- Check if root logger or third-party loggers are formatted correctly") +print("=" * 80) diff --git a/test_json_logs_proxy_startup.py b/test_json_logs_proxy_startup.py new file mode 100644 index 00000000000..fe9f60ed34c --- /dev/null +++ b/test_json_logs_proxy_startup.py @@ -0,0 +1,12 @@ +#!/usr/bin/env python3 +""" +Reproducer that simulates EXACT proxy startup sequence. + +This simulates what happens when: +1. Proxy starts without JSON_LOGS env var +2. Logging module is imported and initialized with default formatters +3. Config is loaded with json_logs: true +4. _turn_on_json() is called +5. Errors are logged + +This should reproduce the bug if there's an issue with the initialization order. diff --git a/test_json_logs_reproducer.py b/test_json_logs_reproducer.py new file mode 100644 index 00000000000..7ed927cb42b --- /dev/null +++ b/test_json_logs_reproducer.py @@ -0,0 +1,91 @@ +#!/usr/bin/env python3 +""" +Reproducer for json_logs issue with exceptions not being formatted as JSON. + +This script demonstrates that when json_logs is enabled, regular log messages +are formatted as JSON, but exceptions/tracebacks are still printed as plain text. +""" + +import os +import sys +import logging + +# Set JSON_LOGS environment variable before importing litellm +os.environ["JSON_LOGS"] = "true" + +# Import litellm modules +import litellm +from litellm._logging import verbose_logger, verbose_router_logger, verbose_proxy_logger + +# Explicitly turn on json logs +litellm.json_logs = True +litellm._turn_on_json() + +print("=" * 80) +print("Testing JSON Logs with litellm") +print("json_logs enabled:", litellm.json_logs) +print("=" * 80) +print() + +# Test 1: Regular INFO log (should be JSON) +print("Test 1: Regular INFO log") +verbose_logger.info("This is a regular INFO message") +print() + +# Test 2: Regular ERROR log without exception (should be JSON) +print("Test 2: Regular ERROR log without exception") +verbose_logger.error("This is a regular ERROR message without exception") +print() + +# Test 3: ERROR log with exception using logger.error() (problematic case) +print("Test 3: ERROR log with logger.error() inside exception handler") +try: + raise ValueError("This is a test exception") +except Exception as e: + verbose_logger.error(f"Caught an exception: {e}") +print() + +# Test 4: ERROR log with exception using logger.exception() (should include traceback) +print("Test 4: ERROR log with logger.exception() inside exception handler") +try: + raise ValueError("This is another test exception") +except Exception as e: + verbose_logger.exception(f"Caught an exception with .exception(): {e}") +print() + +# Test 5: Simulate the vertex_ai error that dmc reported +print("Test 5: Simulating vertex_ai credential loading error") +try: + # Simulate JSON parsing error like in vertex_llm_base.py + import json + json_obj = json.loads("") # This will fail +except Exception as e: + verbose_logger.exception( + f"Failed to load vertex credentials. Check to see if credentials containing partial/invalid information. Error: {str(e)}" + ) +print() + +# Test 6: Simulate router error that dmc reported +print("Test 6: Simulating router error") +verbose_router_logger.error( + "Could not identify azure model 'text-embedding-3-small'. Set azure 'base_model' for accurate max tokens, cost tracking, etc." +) +print() + +# Test 7: Multiple nested exceptions +print("Test 7: Multiple nested exceptions") +try: + try: + raise RuntimeError("Inner exception") + except RuntimeError as inner_e: + raise ValueError("Outer exception") from inner_e +except Exception as e: + verbose_logger.exception(f"Nested exception occurred: {e}") +print() + +print("=" * 80) +print("Tests completed. Check output above:") +print("- Regular logs should be single-line JSON") +print("- Exceptions should ALSO be single-line JSON with stacktrace field") +print("- If exceptions are multi-line plain text, the bug is reproduced") +print("=" * 80) diff --git a/test_logging_handlers.py b/test_logging_handlers.py new file mode 100644 index 00000000000..6c63c682a3d --- /dev/null +++ b/test_logging_handlers.py @@ -0,0 +1,129 @@ +#!/usr/bin/env python3 +""" +Test to understand the logging handler hierarchy and potential issues. +""" + +import logging +import sys + +# Simulate the proxy startup WITHOUT JSON_LOGS env var +print("=" * 80) +print("Step 1: Check Python's default logging configuration") +print("=" * 80) + +root = logging.getLogger() +print(f"Root logger: {root}") +print(f"Root logger level: {root.level} ({logging.getLevelName(root.level)})") +print(f"Root logger handlers: {root.handlers}") +print(f"Root logger propagate: {root.propagate}") +print() + +# Now import litellm's logging +print("=" * 80) +print("Step 2: Import litellm (without JSON_LOGS env var)") +print("=" * 80) + +import litellm +from litellm._logging import verbose_logger, verbose_router_logger, verbose_proxy_logger + +print(f"litellm.json_logs: {litellm.json_logs}") +print() + +print(f"verbose_logger: {verbose_logger}") +print(f" - name: {verbose_logger.name}") +print(f" - level: {verbose_logger.level} ({logging.getLevelName(verbose_logger.level)})") +print(f" - handlers: {verbose_logger.handlers}") +print(f" - propagate: {verbose_logger.propagate}") +print() + +print(f"Root logger after litellm import:") +print(f" - handlers: {root.handlers}") +print(f" - propagate: {root.propagate}") +print() + +# Create a child logger like health_check.py does +print("=" * 80) +print("Step 3: Create a child logger (like health_check.py)") +print("=" * 80) + +health_logger = logging.getLogger("litellm.proxy.health_check") +print(f"health_logger: {health_logger}") +print(f" - name: {health_logger.name}") +print(f" - level: {health_logger.level} ({logging.getLevelName(health_logger.level)})") +print(f" - handlers: {health_logger.handlers}") +print(f" - propagate: {health_logger.propagate}") +print() + +# Test logging BEFORE json_logs is enabled +print("=" * 80) +print("Step 4: Test logging BEFORE json_logs enabled") +print("=" * 80) + +verbose_logger.error("Test error from verbose_logger BEFORE json_logs") +health_logger.error("Test error from health_logger BEFORE json_logs") +logging.error("Test error from root logger BEFORE json_logs") +print() + +# Now enable json_logs +print("=" * 80) +print("Step 5: Enable json_logs (simulate config loading)") +print("=" * 80) + +litellm.json_logs = True +litellm._turn_on_json() + +print(f"litellm.json_logs: {litellm.json_logs}") +print() + +print(f"verbose_logger after _turn_on_json():") +print(f" - handlers: {verbose_logger.handlers}") +print(f" - propagate: {verbose_logger.propagate}") +if verbose_logger.handlers: + print(f" - handler formatter: {verbose_logger.handlers[0].formatter}") +print() + +print(f"Root logger after _turn_on_json():") +print(f" - handlers: {root.handlers}") +print(f" - propagate: {root.propagate}") +if root.handlers: + print(f" - handler formatter: {root.handlers[0].formatter}") +print() + +print(f"health_logger after _turn_on_json():") +print(f" - handlers: {health_logger.handlers}") +print(f" - propagate: {health_logger.propagate}") +print() + +# Test logging AFTER json_logs is enabled +print("=" * 80) +print("Step 6: Test logging AFTER json_logs enabled") +print("=" * 80) + +print("\nTest from verbose_logger:") +verbose_logger.error("Test error from verbose_logger AFTER json_logs") + +print("\nTest from health_logger (should propagate to root):") +health_logger.error("Test error from health_logger AFTER json_logs") + +print("\nTest from root logger:") +logging.error("Test error from root logger AFTER json_logs") + +print("\nTest exception from verbose_logger:") +try: + raise ValueError("Test exception") +except Exception as e: + verbose_logger.exception(f"Caught exception: {e}") + +print("\nTest exception from health_logger:") +try: + raise ValueError("Test exception from health logger") +except Exception as e: + health_logger.exception(f"Caught exception: {e}") + +print() +print("=" * 80) +print("Analysis:") +print("- Check if health_logger messages are formatted as JSON") +print("- Check if exceptions have stacktrace in JSON") +print("- If health_logger is NOT JSON, then propagation is broken") +print("=" * 80) diff --git a/test_proxy_json_logs_reproducer.py b/test_proxy_json_logs_reproducer.py new file mode 100644 index 00000000000..3e917a66988 --- /dev/null +++ b/test_proxy_json_logs_reproducer.py @@ -0,0 +1,144 @@ +#!/usr/bin/env python3 +""" +Comprehensive reproducer for json_logs issue in proxy server context. + +This simulates the EXACT proxy server startup sequence including: +1. Import litellm modules (without JSON_LOGS env var) +2. Load config with json_logs: true +3. Call _turn_on_json() +4. Trigger various types of errors that dmc reported +""" + +import os +import sys + +# Ensure JSON_LOGS is NOT set +if "JSON_LOGS" in os.environ: + del os.environ["JSON_LOGS"] + +print("=" * 80) +print("REPRODUCER FOR NON-JSON LOGS IN LITELLM PROXY") +print("=" * 80) +print() + +# Step 1: Import litellm (simulates module loading at proxy startup) +print("Step 1: Importing litellm modules (json_logs not yet enabled)...") +print() + +import litellm +from litellm._logging import verbose_logger, verbose_router_logger, verbose_proxy_logger + +print(f"Initial json_logs status: {litellm.json_logs}") +print(f"verbose_logger handlers: {verbose_logger.handlers}") +if verbose_logger.handlers: + print(f"verbose_logger formatter type: {type(verbose_logger.handlers[0].formatter)}") +print() + +# Step 2: Simulate some early initialization logging +print("Step 2: Simulating early logging (before config is loaded)...") +verbose_logger.info("Early INFO message during proxy initialization") +verbose_logger.error("Early ERROR message during proxy initialization") +print() + +# Step 3: Simulate config loading and enabling json_logs +print("Step 3: Loading config and enabling json_logs...") +print() + +# This simulates what proxy_cli.py does at line 680-682 +litellm.json_logs = True +litellm._turn_on_json() + +print(f"After _turn_on_json():") +print(f" json_logs status: {litellm.json_logs}") +print(f" verbose_logger handlers: {verbose_logger.handlers}") +if verbose_logger.handlers: + print(f" verbose_logger formatter type: {type(verbose_logger.handlers[0].formatter)}") + print(f" verbose_logger propagate: {verbose_logger.propagate}") +print() + +# Print the message that appears in dmc's logs +print("Using json logs. Setting log_config to None.") +print() + +# Step 4: Simulate various errors that dmc reported +print("Step 4: Simulating errors that dmc reported...") +print() + +# Test 1: Vertex AI credential error (like dmc's log) +print("Test 1: Vertex AI credential error") +try: + import json as json_module + json_module.loads("") # Triggers JSONDecodeError +except Exception as e: + verbose_logger.exception( + f"Failed to load vertex credentials. Check to see if credentials containing partial/invalid information. Error: {str(e)}" + ) +print() + +# Test 2: Router error (like dmc's log) +print("Test 2: Router error about Azure model") +verbose_router_logger.error( + "Could not identify azure model 'text-embedding-3-small'. Set azure 'base_model' for accurate max tokens, cost tracking, etc.- https://docs.litellm.ai/docs/proxy/cost_tracking#spend-tracking-for-azure-openai-models" +) +print() + +# Test 3: Database error (like dmc's log) +print("Test 3: Simulating database error") +try: + raise Exception("Can't reach database server at `pglitellmstag-rw.hudson-trading.com`:`5432`\n\nPlease make sure your database server is running at `pglitellmstag-rw.hudson-trading.com`:`5432`.") +except Exception as e: + verbose_proxy_logger.exception( + "Failed to reset budget for endusers: " + str(e) + ) +print() + +# Test 4: Nested exceptions +print("Test 4: Nested exceptions") +try: + try: + json_module.loads("") + except Exception as inner: + raise Exception("Unable to load vertex credentials from environment. Got=") from inner +except Exception as e: + verbose_logger.exception( + f"Failed to load vertex credentials. Check to see if credentials containing partial/invalid information. Error: {str(e)}" + ) +print() + +# Test 5: Logging from a module-level logger (like health_check.py) +print("Test 5: Logging from a module logger (like health_check.py)") +import logging +module_logger = logging.getLogger("litellm.proxy.health_check") +try: + raise ValueError("Health check failed for model") +except Exception as e: + module_logger.exception(f"Health check error: {e}") +print() + +# Test 6: Direct logging.error with exc_info +print("Test 6: Using logging.error with exc_info=True") +try: + raise RuntimeError("Test error") +except Exception: + logging.error("This is from root logger with exception", exc_info=True) +print() + +# Test 7: Check if there are multiple handlers +print("Step 5: Checking for multiple handlers (could cause duplicates)...") +print(f"Root logger handlers: {logging.getLogger().handlers}") +print(f"verbose_logger handlers: {verbose_logger.handlers}") +print(f"verbose_router_logger handlers: {verbose_router_logger.handlers}") +print(f"verbose_proxy_logger handlers: {verbose_proxy_logger.handlers}") +print() + +print("=" * 80) +print("EXPECTED BEHAVIOR:") +print("- All logs after 'Using json logs' should be single-line JSON") +print("- Exceptions should have stacktrace in JSON format") +print() +print("IF YOU SEE PLAIN TEXT LOGS LIKE:") +print(" '15:46:06 - LiteLLM:ERROR: file.py:123 - Error message'") +print(" 'Traceback (most recent call last):'") +print(" ' ...'") +print("THEN THE BUG IS REPRODUCED!") +print("=" * 80)