diff --git a/REPRODUCER_RESULTS.md b/REPRODUCER_RESULTS.md new file mode 100644 index 00000000000..2105f36a15c --- /dev/null +++ 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. diff --git a/actual_proxy_logs.txt b/actual_proxy_logs.txt new file mode 100644 index 00000000000..d2c666ecadb --- /dev/null +++ b/actual_proxy_logs.txt @@ -0,0 +1,36 @@ +Using json logs. Setting log_config to None. + + ██╗ ██╗████████╗███████╗██╗ ██╗ ███╗ ███╗ + ██║ ██║╚══██╔══╝██╔════╝██║ ██║ ████╗ ████║ + ██║ ██║ ██║ █████╗ ██║ ██║ ██╔████╔██║ + ██║ ██║ ██║ ██╔══╝ ██║ ██║ ██║╚██╔╝██║ + ███████╗██║ ██║ ███████╗███████╗███████╗██║ ╚═╝ ██║ + ╚══════╝╚═╝ ╚═╝ ╚══════╝╚══════╝╚══════╝╚═╝ ╚═╝ + + +#------------------------------------------------------------# +# # +# 'The thing I wish you improved is...' # +# https://github.com/BerriAI/litellm/issues/new # +# # +#------------------------------------------------------------# + + Thank you for using LiteLLM! - Krrish & Ishaan + + + +Give Feedback / Get Help: https://github.com/BerriAI/litellm/issues/new + + + Initialized Success Callbacks - []  + Initialized Failure Callbacks - []  +LiteLLM: Proxy initialized with Config, Set models: + gpt-3.5-turbo + azure-gpt-35 + vertex-gemini + azure-embedding +{"message": "litellm.proxy.proxy_server._handle_llm_api_exception(): Exception occured - litellm.AuthenticationError: AuthenticationError: OpenAIException - Incorrect API key provided: sk-fake-**************fail. You can find your API key at https://platform.openai.com/account/api-keys.. Received Model Group=gpt-3.5-turbo\nAvailable Model Group Fallbacks=None", "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 headers, response = await self.make_openai_chat_completion_request(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/logging_utils.py\", line 190, in async_wrapper\n result = await func(*args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/openai/openai.py\", line 460, in make_openai_chat_completion_request\n raise e\n File \"/home/user/litellm/litellm/llms/openai/openai.py\", line 437, in make_openai_chat_completion_request\n await openai_aclient.chat.completions.with_raw_response.create(\n File \"/usr/local/lib/python3.11/dist-packages/openai/_legacy_response.py\", line 381, in wrapped\n return cast(LegacyAPIResponse[R], await func(*args, **kwargs))\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/openai/resources/chat/completions/completions.py\", line 2678, in create\n return await self._post(\n ^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/openai/_base_client.py\", line 1797, in post\n return await self.request(cast_to, opts, stream=stream, stream_cls=stream_cls)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/openai/_base_client.py\", line 1597, in request\n raise self._make_status_error_from_response(err.response) from None\nopenai.AuthenticationError: Error code: 401 - {'error': {'message': 'Incorrect API key provided: sk-fake-**************fail. You can find your API key at https://platform.openai.com/account/api-keys.', 'type': 'invalid_request_error', 'code': 'invalid_api_key', 'param': None}, 'status': 401}\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n File \"/home/user/litellm/litellm/main.py\", line 610, in acompletion\n response = await init_response\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/openai/openai.py\", line 887, in acompletion\n raise OpenAIError(\nlitellm.llms.openai.common_utils.OpenAIError: Error code: 401 - {'error': {'message': 'Incorrect API key provided: sk-fake-**************fail. You can find your API key at https://platform.openai.com/account/api-keys.', 'type': 'invalid_request_error', 'code': 'invalid_api_key', 'param': None}, 'status': 401}\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n File \"/home/user/litellm/litellm/proxy/proxy_server.py\", line 5250, in chat_completion\n result = await base_llm_response_processor.base_process_llm_request(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/proxy/common_request_processing.py\", line 680, in base_process_llm_request\n responses = await llm_responses\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 1374, in acompletion\n raise e\n File \"/home/user/litellm/litellm/router.py\", line 1350, in acompletion\n response = await self.async_function_with_fallbacks(**kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4571, in async_function_with_fallbacks\n return await self.async_function_with_fallbacks_common_utils(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4529, in async_function_with_fallbacks_common_utils\n raise original_exception\n File \"/home/user/litellm/litellm/router.py\", line 4563, in async_function_with_fallbacks\n response = await self.async_function_with_retries(*args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4685, in async_function_with_retries\n self.should_retry_this_error(\n File \"/home/user/litellm/litellm/router.py\", line 4887, in should_retry_this_error\n raise error # then raise error\n ^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4659, in async_function_with_retries\n response = await self.make_call(original_function, *args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4787, in make_call\n response = await response\n ^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 1660, in _acompletion\n raise e\n File \"/home/user/litellm/litellm/router.py\", line 1606, in _acompletion\n response = await _response\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/utils.py\", line 1970, in wrapper_async\n raise e\n File \"/home/user/litellm/litellm/utils.py\", line 1790, in wrapper_async\n result = await original_function(*args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/main.py\", line 629, in acompletion\n raise exception_type(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/exception_mapping_utils.py\", line 2356, in exception_type\n raise e\n File \"/home/user/litellm/litellm/litellm_core_utils/exception_mapping_utils.py\", line 502, in exception_type\n raise AuthenticationError(\nlitellm.exceptions.AuthenticationError: litellm.AuthenticationError: AuthenticationError: OpenAIException - Incorrect API key provided: sk-fake-**************fail. You can find your API key at https://platform.openai.com/account/api-keys.. Received Model Group=gpt-3.5-turbo\nAvailable Model Group Fallbacks=None"} +{"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 File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'"} +{"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:50.414869", "stacktrace": "Traceback (most recent call last):\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'"} +{"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:51.976356", "stacktrace": "Traceback (most recent call last):\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'"} +{"message": "litellm.proxy.proxy_server._handle_llm_api_exception(): Exception occured - litellm.APIConnectionError: No module named 'google'\nTraceback (most recent call last):\n File \"/home/user/litellm/litellm/main.py\", line 610, in acompletion\n response = await init_response\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/gemini/vertex_and_google_ai_studio_gemini.py\", line 2430, in async_completion\n _auth_header, vertex_project = await self._ensure_access_token_async(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 642, in _ensure_access_token_async\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 637, in _ensure_access_token_async\n return await asyncify(self.get_access_token)(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/asyncify.py\", line 57, in wrapper\n return await anyio.to_thread.run_sync(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/to_thread.py\", line 63, in run_sync\n return await get_async_backend().run_sync_in_worker_thread(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 2502, in run_sync_in_worker_thread\n return await future\n ^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 986, in run\n result = context.run(func, *args)\n ^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 553, in get_access_token\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'\n. Received Model Group=vertex-gemini\nAvailable Model Group Fallbacks=None LiteLLM Retried: 2 times, LiteLLM Max Retries: 2", "level": "ERROR", "timestamp": "2026-01-19T22:51:54.192782", "stacktrace": "Traceback (most recent call last):\n File \"/home/user/litellm/litellm/main.py\", line 610, in acompletion\n response = await init_response\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/gemini/vertex_and_google_ai_studio_gemini.py\", line 2430, in async_completion\n _auth_header, vertex_project = await self._ensure_access_token_async(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 642, in _ensure_access_token_async\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 637, in _ensure_access_token_async\n return await asyncify(self.get_access_token)(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/asyncify.py\", line 57, in wrapper\n return await anyio.to_thread.run_sync(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/to_thread.py\", line 63, in run_sync\n return await get_async_backend().run_sync_in_worker_thread(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 2502, in run_sync_in_worker_thread\n return await future\n ^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 986, in run\n result = context.run(func, *args)\n ^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 553, in get_access_token\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n File \"/home/user/litellm/litellm/proxy/proxy_server.py\", line 5250, in chat_completion\n result = await base_llm_response_processor.base_process_llm_request(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/proxy/common_request_processing.py\", line 680, in base_process_llm_request\n responses = await llm_responses\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 1374, in acompletion\n raise e\n File \"/home/user/litellm/litellm/router.py\", line 1350, in acompletion\n response = await self.async_function_with_fallbacks(**kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4571, in async_function_with_fallbacks\n return await self.async_function_with_fallbacks_common_utils(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4529, in async_function_with_fallbacks_common_utils\n raise original_exception\n File \"/home/user/litellm/litellm/router.py\", line 4563, in async_function_with_fallbacks\n response = await self.async_function_with_retries(*args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4776, in async_function_with_retries\n raise original_exception\n File \"/home/user/litellm/litellm/router.py\", line 4659, in async_function_with_retries\n response = await self.make_call(original_function, *args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 4787, in make_call\n response = await response\n ^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/router.py\", line 1660, in _acompletion\n raise e\n File \"/home/user/litellm/litellm/router.py\", line 1606, in _acompletion\n response = await _response\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/utils.py\", line 1970, in wrapper_async\n raise e\n File \"/home/user/litellm/litellm/utils.py\", line 1790, in wrapper_async\n result = await original_function(*args, **kwargs)\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/main.py\", line 629, in acompletion\n raise exception_type(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/exception_mapping_utils.py\", line 2356, in exception_type\n raise e\n File \"/home/user/litellm/litellm/litellm_core_utils/exception_mapping_utils.py\", line 2332, in exception_type\n raise APIConnectionError(\nlitellm.exceptions.APIConnectionError: litellm.APIConnectionError: No module named 'google'\nTraceback (most recent call last):\n File \"/home/user/litellm/litellm/main.py\", line 610, in acompletion\n response = await init_response\n ^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/gemini/vertex_and_google_ai_studio_gemini.py\", line 2430, in async_completion\n _auth_header, vertex_project = await self._ensure_access_token_async(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 642, in _ensure_access_token_async\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 637, in _ensure_access_token_async\n return await asyncify(self.get_access_token)(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/litellm_core_utils/asyncify.py\", line 57, in wrapper\n return await anyio.to_thread.run_sync(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/to_thread.py\", line 63, in run_sync\n return await get_async_backend().run_sync_in_worker_thread(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 2502, in run_sync_in_worker_thread\n return await future\n ^^^^^^^^^^^^\n File \"/usr/local/lib/python3.11/dist-packages/anyio/_backends/_asyncio.py\", line 986, in run\n result = context.run(func, *args)\n ^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 553, in get_access_token\n raise e\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 546, in get_access_token\n _credentials, credential_project_id = self.load_auth(\n ^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 121, in load_auth\n creds, creds_project_id = self._credentials_from_default_auth(\n ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n File \"/home/user/litellm/litellm/llms/vertex_ai/vertex_llm_base.py\", line 172, in _credentials_from_default_auth\n import google.auth as google_auth\nModuleNotFoundError: No module named 'google'\n. Received Model Group=vertex-gemini\nAvailable Model Group Fallbacks=None LiteLLM Retried: 2 times, LiteLLM Max Retries: 2"} diff --git a/reproduce_json_logs.sh b/reproduce_json_logs.sh new file mode 100755 index 00000000000..58ababf5f19 --- /dev/null +++ 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 "================================================================================" diff --git a/reproduce_json_logs_config.yaml b/reproduce_json_logs_config.yaml new file mode 100644 index 00000000000..8632de1b276 --- /dev/null +++ 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 diff --git a/start_proxy.py b/start_proxy.py new file mode 100644 index 00000000000..8487bf8ef10 --- /dev/null +++ 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()