[Django] #27234: django.request receives a socket object rather than a request object in logging
Django
logging
-------------------------+-------------------------------------------------
Reporter: ben- | Owner: nobody
whale |
Type: Bug | Status: new
Component: | Version: 1.10
Uncategorized | Keywords: django.request runserver
Severity: Normal | WSGIRequest socket
Triage Stage: | Has patch: 0
Unreviewed |
Easy pickings: 0 | UI/UX: 0
-------------------------+-------------------------------------------------
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
logging
Reporter: ben-whale | Owner: nobody
Type: Bug | Status: closed
Component: Uncategorized | Version: 1.10
Severity: Normal | Resolution: invalid
Keywords: django.request | Triage Stage:
runserver WSGIRequest socket | Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by ben-whale):
* status: new => closed
* needs_better_patch: => 0
* resolution: => invalid
* needs_tests: => 0
* needs_docs: => 0
Comment:
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:1>
Django
logging
Reporter: ben-whale | Owner: nobody
Component: Uncategorized | Version: 1.10
Severity: Normal | Resolution:
runserver WSGIRequest socket | Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Changes (by ben-whale):
* status: closed => new
* resolution: invalid =>
Comment:
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?
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:2>
Django
-------------------------------------+-------------------------------------
Reporter: ben-whale | Owner: nobody
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Changes (by timgraham):
* component: Uncategorized => Documentation
* stage: Unreviewed => Accepted
* type: Bug => Cleanup/optimization
Comment:
I think updating [https://docs.djangoproject.com/en/1.10/topics/logging
/#django-server the docs] is the correct resolution.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:3>
Django
-------------------------------------+-------------------------------------
Type: | Status: new
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by 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).
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:4>
Django
-------------------------------------+-------------------------------------
Reporter: Ben Whale | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:5>
Django
-------------------------------------+-------------------------------------
Reporter: Ben Whale | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by 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?
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:6>
Django
-------------------------------------+-------------------------------------
Reporter: Ben Whale | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:7>
Django
-------------------------------------+-------------------------------------
Reporter: Ben Whale | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Documentation | Version: 1.10
Severity: Normal | Resolution:
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by Ben Whale):
Oke doke. Thanks for the thoughts.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:8>
Django
-------------------------------------+-------------------------------------
Reporter: Ben Whale | Owner: nobody
Cleanup/optimization |
Component: Documentation | Version: 1.10
Keywords: django.request | Triage Stage: Accepted
runserver WSGIRequest socket |
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Changes (by Natalia Bidart):
* status: new => closed
* resolution: => duplicate
Comment:
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27234#comment:9>