Add real proxy server reproducer for json_logs issue

Successfully reproduced the issue with actual running proxy server! Key findings: - ERROR logs with exceptions ARE properly formatted as JSON ✅ - Startup INFO logs are NOT formatted as JSON ❌ - ANSI color codes appear in logs ([94m, [32m, etc.) ❌ - Mix of JSON and plain text logs confirmed Issue reproduced: 1. Started litellm proxy with json_logs: true 2. Made requests to trigger various errors 3. Captured actual logs showing the problem Problem logs (plain text with ANSI codes): - "Using json logs. Setting log_config to None." - "[94m Initialized Success Callbacks - [] [0m" - "[32mLiteLLM: Proxy initialized with Config, Set models:[0m" Working logs (proper JSON): - {"message": "litellm.proxy.proxy_server._handle_llm_api_exception()...", "level": "ERROR", ...} - {"message": "Failed to load vertex credentials...", "level": "ERROR", "stacktrace": "..."} Root cause: - Some code uses print() statements instead of loggers - Colored formatters bypass JsonFormatter - ANSI escape codes in formatter not removed when json_logs enabled Files added: - reproduce_json_logs_config.yaml: Proxy config with json_logs enabled - start_proxy.py: Script to start proxy programmatically - reproduce_json_logs.sh: Automated test that runs proxy and analyzes logs - actual_proxy_logs.txt: Real captured logs showing the issue - REPRODUCER_RESULTS.md: Comprehensive analysis and findings This exactly reproduces dmc's reported issue from the Slack thread.
2026-10-11 03:38:38 +00:00 · 2026-01-19 22:53:15 +00:00 · 2026-01-19 22:53:15 +00:00 · ee419b09ea
commit ee419b09ea
parent 8955e579c7
5 changed files with 407 additions and 0 deletions
--- a/REPRODUCER_RESULTS.md
+++ b/REPRODUCER_RESULTS.md
@ -0,0 +1,138 @@
+# JSON Logs Reproducer - Results and Analysis
+
+## Summary
+
+**Status**: ✅ **Issue Reproduced Successfully with Real Proxy Server**
+
+When `json_logs: true` is enabled in litellm proxy configuration, there is a **MIX of JSON and non-JSON formatted logs**.
+
+## Reproduction Steps
+
+1. **Start litellm proxy with json_logs enabled:**
+   ```bash
+   # Using the provided config file
+   python3 start_proxy.py
+   ```
+
+2. **Make requests to trigger errors:**
+   ```bash
+   curl -X POST http://localhost:4000/chat/completions \
+     -H "Content-Type: application/json" \
+     -H "Authorization: Bearer sk-1234567890" \
+     -d '{"model": "gpt-3.5-turbo", "messages": [{"role": "user", "content": "test"}]}'
+   ```
+
+3. **Check logs** in `actual_proxy_logs.txt`
+
+## Findings
+
+### ✅ What WORKS (JSON Formatted)
+
+**ERROR logs with exceptions ARE properly formatted as JSON:**
+
+```json
+{"message": "litellm.proxy.proxy_server._handle_llm_api_exception(): Exception occured - litellm.AuthenticationError: ...", "level": "ERROR", "timestamp": "2026-01-19T22:51:46.250125", "stacktrace": "Traceback (most recent call last):\n  File \"/home/user/litellm/litellm/llms/openai/openai.py\", line 840, in acompletion\n..."}
+```
+
+```json
+{"message": "Failed to load vertex credentials. Check to see if credentials containing partial/invalid information. Error: No module named 'google'", "level": "ERROR", "timestamp": "2026-01-19T22:51:49.318104", "stacktrace": "Traceback (most recent call last):\n..."}
+```
+
+### ❌ What DOESN'T WORK (Plain Text)
+
+**Some startup INFO logs are NOT formatted as JSON:**
+
+1. **Plain text message:**
+   ```
+   Using json logs. Setting log_config to None.
+   ```
+
+2. **ANSI colored plain text logs:**
+   ```
+   [94m Initialized Success Callbacks - [] [0m
+   [94m Initialized Failure Callbacks - [] [0m
+   [32mLiteLLM: Proxy initialized with Config, Set models:[0m
+   [32m    gpt-3.5-turbo[0m
+   [32m    azure-gpt-35[0m
+   [32m    vertex-gemini[0m
+   [32m    azure-embedding[0m
+   ```
+
+3. **ASCII art banner** (plain text, not JSON)
+
+## Root Cause
+
+The issue occurs because:
+
+1. ✅ `_turn_on_json()` IS being called correctly (we see "Using json logs" message)
+2. ✅ The JsonFormatter IS working for ERROR logs with exceptions
+3. ❌ Some code paths use `print()` statements or colored formatters instead of the JSON logger
+4. ❌ ANSI color codes (`[94m`, `[32m`, etc.) indicate use of the colored formatter, not JsonFormatter
+
+### Specific Problem Locations
+
+Looking at the colored logs, these are likely coming from:
+- `litellm/proxy/proxy_server.py` - proxy initialization messages
+- `litellm/proxy/proxy_cli.py` - "Using json logs" print statement (line 140)
+- Various INFO level logs that use colored formatters
+
+The colored formatter code in `litellm/_logging.py:95-100`:
+```python
+formatter = logging.Formatter(
+    "\033[92m%(asctime)s - %(name)s:%(levelname)s\033[0m: %(filename)s:%(lineno)s - %(message)s",
+    datefmt="%H:%M:%S",
+)
+```
+
+These ANSI escape codes (`\033[92m`, `\033[0m`) are what we see as `[92m` and `[0m` in the logs.
+
+## Test Files Created
+
+1. **reproduce_json_logs_config.yaml** - Proxy config with json_logs enabled and models that trigger errors
+2. **start_proxy.py** - Script to start the proxy programmatically
+3. **reproduce_json_logs.sh** - Automated test script that starts proxy, makes requests, analyzes logs
+4. **actual_proxy_logs.txt** - Captured logs showing the mix of JSON and non-JSON
+
+## Comparison: Expected vs Actual
+
+### Expected (ALL JSON):
+```json
+{"message": "Using json logs. Setting log_config to None.", "level": "INFO", "timestamp": "..."}
+{"message": " Initialized Success Callbacks - []", "level": "INFO", "timestamp": "..."}
+{"message": "LiteLLM: Proxy initialized with Config, Set models: gpt-3.5-turbo, azure-gpt-35, vertex-gemini, azure-embedding", "level": "INFO", "timestamp": "..."}
+{"message": "litellm.proxy.proxy_server._handle_llm_api_exception():...", "level": "ERROR", "timestamp": "...", "stacktrace": "..."}
+```
+
+### Actual (MIXED):
+```
+Using json logs. Setting log_config to None.
+[94m Initialized Success Callbacks - [] [0m
+[32mLiteLLM: Proxy initialized with Config, Set models:[0m
+{"message": "litellm.proxy.proxy_server._handle_llm_api_exception():...", "level": "ERROR", "timestamp": "...", "stacktrace": "..."}
+```
+
+## Severity Assessment
+
+**Impact**: Medium to High for production deployments
+
+- ✅ Critical ERROR logs with exceptions ARE properly formatted
+- ❌ INFO/DEBUG logs from startup and initialization are NOT formatted
+- ❌ Logs cannot be reliably parsed by JSON log aggregators (Elasticsearch, Splunk, etc.)
+- ❌ ANSI color codes appear in logs, breaking JSON parsers
+
+## Recommendations
+
+1. **Remove `print()` statements** in proxy_cli.py and replace with logger calls
+2. **Ensure all logging goes through the configured loggers**, not direct print statements
+3. **Check for hardcoded colored formatters** that bypass json_logs setting
+4. **Add integration test** to verify ALL logs are JSON when json_logs=true
+
+## Files for Review
+
+All reproducer files have been created and are ready for commit:
+- `reproduce_json_logs_config.yaml`
+- `start_proxy.py`
+- `reproduce_json_logs.sh`
+- `actual_proxy_logs.txt` (example output)
+
+This reproduces the exact issue that dmc reported in the Slack thread.
--- a/actual_proxy_logs.txt
+++ b/actual_proxy_logs.txt
--- a/reproduce_json_logs.sh
+++ b/reproduce_json_logs.sh
@ -0,0 +1,172 @@
+#!/bin/bash
+
+# Script to reproduce json_logs issue with actual litellm proxy server
+# This will start the proxy, trigger errors, and show log output
+
+set -e
+
+echo "================================================================================"
+echo "LITELLM JSON LOGS REPRODUCER - Real Proxy Server Test"
+echo "================================================================================"
+echo ""
+
+# Cleanup function
+cleanup() {
+    echo ""
+    echo "Cleaning up..."
+    if [ ! -z "$PROXY_PID" ]; then
+        echo "Stopping litellm proxy (PID: $PROXY_PID)..."
+        kill $PROXY_PID 2>/dev/null || true
+        wait $PROXY_PID 2>/dev/null || true
+    fi
+    rm -f proxy_output.log
+}
+
+trap cleanup EXIT INT TERM
+
+# Start the proxy in the background and capture output
+echo "Step 1: Starting litellm proxy with json_logs: true"
+echo "Config file: reproduce_json_logs_config.yaml"
+echo ""
+
+# Start proxy and capture all output (stdout and stderr)
+python3 start_proxy.py > proxy_output.log 2>&1 &
+PROXY_PID=$!
+
+echo "Proxy started with PID: $PROXY_PID"
+echo "Waiting for proxy to start up..."
+sleep 8
+
+# Check if proxy is still running
+if ! kill -0 $PROXY_PID 2>/dev/null; then
+    echo "ERROR: Proxy failed to start!"
+    echo "=== Proxy output ==="
+    cat proxy_output.log
+    exit 1
+fi
+
+echo "Proxy should be running. Checking logs..."
+echo ""
+
+# Show startup logs
+echo "================================================================================"
+echo "STARTUP LOGS (first 50 lines):"
+echo "================================================================================"
+head -50 proxy_output.log
+echo ""
+echo "... (truncated) ..."
+echo ""
+
+# Check if "Using json logs" message appears
+if grep -q "Using json logs" proxy_output.log; then
+    echo "✓ Found 'Using json logs' message in startup"
+else
+    echo "✗ Did NOT find 'Using json logs' message"
+fi
+echo ""
+
+# Wait a bit more for full startup
+sleep 2
+
+echo "================================================================================"
+echo "Step 2: Triggering errors by making requests"
+echo "================================================================================"
+echo ""
+
+# Test 1: Make request to OpenAI model with fake key
+echo "Test 1: Request to gpt-3.5-turbo (will fail with auth error)..."
+curl -s -X POST http://localhost:4000/chat/completions \
+  -H "Content-Type: application/json" \
+  -H "Authorization: Bearer sk-1234567890" \
+  -d '{
+    "model": "gpt-3.5-turbo",
+    "messages": [{"role": "user", "content": "Hello"}]
+  }' > /dev/null 2>&1 || true
+
+sleep 2
+
+# Test 2: Make request to Azure model
+echo "Test 2: Request to azure-gpt-35 (will fail)..."
+curl -s -X POST http://localhost:4000/chat/completions \
+  -H "Content-Type: application/json" \
+  -H "Authorization: Bearer sk-1234567890" \
+  -d '{
+    "model": "azure-gpt-35",
+    "messages": [{"role": "user", "content": "Hello"}]
+  }' > /dev/null 2>&1 || true
+
+sleep 2
+
+# Test 3: Make request to Vertex AI model (will trigger credential error)
+echo "Test 3: Request to vertex-gemini (will fail with credential error)..."
+curl -s -X POST http://localhost:4000/chat/completions \
+  -H "Content-Type: application/json" \
+  -H "Authorization: Bearer sk-1234567890" \
+  -d '{
+    "model": "vertex-gemini",
+    "messages": [{"role": "user", "content": "Hello"}]
+  }' > /dev/null 2>&1 || true
+
+sleep 2
+
+# Test 4: Check model info endpoint (triggers router model identification)
+echo "Test 4: Request to /model/info (may trigger router errors)..."
+curl -s -X GET "http://localhost:4000/model/info" \
+  -H "Authorization: Bearer sk-1234567890" > /dev/null 2>&1 || true
+
+sleep 2
+
+# Test 5: Trigger health check if possible
+echo "Test 5: Request to /health/liveliness..."
+curl -s -X GET "http://localhost:4000/health/liveliness" > /dev/null 2>&1 || true
+
+sleep 3
+
+echo ""
+echo "All test requests completed."
+echo ""
+
+# Analyze the logs
+echo "================================================================================"
+echo "Step 3: Analyzing logs for JSON vs plain text format"
+echo "================================================================================"
+echo ""
+
+# Show all error logs
+echo "=== ALL ERROR LOGS FROM PROXY ==="
+echo ""
+grep -i "error\|exception\|traceback\|failed" proxy_output.log | head -100 || echo "(No error logs found)"
+echo ""
+
+# Count JSON vs non-JSON log lines
+JSON_COUNT=$(grep -E '^\{"message":.*"level":.*"timestamp":' proxy_output.log | wc -l)
+PLAIN_TEXT_ERROR_COUNT=$(grep -E '^[0-9]{2}:[0-9]{2}:[0-9]{2}.*ERROR' proxy_output.log | wc -l)
+TRACEBACK_COUNT=$(grep "^Traceback (most recent call last)" proxy_output.log | wc -l)
+
+echo "================================================================================"
+echo "LOG FORMAT ANALYSIS:"
+echo "================================================================================"
+echo "JSON formatted logs: $JSON_COUNT"
+echo "Plain text ERROR logs: $PLAIN_TEXT_ERROR_COUNT"
+echo "Plain text Tracebacks: $TRACEBACK_COUNT"
+echo ""
+
+if [ $PLAIN_TEXT_ERROR_COUNT -gt 0 ] || [ $TRACEBACK_COUNT -gt 0 ]; then
+    echo "❌ BUG REPRODUCED! Found plain text logs when json_logs is enabled."
+    echo ""
+    echo "=== Examples of plain text ERROR logs ==="
+    grep -E '^[0-9]{2}:[0-9]{2}:[0-9]{2}.*ERROR' proxy_output.log | head -5
+    echo ""
+    if [ $TRACEBACK_COUNT -gt 0 ]; then
+        echo "=== Examples of plain text Tracebacks ==="
+        grep -A 5 "^Traceback (most recent call last)" proxy_output.log | head -20
+    fi
+else
+    echo "✓ All logs appear to be in JSON format."
+fi
+
+echo ""
+echo "================================================================================"
+echo "Full log file saved to: proxy_output.log"
+echo "You can inspect it with: less proxy_output.log"
+echo "================================================================================"
--- a/reproduce_json_logs_config.yaml
+++ b/reproduce_json_logs_config.yaml
@ -0,0 +1,39 @@
+model_list:
+  # OpenAI model with fake key to trigger auth errors
+  - model_name: gpt-3.5-turbo
+    litellm_params:
+      model: gpt-3.5-turbo
+      api_key: sk-fake-key-this-will-fail
+
+  # Azure model without proper config to trigger errors
+  - model_name: azure-gpt-35
+    litellm_params:
+      model: azure/gpt-35-turbo
+      api_base: https://fake-endpoint.openai.azure.com
+      api_key: fake-azure-key
+      api_version: "2023-05-15"
+
+  # Vertex AI model without credentials to trigger vertex error
+  - model_name: vertex-gemini
+    litellm_params:
+      model: vertex_ai/gemini-pro
+      vertex_project: fake-project-12345
+      vertex_location: us-central1
+
+  # Model with invalid base_model to trigger router error
+  - model_name: azure-embedding
+    litellm_params:
+      model: azure/text-embedding-3-small
+      api_base: https://fake-endpoint.openai.azure.com
+      api_key: fake-key
+      api_version: "2023-05-15"
+
+litellm_settings:
+  json_logs: true
+  drop_params: true
+  success_callback: []
+  failure_callback: []
+
+general_settings:
+  master_key: sk-1234567890
+  database_url: null
--- a/start_proxy.py
+++ b/start_proxy.py
@ -0,0 +1,22 @@
+#!/usr/bin/env python3
+"""Start litellm proxy with config file."""
+import sys
+import os
+
+# Add current directory to path
+sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
+
+if __name__ == "__main__":
+    from litellm.proxy.proxy_cli import run_server
+
+    # Run the server
+    # Disable loop type to use default asyncio (avoid uvloop dependency)
+    os.environ["LITELLM_PROXY_LOOP_TYPE"] = "none"
+
+    sys.argv = [
+        "litellm",
+        "--config", "reproduce_json_logs_config.yaml",
+        "--port", "4000"
+    ]
+
+    run_server()