Custom log format for uvicorn#1767
Open
devmount wants to merge 1 commit into
Open
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What changed?
This PR introduces a
uvicorn_log_config.jsonfile to customize the log format the uvicorn server uses and updates the docker file and entry.sh accordingly. It's almost exactly what they suggest in the docs (I only removed the dashes):https://uvicorn.dev/concepts/logging/#yaml-example
Why?
Uvicorn uses its own loggers, independent from our application level logging we set up in main.py.
How to test
docker compose up -d --build backendLimitations and Notes
Two things I did that are related but not necessary for this issue:
tracetoinfo. We can discuss this, but I found absolutely no value in all those spammy trace messages. On the contrary, I searched for relevant logging entries between them on a regular basis. But if we need those for any reason, please let me know - we can totally keep it like it was. Check the logs I put in detail tags below to see the huge difference.Applicable Issues
Closes #455
Screenshots
Before, on startup:
Before: on page load of the dashboard
2026-07-23 23:03:37.246 | TRACE: 172.20.0.1:62066 - HTTP connection made 2026-07-23 23:03:37.246 | TRACE: 172.20.0.1:62066 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62066), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/session-info', 'raw_path': b'/session-info', 'query_string': b''} 2026-07-23 23:03:37.250 | TRACE: 172.20.0.1:62066 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.250 | INFO: 172.20.0.1:62066 - "OPTIONS /session-info HTTP/1.1" 200 OK 2026-07-23 23:03:37.250 | TRACE: 172.20.0.1:62066 - ASGI [2] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.250 | TRACE: 172.20.0.1:62066 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.251 | TRACE: 172.20.0.1:62066 - ASGI [2] Completed 2026-07-23 23:03:37.256 | TRACE: 172.20.0.1:62076 - HTTP connection made 2026-07-23 23:03:37.258 | TRACE: 172.20.0.1:62076 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62076), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/session-info', 'raw_path': b'/session-info', 'query_string': b''} 2026-07-23 23:03:37.261 | TRACE: 172.20.0.1:62076 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.261 | INFO: 172.20.0.1:62076 - "GET /session-info HTTP/1.1" 200 OK 2026-07-23 23:03:37.261 | TRACE: 172.20.0.1:62076 - ASGI [3] Send {'type': 'http.response.body', 'body': '<4 bytes>', 'more_body': True} 2026-07-23 23:03:37.261 | TRACE: 172.20.0.1:62076 - ASGI [3] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.261 | TRACE: 172.20.0.1:62076 - ASGI [3] Completed 2026-07-23 23:03:37.294 | TRACE: 172.20.0.1:62066 - ASGI [4] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62066), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/me/appointments_count_by_status', 'raw_path': b'/me/appointments_count_by_status', 'query_string': b'status=requested'} 2026-07-23 23:03:37.295 | TRACE: 172.20.0.1:62082 - HTTP connection made 2026-07-23 23:03:37.295 | TRACE: 172.20.0.1:62084 - HTTP connection made 2026-07-23 23:03:37.295 | TRACE: 172.20.0.1:62082 - ASGI [5] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62082), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/me', 'raw_path': b'/me', 'query_string': b''} 2026-07-23 23:03:37.295 | TRACE: 172.20.0.1:62104 - HTTP connection made 2026-07-23 23:03:37.295 | TRACE: 172.20.0.1:62084 - ASGI [6] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62084), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/me/appointments', 'raw_path': b'/me/appointments', 'query_string': b'page=1&per_page=50'} 2026-07-23 23:03:37.296 | TRACE: 172.20.0.1:62114 - HTTP connection made 2026-07-23 23:03:37.296 | TRACE: 172.20.0.1:62104 - ASGI [7] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62104), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/schedule/', 'raw_path': b'/schedule/', 'query_string': b''} 2026-07-23 23:03:37.297 | TRACE: 172.20.0.1:62114 - ASGI [8] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62114), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'OPTIONS', 'path': '/me/calendars', 'raw_path': b'/me/calendars', 'query_string': b'only_connected=false'} 2026-07-23 23:03:37.297 | TRACE: 172.20.0.1:62066 - ASGI [4] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.297 | INFO: 172.20.0.1:62066 - "OPTIONS /me/appointments_count_by_status?status=requested HTTP/1.1" 200 OK 2026-07-23 23:03:37.297 | TRACE: 172.20.0.1:62066 - ASGI [4] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.297 | TRACE: 172.20.0.1:62082 - ASGI [5] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.297 | INFO: 172.20.0.1:62082 - "OPTIONS /me HTTP/1.1" 200 OK 2026-07-23 23:03:37.297 | TRACE: 172.20.0.1:62066 - ASGI [4] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62084 - ASGI [6] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.298 | INFO: 172.20.0.1:62084 - "OPTIONS /me/appointments?page=1&per_page=50 HTTP/1.1" 200 OK 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62082 - ASGI [5] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62104 - ASGI [7] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.298 | INFO: 172.20.0.1:62104 - "OPTIONS /schedule/ HTTP/1.1" 200 OK 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62082 - ASGI [5] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62084 - ASGI [6] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.298 | TRACE: 172.20.0.1:62114 - ASGI [8] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.298 | INFO: 172.20.0.1:62114 - "OPTIONS /me/calendars?only_connected=false HTTP/1.1" 200 OK 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62084 - ASGI [6] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62104 - ASGI [7] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62066 - ASGI [4] Completed 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62104 - ASGI [7] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62114 - ASGI [8] Send {'type': 'http.response.body', 'body': '<2 bytes>', 'more_body': True} 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62114 - ASGI [8] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62082 - ASGI [5] Completed 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62084 - ASGI [6] Completed 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62104 - ASGI [7] Completed 2026-07-23 23:03:37.299 | TRACE: 172.20.0.1:62114 - ASGI [8] Completed 2026-07-23 23:03:37.311 | TRACE: 172.20.0.1:62076 - ASGI [9] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62076), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/me/appointments_count_by_status', 'raw_path': b'/me/appointments_count_by_status', 'query_string': b'status=requested'} 2026-07-23 23:03:37.311 | TRACE: 172.20.0.1:62126 - HTTP connection made 2026-07-23 23:03:37.311 | TRACE: 172.20.0.1:62132 - HTTP connection made 2026-07-23 23:03:37.312 | TRACE: 172.20.0.1:62126 - ASGI [10] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62126), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/me', 'raw_path': b'/me', 'query_string': b''} 2026-07-23 23:03:37.313 | TRACE: 172.20.0.1:62140 - HTTP connection made 2026-07-23 23:03:37.313 | TRACE: 172.20.0.1:62132 - ASGI [11] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62132), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/schedule/', 'raw_path': b'/schedule/', 'query_string': b''} 2026-07-23 23:03:37.313 | TRACE: 172.20.0.1:62146 - HTTP connection made 2026-07-23 23:03:37.313 | TRACE: 172.20.0.1:62140 - ASGI [12] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62140), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/me/appointments', 'raw_path': b'/me/appointments', 'query_string': b'page=1&per_page=50'} 2026-07-23 23:03:37.316 | TRACE: 172.20.0.1:62146 - ASGI [13] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62146), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/me/calendars', 'raw_path': b'/me/calendars', 'query_string': b'only_connected=false'} 2026-07-23 23:03:37.388 | /usr/local/lib/python3.12/site-packages/jwt/api_jwt.py:368: InsecureKeyLengthWarning: The HMAC key is 24 bytes long, which is below the minimum recommended length of 32 bytes for SHA256. See RFC 7518 Section 3.2. 2026-07-23 23:03:37.388 | decoded = self.decode_complete( 2026-07-23 23:03:37.503 | TRACE: 172.20.0.1:62146 - ASGI [13] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.504 | INFO: 172.20.0.1:62146 - "GET /me/calendars?only_connected=false HTTP/1.1" 200 OK 2026-07-23 23:03:37.505 | TRACE: 172.20.0.1:62132 - ASGI [11] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.505 | INFO: 172.20.0.1:62132 - "GET /schedule/ HTTP/1.1" 200 OK 2026-07-23 23:03:37.505 | TRACE: 172.20.0.1:62126 - ASGI [10] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.505 | INFO: 172.20.0.1:62126 - "GET /me HTTP/1.1" 200 OK 2026-07-23 23:03:37.505 | TRACE: 172.20.0.1:62146 - ASGI [13] Send {'type': 'http.response.body', 'body': '<871 bytes>', 'more_body': True} 2026-07-23 23:03:37.505 | TRACE: 172.20.0.1:62132 - ASGI [11] Send {'type': 'http.response.body', 'body': '<1759 bytes>', 'more_body': True} 2026-07-23 23:03:37.505 | TRACE: 172.20.0.1:62126 - ASGI [10] Send {'type': 'http.response.body', 'body': '<447 bytes>', 'more_body': True} 2026-07-23 23:03:37.506 | TRACE: 172.20.0.1:62146 - ASGI [13] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.506 | TRACE: 172.20.0.1:62132 - ASGI [11] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.506 | TRACE: 172.20.0.1:62126 - ASGI [10] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.513 | TRACE: 172.20.0.1:62126 - ASGI [10] Completed 2026-07-23 23:03:37.513 | TRACE: 172.20.0.1:62146 - ASGI [13] Completed 2026-07-23 23:03:37.513 | TRACE: 172.20.0.1:62132 - ASGI [11] Completed 2026-07-23 23:03:37.520 | TRACE: 172.20.0.1:62076 - ASGI [9] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.520 | INFO: 172.20.0.1:62076 - "GET /me/appointments_count_by_status?status=requested HTTP/1.1" 200 OK 2026-07-23 23:03:37.521 | TRACE: 172.20.0.1:62076 - ASGI [9] Send {'type': 'http.response.body', 'body': '<11 bytes>', 'more_body': True} 2026-07-23 23:03:37.521 | TRACE: 172.20.0.1:62076 - ASGI [9] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.524 | TRACE: 172.20.0.1:62140 - ASGI [12] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.524 | INFO: 172.20.0.1:62140 - "GET /me/appointments?page=1&per_page=50 HTTP/1.1" 200 OK 2026-07-23 23:03:37.524 | TRACE: 172.20.0.1:62140 - ASGI [12] Send {'type': 'http.response.body', 'body': '<1982 bytes>', 'more_body': True} 2026-07-23 23:03:37.525 | TRACE: 172.20.0.1:62140 - ASGI [12] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.525 | TRACE: 172.20.0.1:62076 - ASGI [9] Completed 2026-07-23 23:03:37.526 | TRACE: 172.20.0.1:62140 - ASGI [12] Completed 2026-07-23 23:03:37.552 | TRACE: 172.20.0.1:62140 - ASGI [14] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62140), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/me/signature', 'raw_path': b'/me/signature', 'query_string': b''} 2026-07-23 23:03:37.573 | TRACE: 172.20.0.1:62140 - ASGI [14] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.573 | INFO: 172.20.0.1:62140 - "GET /me/signature HTTP/1.1" 200 OK 2026-07-23 23:03:37.573 | TRACE: 172.20.0.1:62140 - ASGI [14] Send {'type': 'http.response.body', 'body': '<117 bytes>', 'more_body': True} 2026-07-23 23:03:37.573 | TRACE: 172.20.0.1:62140 - ASGI [14] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.574 | TRACE: 172.20.0.1:62140 - ASGI [14] Completed 2026-07-23 23:03:37.585 | TRACE: 172.20.0.1:62132 - ASGI [15] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62132), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/rmt/cal/1/2026-07-01/2026-08-01', 'raw_path': b'/rmt/cal/1/2026-07-01/2026-08-01', 'query_string': b'force_refresh=true'} 2026-07-23 23:03:37.586 | TRACE: 172.20.0.1:62140 - ASGI [16] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.20.0.6', 5000), 'client': ('172.20.0.1', 62140), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'GET', 'path': '/rmt/cal/4/2026-07-01/2026-08-01', 'raw_path': b'/rmt/cal/4/2026-07-01/2026-08-01', 'query_string': b'force_refresh=true'} 2026-07-23 23:03:37.640 | TRACE: 172.20.0.1:62132 - ASGI [15] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.640 | INFO: 172.20.0.1:62132 - "GET /rmt/cal/1/2026-07-01/2026-08-01?force_refresh=true HTTP/1.1" 200 OK 2026-07-23 23:03:37.640 | TRACE: 172.20.0.1:62132 - ASGI [15] Send {'type': 'http.response.body', 'body': '<1983 bytes>', 'more_body': True} 2026-07-23 23:03:37.640 | TRACE: 172.20.0.1:62132 - ASGI [15] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.641 | TRACE: 172.20.0.1:62140 - ASGI [16] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 2026-07-23 23:03:37.641 | INFO: 172.20.0.1:62140 - "GET /rmt/cal/4/2026-07-01/2026-08-01?force_refresh=true HTTP/1.1" 200 OK 2026-07-23 23:03:37.642 | TRACE: 172.20.0.1:62140 - ASGI [16] Send {'type': 'http.response.body', 'body': '<6149 bytes>', 'more_body': True} 2026-07-23 23:03:37.642 | TRACE: 172.20.0.1:62140 - ASGI [16] Send {'type': 'http.response.body', 'body': '<0 bytes>', 'more_body': False} 2026-07-23 23:03:37.642 | TRACE: 172.20.0.1:62132 - ASGI [15] Completed 2026-07-23 23:03:37.643 | TRACE: 172.20.0.1:62140 - ASGI [16] Completed 2026-07-23 23:03:42.299 | TRACE: 172.20.0.1:62066 - HTTP connection lost 2026-07-23 23:03:42.299 | TRACE: 172.20.0.1:62082 - HTTP connection lost 2026-07-23 23:03:42.299 | TRACE: 172.20.0.1:62084 - HTTP connection lost 2026-07-23 23:03:42.299 | TRACE: 172.20.0.1:62104 - HTTP connection lost 2026-07-23 23:03:42.299 | TRACE: 172.20.0.1:62114 - HTTP connection lost 2026-07-23 23:03:42.506 | TRACE: 172.20.0.1:62146 - HTTP connection lost 2026-07-23 23:03:42.506 | TRACE: 172.20.0.1:62126 - HTTP connection lost 2026-07-23 23:03:42.521 | TRACE: 172.20.0.1:62076 - HTTP connection lost 2026-07-23 23:03:42.640 | TRACE: 172.20.0.1:62132 - HTTP connection lost 2026-07-23 23:03:42.642 | TRACE: 172.20.0.1:62140 - HTTP connection lostAfter, on startup:
After: the same (!) page load of the dashboard