#29186: "django.request" logging breaks "logging.handlers.SocketHandler"
------------------------------+-----------------------------------------
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
------------------------------+-----------------------------------------
Old description:
> Just wondering what the status of this is. I get occasional errors like
> the following in my log file. Looks like it's this same issue. I'm
> running Django 3.1.8.
>
> {{{
> --- Logging error ---
> Traceback (most recent call last):
> File "/data/project/spi-tools-dev/python-
> distros/Python-3.7.3-install/lib/python3.7/logging/handlers.py", line
> 630, in emit
> s = self.makePickle(record)
> File "/data/project/spi-tools-dev/python-
> distros/Python-3.7.3-install/lib/python3.7/logging/handlers.py", line
> 602, in makePickle
> s = pickle.dumps(d, 1)
> File "/data/project/spi-tools-dev/python-
> distros/Python-3.7.3-install/lib/python3.7/copyreg.py", line 65, in
> _reduce_ex
> raise TypeError("can't pickle %s objects" % base.__name__)
> TypeError: can't pickle _Input objects
> Call stack:
> File "/data/project/spi-tools-dev/www/python/venv/lib/python3.7/site-
> packages/django/core/handlers/wsgi.py", line 133, in __call__
> response = self.get_response(request)
> File "/data/project/spi-tools-dev/www/python/venv/lib/python3.7/site-
> packages/django/core/handlers/base.py", line 136, in get_response
> request=request,
> File "/data/project/spi-tools-dev/www/python/venv/lib/python3.7/site-
> packages/django/utils/log.py", line 230, in log_response
> exc_info=exc_info,
> }}}
New description:
When setting up logging with Python's default `SocketHandler` then the log
messages produced by `django.request` cause an exception in the logging
system. This happens everywhere where Django passes an `extra={'request':
request}` dictionary to log messages. The reason for this is that the
request object cannot be pickled.
Steps to reproduce (example):
1. `./manage.py startproject`
1. Add this logging config in settings:
{{{
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'socket_handler': {
'class': 'logging.handlers.SocketHandler',
'host': '127.0.0.1',
'port': 9020,
}
},
'loggers': {
'django.request': {
'handlers': ['socket_handler'],
'level': 'INFO',
'propagate': False,
},
}
}
}}}
1. `./manage.py migrate`
1. `./manage.py runserver`
1. `wget http://127.0.0.1:8000/invalid -O /dev//null`
The exception is this one:
{{{
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.6/logging/handlers.py", line 633, in emit
s = self.makePickle(record)
File "/usr/lib/python3.6/logging/handlers.py", line 605, in makePickle
s = pickle.dumps(d, 1)
File "/usr/lib/python3.6/copyreg.py", line 65, in _reduce_ex
raise TypeError("can't pickle %s objects" % base.__name__)
TypeError: can't pickle BufferedReader objects
Call stack:
File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
self._bootstrap_inner()
File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/usr/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib/python3.6/socketserver.py", line 639, in
process_request_thread
self.finish_request(request, client_address)
File "/usr/lib/python3.6/socketserver.py", line 361, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "/usr/lib/python3.6/socketserver.py", line 696, in __init__
self.handle()
File "/home/direx/virtualenv/django-2.0/lib/python3.6/site-
packages/django/core/servers/basehttp.py", line 154, in handle
handler.run(self.server.get_app())
File "/usr/lib/python3.6/wsgiref/handlers.py", line 137, in run
self.result = application(self.environ, self.start_response)
File "/home/direx/virtualenv/django-2.0/lib/python3.6/site-
packages/django/contrib/staticfiles/handlers.py", line 66, in __call__
return self.application(environ, start_response)
File "/home/direx/virtualenv/django-2.0/lib/python3.6/site-
packages/django/core/handlers/wsgi.py", line 146, in __call__
response = self.get_response(request)
File "/home/direx/virtualenv/django-2.0/lib/python3.6/site-
packages/django/core/handlers/base.py", line 93, in get_response
extra={'status_code': 404, 'request': request},
Message: 'Not Found: %s'
Arguments: ('/invalid',)
}}}
Of course these steps are only an example. This bug does not only apply to
404 errors, but also to CSRF verfication errors for instance. In fact all
places where the `request` object is passed in as an `extra` logger
argument.
I see a few possible solutions for this issue:
1. Remove the `request` object from the `extra` log message dict. Right
now I am not even sure why this is required.
1. Make the entire `request` object pickleable (probably not an easy task)
1. Pass in a reduced (pickable) version of the request object in the
`extra` dict
1. Ship a compatible version of `SocketHandler`
BTW: socket logging is explicitly mentioned in the Django docs:
> -> The handler is the engine that determines what happens to each
message in a logger. It describes a particular logging behavior, such as
writing a message to the screen, to a file, **or to a network socket**.
This bug also applies to older Django versions.
--
Comment (by Jacob Walls):
Think I got it fixed up. Perhaps you pasted your comment in both the
comment and ticket body boxes?
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:9>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
--
You received this message because you are subscribed to the Google Groups
"Django updates" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/django-updates/063.9a6d892ce6aa4c515fbfd3062ca50ac5%40djangoproject.com.
