[Django] #29186: "django.request" logging breaks "logging.handlers.SocketHandler"
Django
-----------------------------------------+------------------------
Reporter: direx | Owner: nobody
Type: Bug | Status: new
Component: Uncategorized | Version: 2.0
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
-----------------------------------------+------------------------
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: direx | Owner: nobody
Type: Bug | Status: new
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tim Graham):
* component: Uncategorized => Core (Other)
* stage: Unreviewed => Accepted
Comment:
I'm not sure what the best solution is, but I don't think removing
`request` from `extra` is acceptable as that would be backwards
incompatible for logging handlers using that information.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:1>
Django
Reporter: direx | Owner: nobody
Type: Bug | Status: new
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by direx):
Just for the record: A custom SocketHandler which works around this
problem could look like this:
{{{
# -*- coding: utf-8 -*-
from logging.handlers import SocketHandler as _SocketHandler
class DjangoSocketHandler(_SocketHandler):
def emit(self, record):
if hasattr(record, 'request'):
record.request = None
return super().emit(record)
}}}
I don't know if you guys want to ship this as a workaround and update the
documentation accordingly. This could also be a ''documentation-only'' fix
where this code is added as an example for socket logging.
On the other hand an actual fix would be nice of course. I know this is
not an easy task and since the majority of people probably won't be using
socket logging, a documented and supported workaround (such as the code
above) might be sufficient.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:2>
Django
Reporter: direx | Owner: candypoplatte
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by candypoplatte):
* owner: nobody => candypoplatte
* status: new => assigned
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:3>
Django
Reporter: direx | Owner: candypoplatte
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by candypoplatte):
I made a Pull Request. [https://github.com/django/django/pull/10758]
Respect to direx and Tim, I think django framework has to replace the
SocketHandler to its own SocketHandler that replace the WSGIRequest object
with pickle-able dictionary.
Dhango framework should respect the design philosophy of Python. So it’s
unfair changing SocketHandler.
And it’s unfair blocking SocketHandler or removing request object when it
passed into handlers.
I wonder this approach is okay. Please check this PR.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:4>
Django
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by Tim Graham):
* needs_better_patch: 0 => 1
* has_patch: 0 => 1
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:5>
Django
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Old description:
New 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,
}}}
--
Comment (by Roy Smith):
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,
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:6>
Django
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Comment (by Jacob Walls):
Hi Roy. It's waiting for a volunteer to contribute a patch. In fact, would
you mind reverting the changes you made to the body of the ticket? By
overwriting all the repro instructions and potential solutions in the
ticket body, the result is to make it extremely difficult for a volunteer
to stroll by and pick up this ticket. Use the "diff" link in "Description:
modified (diff)". Thanks!
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:7>
Django
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Comment (by Roy Smith):
Replying to [comment:7 Jacob Walls]:
> Hi Roy. It's waiting for a volunteer to contribute a patch or improve
the existing one. In fact, would you mind reverting the changes you made
to the body of the ticket? By overwriting all the repro instructions and
potential solutions in the ticket body, the result is to make it extremely
difficult for a volunteer to stroll by and pick up this ticket. Use the
"diff" link in "Description: modified (diff)". Thanks!
Whoops, I didn't intend to do anything other than leave a comment. Not
sure what I did to muck up the body of the ticket. I'd be happy to revert
that, but I'm not sure how.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:8>
Django
Reporter: direx | Owner: HyunTae Hwang
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
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:
Steps to reproduce (example):
> -> 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
Reporter: direx | Owner: (none)
Type: Bug | Status: new
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* owner: HyunTae Hwang => (none)
* status: assigned => new
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:10>
Django
Reporter: direx | Owner: (none)
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak):
Stripping non-picklable attributes may be an acceptable solution, see
similar change for `HttpResponse`
d7f5bfd241666c0a76e90208da1e9ef81aec44db.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:11>
Django
Reporter: direx | Owner: (none)
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* needs_better_patch: 1 => 0
* has_patch: 1 => 0
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:12>
Django
Reporter: direx | Owner: (none)
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* cc: Anvesh Mishra (added)
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:13>
Django
Reporter: direx | Owner: Anvesh Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Anvesh Mishra):
* owner: (none) => Anvesh Mishra
* status: new => assigned
Comment:
Replying to [comment:11 Mariusz Felisiak]:
> Stripping non-picklable attributes may be an acceptable solution, see
similar change for `HttpResponse`
d7f5bfd241666c0a76e90208da1e9ef81aec44db.
Yeah seems like a valid solution gonna work on it.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:14>
Django
Reporter: direx | Owner: Anvesh Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Anvesh Mishra):
Replying to [comment:11 Mariusz Felisiak]:
> Stripping non-picklable attributes may be an acceptable solution, see
similar change for `HttpResponse`
d7f5bfd241666c0a76e90208da1e9ef81aec44db.
Felix if you could give an idea about what the non-picklable attributes
could be?
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:15>
Django
Reporter: direx | Owner: Anvesh Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak):
Replying to [comment:15 Anvesh Mishra]:
> Replying to [comment:11 Mariusz Felisiak]:
> > Stripping non-picklable attributes may be an acceptable solution, see
similar change for `HttpResponse`
d7f5bfd241666c0a76e90208da1e9ef81aec44db.
> Felix if you could give an idea about what the non-picklable attributes
could be in this case?
You should be able to find out after creating a regression test.
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:16>
Django
Reporter: direx | Owner: Anvesh Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Anvesh Mishra):
Submitted a [https://github.com/django/django/pull/15937 patch]
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:17>
Django
Reporter: direx | Owner: Anvesh Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 1 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* needs_better_patch: 0 => 1
* has_patch: 0 => 1
* needs_tests: 0 => 1
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:18>
Django
Reporter: direx | Owner: Anvesh
| Mishra
Type: Bug | Status: assigned
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
| checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* needs_better_patch: 1 => 0
* needs_tests: 1 => 0
* stage: Accepted => Ready for checkin
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:19>
Django
Reporter: direx | Owner: Anvesh
| Mishra
Component: Core (Other) | Version: 2.0
Keywords: | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak <felisiak.mariusz@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"6220c445c40a6a7f4d442de8bde2628346153963" 6220c44]:
{{{
#!CommitTicketReference repository=""
revision="6220c445c40a6a7f4d442de8bde2628346153963"
Fixed #29186 -- Fixed pickling HttpRequest and subclasses.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:20>
Django
Reporter: direx | Owner: Anvesh
| Mishra
Type: Bug | Status: closed
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"280ca147af9cdfce1ca9cb14cc3c5527ff6c7a02" 280ca147]:
{{{
#!CommitTicketReference repository=""
revision="280ca147af9cdfce1ca9cb14cc3c5527ff6c7a02"
Fixed #34484, Refs #34482 -- Reverted "Fixed #29186 -- Fixed pickling
HttpRequest and subclasses."
This reverts commit 6220c445c40a6a7f4d442de8bde2628346153963.
Thanks Adam Johnson and Márton Salomváry for reports.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:21>
Django
Reporter: direx | Owner: Anvesh
| Mishra
Type: Bug | Status: closed
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Mariusz Felisiak <felisiak.mariusz@…>):
In [changeset:"2feb9333e7044df348c45417d23ee20b08c1a7fd" 2feb933]:
{{{
#!CommitTicketReference repository=""
revision="2feb9333e7044df348c45417d23ee20b08c1a7fd"
[4.2.x] Fixed #34484, Refs #34482 -- Reverted "Fixed #29186 -- Fixed
pickling HttpRequest and subclasses."
This reverts commit 6220c445c40a6a7f4d442de8bde2628346153963.
Thanks Adam Johnson and Márton Salomváry for reports.
Backport of 280ca147af9cdfce1ca9cb14cc3c5527ff6c7a02 from main
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:22>
Django
Reporter: direx | Owner: Anvesh Mishra
Component: Core (Other) | Version: 2.0
Severity: Normal | Resolution:
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak):
* status: closed => new
* has_patch: 1 => 0
* resolution: fixed =>
* stage: Ready for checkin => Accepted
--
Ticket URL: <https://code.djangoproject.com/ticket/29186#comment:23>