Clarify the type of the django.server logger's 'request' extra context

[Ben Whale]

This bug (if indeed it is a bug) is probably related to: #27233 (https://code.djangoproject.com/ticket/27233).

The documentation for the django.request logger (​https://docs.djangoproject.com/en/1.10/topics/logging/#django-request) implies that the request variable (passed in as extra context) is a request (or something request like). Instead, it can be either an instance of WSGIRequest or socket.

I expected it to be something request like so that it would be possible to log the GET parameters or the POST data. I'm pretty sure that the socket the webserver listens to shouldn't be passed to a logging object that a user could then interact with.

How to replicate:
I'm going to give to examples, the first will show that the request variable is a socket, the second will show that it is sometimes a WSGIRequest and sometimes a socket.

First example:
1) install vanilla django and set up a project.
2) Put the following into the settings.py file:

LOGGING = {                                                                          
    'version': 1,                                                                    
    'disable_existing_loggers': False,                                               
    'formatters': {                                                                     
        'custom': {                                                                                                                                                                                                                                                                   
            '()': 'django.utils.log.ServerFormatter',                                   
            'format': '[%(server_time)s] %(message)s %(request)r',                      
        }                                                                               
    },                                                                                  
    'handlers': {                                                                       
        'custom': {                                                                     
            'level': 'INFO',                                                            
            'class': 'logging.StreamHandler',                                           
            'formatter': 'custom',                                                      
        },                                                                              
    },                                                                                  
    'loggers': {                                                                        
        'django.request': {                                                             
            'handlers': ['custom'],                                                     
            'level': 'DEBUG',                                                           
            'propagate': False,                                                         
        },                                                                              
    }                                                                                   
} 

3) Edit the file <path_to_django_install>/django/utils/log.py and put the following print repr(record.request) into the format method of the ServerFormatter object
4) use python manage.py runserver to launch the server
5) navigate to a valid page, e.g. 127.0.0.1:8000 (I use port 8001 because reasons)

You should see something like

# python manage.py runserver 8001
System check identified no issues (0 silenced).
September 16, 2016 - 06:01:12
Django version 1.10.1, using settings 'mwe.settings'
Starting development server at http://127.0.0.1:8001/
Quit the server with CONTROL-C.
<socket._socketobject object at 0x7fc4fccc4c90>
[16/Sep/2016 06:01:14] "GET / HTTP/1.1" 200 1767

The line <socket._socketobject object at 0x7fc4fccc4c90> is the string representation of the request.

Second example:
Using the same set up as for the first example navigate to an invalid page, e.g. 127.0.0.1:8001/foo

You should see something like

System check identified no issues (0 silenced).
September 16, 2016 - 06:06:15
Django version 1.10.1, using settings 'mwe.settings'
Starting development server at http://127.0.0.1:8001/
Quit the server with CONTROL-C.
<WSGIRequest: GET '/foo'>
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 861, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/home/benwhale/Documents/Projects/mwe/venv/local/lib/python2.7/site-packages/django/utils/log.py", line 174, in format
    if args[1][0] == '2':
IndexError: tuple index out of range
Logged from file base.py, line 152
<socket._socketobject object at 0x7f4997751a60>
[16/Sep/2016 06:06:18] "GET /foo HTTP/1.1" 404 1909

on the command line. Please ignore the IndexError for the purposes of this bug see https://code.djangoproject.com/ticket/27233. Observe the two lines <WSGIRequest: GET '/foo'> and <socket._socketobject object at 0x7f4997751a60> these indicate that the request object can be either a WSGIRequest or a socket object.

Placing a break point in the format method is not sufficient to see both calls with WSGIRequest and socket objects as, at least for me, the break point would only trigger once.

The code paths that result in both calls are slightly different and result from a difference in the handlers array in the Logger object. This difference in code path also responsible for the IndexError and so fixing this ticket is likely to be related to fixing ticket #27233.

[Ben Whale]

Bug #27233 has been resolved as invalid. This indicates that it is invalid to use the ServerFormatter in anything other than the django.server logger. As a consequence the socket vs WSGIRequest issue is partly (fully?) resolved.

The reason for the difference in the request object comes from calls being logged by django.request and django.server through the same formatter. So no surprise when different arguments result.

I'm guessing this should be marked as invalid since the implementation of the ServerFormatter is an internal detail and the user should never see the difference mentioned above.

[Ben Whale]

Actually it occurs to me that the documentation should probably be altered. For 1.10 it implies that django.server is the same as django.request except that it only logs when the runserver command is used. This is incorrect as django.server receives sockets rather than WSGIRequests it is also incorrect as the record.args is different in both cases.

So either the documentation should be changed or the code should be altered to match the documentation?

[Tim Graham]

I think updating ​the docs is the correct resolution.

[Ben Whale]

I'll leave that judgement to you.

Does #26688 standardise django.request and django.server so that they both receive WSGIRequests or both receive sockets? This might effect documentation changes for 1.11.

Because I'm curious, why have both django.request and django.server loggers? The documentation implies that they do the same thing, after #26688 they will log the same things and they both run when using python manage.py runserver. Would it be sensible to look to removing django.server in favour of django.request at some future point? For example as an additional patch to 1.11 or even 1.12? If you think it's worth looking into I'm happy to do some digging to find out what the changes would look like (I want to learn more about the django internals in any case).

[Tim Graham]

No, I don't think the PR you mentioned has an effect on this.

From the documentation:

django.request: "Log messages related to the handling of requests."

django.server: Log messages related to the handling of requests received by the server invoked by the runserver command.

If that distinction isn't clear, then I guess the documentation should be clarified. Perhaps it was all less confusing before runserver was modified to use logging (#25684).

My ideal scenario involves deprecating runserver in favor of a normal wsgi runserver such as gunicorn (#21978) so that Django doesn't need to maintain it's own minimal server, but it's unclear if it's feasible.

[Ben Whale]

Agreed, and even if it was possible it'd be along way off. The additional work required for beginners to get up and running would also need to be considered.

It might be possible to replace the calls to django.server with calls to django.request without removing runserver or do you think django.server is too tightly integrated? Such a change might make it easier to remove runserver in the future?

As a side point, would you be against including a comment in the django logging documentation that certain kinds of logging (e.g. all incoming requests) are better handled by the actual webserver (e.g. Apache or Nginx) in a production or remote development environment?

[Tim Graham]

I don't think making django.request do the logging of django.server is desirable. The purpose of having two loggers is to keep runserver logging separate from other logging.

I don't have any strong feelings about your documentation proposal. I'm sure there are plenty of apps out there that use Django logging for all requests and I don't see any problems with that.

[Ben Whale]

Oke doke. Thanks for the thoughts.

[Natalia Bidart]

Ticket #34781 was recently filed and fixed and I did not spot this ticket in my "duplicate search", but someone mentioned it today during Django Sprints in Durham. Closing as dupe of #34781.