Logging issues output to console

[marksweb]

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.

[bmispelon]

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?

[marksweb]

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

[bmispelon]

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 🤔