djangoproject.com
djangoproject.com copied to clipboard
django
Logging issues output to console
While adding translations to the foundation app and setting up a test meeting I'm seeing the following in the console which appears to suggest a failure to log something;
[16/Oct/2024 13:45:14] "POST /admin/foundation/meeting/add/ HTTP/1.1" 302 0
[16/Oct/2024 13:45:14] "GET /admin/foundation/meeting/ HTTP/1.1" 200 23376
[16/Oct/2024 13:45:15] "GET /s/admin/js/filters.js HTTP/1.1" 200 978
[16/Oct/2024 13:45:15] "GET /s/admin/js/jquery.init.js HTTP/1.1" 200 347
[16/Oct/2024 13:45:15] "GET /admin/jsi18n/ HTTP/1.1" 200 3325
[16/Oct/2024 13:45:15] "GET /favicon.ico HTTP/1.1" 404 8164
--- Logging error ---
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 692, in process_request_thread
self.finish_request(request, client_address)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 362, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 761, in __init__
self.handle()
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 229, in handle
self.handle_one_request()
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 237, in handle_one_request
self.raw_requestline = self.rfile.readline(65537)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socket.py", line 707, in readinto
return self._sock.recv_into(b)
^^^^^^^^^^^^^^^^^^^^^^^
ConnectionResetError: [Errno 54] Connection reset by peer
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 464, in format
return self._format(record)
^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 460, in _format
return self._fmt % values
~~~~~~~~~~^~~~~~~~
KeyError: 'server_time'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1160, in emit
msg = self.format(record)
^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 999, in format
return fmt.format(record)
^^^^^^^^^^^^^^^^^^
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/utils/log.py", line 204, in format
return super().format(record)
^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 706, in format
s = self.formatMessage(record)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 675, in formatMessage
return self._style.format(record)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 466, in format
raise ValueError('Formatting field not found in record: %s' % e)
ValueError: Formatting field not found in record: 'server_time'
Call stack:
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1030, in _bootstrap
self._bootstrap_inner()
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
self.run()
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1010, in run
self._target(*self._args, **self._kwargs)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 694, in process_request_thread
self.handle_error(request, client_address)
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 81, in handle_error
logger.info("- Broken pipe from %s", client_address)
Message: '- Broken pipe from %s'
Arguments: (('127.0.0.1', 57749),)
[16/Oct/2024 13:45:17] "GET /admin/foundation/meeting/1/change/ HTTP/1.1" 200 68296
[16/Oct/2024 13:45:17] "GET /s/admin/js/calendar.js HTTP/1.1" 200 8466
[16/Oct/2024 13:45:17] "GET /s/admin/js/inlines.js HTTP/1.1" 200 15526
[16/Oct/2024 13:45:17] "GET /s/admin/js/SelectBox.js HTTP/1.1" 200 4530
[16/Oct/2024 13:45:17] "GET /s/admin/js/SelectFilter2.js HTTP/1.1" 200 15292
[16/Oct/2024 13:45:17] "GET /admin/jsi18n/ HTTP/1.1" 200 3325
[16/Oct/2024 13:45:17] "GET /s/admin/img/tooltag-arrowright.svg HTTP/1.1" 200 280
[16/Oct/2024 13:45:17] "GET /favicon.ico HTTP/1.1" 404 8164
--- Logging error ---
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 692, in process_request_thread
self.finish_request(request, client_address)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 362, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 761, in __init__
self.handle()
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 229, in handle
self.handle_one_request()
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 237, in handle_one_request
self.raw_requestline = self.rfile.readline(65537)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socket.py", line 707, in readinto
return self._sock.recv_into(b)
^^^^^^^^^^^^^^^^^^^^^^^
ConnectionResetError: [Errno 54] Connection reset by peer
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 464, in format
return self._format(record)
^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 460, in _format
return self._fmt % values
~~~~~~~~~~^~~~~~~~
KeyError: 'server_time'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1160, in emit
msg = self.format(record)
^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 999, in format
return fmt.format(record)
^^^^^^^^^^^^^^^^^^
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/utils/log.py", line 204, in format
return super().format(record)
^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 706, in format
s = self.formatMessage(record)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 675, in formatMessage
return self._style.format(record)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 466, in format
raise ValueError('Formatting field not found in record: %s' % e)
ValueError: Formatting field not found in record: 'server_time'
Call stack:
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1030, in _bootstrap
self._bootstrap_inner()
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
self.run()
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1010, in run
self._target(*self._args, **self._kwargs)
File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/socketserver.py", line 694, in process_request_thread
self.handle_error(request, client_address)
File "/Users/mark/dev/djangoproject.com/.venv/lib/python3.12/site-packages/django/core/servers/basehttp.py", line 81, in handle_error
logger.info("- Broken pipe from %s", client_address)
Message: '- Broken pipe from %s'
Arguments: (('127.0.0.1', 57751),)
[16/Oct/2024 13:45:18] "GET /admin/r/22/1/ HTTP/1.1" 302 0
[16/Oct/2024 13:45:18] "GET /foundation/minutes/2024/oct/16/dsf-board-monthly-meeting/ HTTP/1.1" 200 14293
I'll try to find time to look into this, but dumping this here in the meantime.
I haven't looked into this in details at all, but I notice you're running Python 3.12 and I wonder if that could be the source of the issue. We're currently running 3.8 in production I believe (there's ongoing work to update, but it's not ready just yet). Do you have a way to run the site with an older version of Python?
@bmispelon Yeah I saw that Paolo has been working on dropping 3.8 and I generally setup a venv with whatever is in the dockerfile, so that's 3.12. Also makes it easier to spot things that might be needing a fix if we're moving that way but not there yet.
I'll swap the venv for a 3.8 one and test it again when I've got the current batch of translations and review comments out the way 👍🏼
Are you still experiencing this? I'm not able to reproduce it locally, so I wonder if it got fixed by upgrading Django, or if maybe there's some differences between our setups 🤔
@bmispelon I'll have to check. Had a hectic month but planning on getting back to the project (like writing those tests for Jeff's change) over the holiday so I don't forget everything I know before starting work in January 😂