scriptoriumadmin/litellm
1
0
Fork 0
mirror of https://github.com/BerriAI/litellm.git synced 2026-10-11 03:38:38 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 83

Add comprehensive reproducers for json_logs issue

Browse source 
Investigation findings:
- JSON logging WORKS correctly in single-process mode
- All test scripts show proper JSON formatting with stacktraces
- Issue likely caused by multi-worker setup where _turn_on_json()
  is only called in main process, not worker processes

Test scripts added:
- test_json_logs_reproducer.py: Basic JSON logging with env var
- test_json_logs_late_enable.py: Tests late JSON logs enablement
- test_logging_handlers.py: Analyzes logger handler hierarchy
- test_proxy_json_logs_reproducer.py: Simulates exact proxy startup
- test_json_logs_config.yaml: Minimal proxy config for testing

Documentation:
- JSON_LOGS_REPRODUCTION.md: Comprehensive investigation findings,
  reproduction steps, and recommended solutions

Root cause: When using multiple workers (gunicorn/uvicorn), each
worker process has its own logging configuration. The _turn_on_json()
call in main process doesn't propagate to workers.

Recommended fix: Ensure _turn_on_json() is called in each worker
process during initialization, or set JSON_LOGS env var before import.
This commit is contained in:
Claude 2026-01-19 22:35:17 +00:00
parent 13bcecb13e
commit 8955e579c7
No known key found for this signature in database
7 changed files with 616 additions and 0 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

123
JSON_LOGS_REPRODUCTION.md Normal file
View file

@ -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

23
test_json_logs_config.yaml Normal file
View file

@ -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

94
test_json_logs_late_enable.py Normal file
View file

@ -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)

12
test_json_logs_proxy_startup.py Normal file
View file

@ -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.

91
test_json_logs_reproducer.py Normal file
View file

@ -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)

129
test_logging_handlers.py Normal file
View file

@ -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)

144
test_proxy_json_logs_reproducer.py Normal file
View file

@ -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)