Opened 8 years ago
Closed 13 months ago
#27234 closed Cleanup/optimization (duplicate)
Clarify the type of the django.server logger's 'request' extra context
Reported by: | Ben Whale | Owned by: | nobody |
---|---|---|---|
Component: | Documentation | Version: | 1.10 |
Severity: | Normal | Keywords: | django.request runserver WSGIRequest socket |
Cc: | Triage Stage: | Accepted | |
Has patch: | no | Needs documentation: | no |
Needs tests: | no | Patch needs improvement: | no |
Easy pickings: | no | UI/UX: | no |
Description
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.
Change History (9)
comment:1 by , 8 years ago
Resolution: | → invalid |
---|---|
Status: | new → closed |
comment:2 by , 8 years ago
Resolution: | invalid |
---|---|
Status: | closed → new |
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?
comment:3 by , 8 years ago
Component: | Uncategorized → Documentation |
---|---|
Summary: | django.request receives a socket object rather than a request object in logging → Clarify the type of the django.server logger's 'request' extra context |
Triage Stage: | Unreviewed → Accepted |
Type: | Bug → Cleanup/optimization |
I think updating the docs is the correct resolution.
comment:4 by , 8 years ago
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).
comment:5 by , 8 years ago
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.
comment:6 by , 8 years ago
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?
comment:7 by , 8 years ago
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.
comment:9 by , 13 months ago
Resolution: | → duplicate |
---|---|
Status: | new → closed |
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
vsWSGIRequest
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.