"django.request" logging breaks "logging.handlers.SocketHandler"

[direx]

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
2. 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,
          },  
      }  
   }
   

3. ./manage.py migrate
4. ./manage.py runserver
5. 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.
2. Make the entire request object pickleable (probably not an easy task)
3. Pass in a reduced (pickable) version of the request object in the extra dict
4. 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.

[Tim Graham]

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.

[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.

[HyunTae Hwang]

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.

Django 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.

[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,

[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!

[Roy Smith]

Replying to 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.

[Jacob Walls]

Think I got it fixed up. Perhaps you pasted your comment in both the comment and ticket body boxes?

[Mariusz Felisiak]

Stripping non-picklable attributes may be an acceptable solution, see similar change for HttpResponse d7f5bfd241666c0a76e90208da1e9ef81aec44db.

[Anvesh Mishra]

Replying to 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.

[Anvesh Mishra]

Replying to 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?

[Mariusz Felisiak]

Replying to Anvesh Mishra:

Replying to 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.

[Anvesh Mishra]

Submitted a ​patch

[Mariusz Felisiak <felisiak.mariusz@…>]

In 6220c44:

Fixed #29186 -- Fixed pickling HttpRequest and subclasses.

[Mariusz Felisiak <felisiak.mariusz@…>]

In 280ca147:

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.

[Mariusz Felisiak <felisiak.mariusz@…>]

In 2feb933:

[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