Access request body in the django.request logger
2,108 views
Skip to first unread message
Ben Whale
Sep 15, 2016, 6:53:55 AM9/15/16
to Django users
Hi
What I'd like to do is log the request body whenever the django.request logger logs something. I had assumed that the extra context referred to as request in https://docs.djangoproject.com/en/1.10/topics/logging/#django-request was something like an HTTPRequest object. It is, however, an instance of socket._socketobject.
Is it possible to get data for logging using the socket? For example the get parameters, the post data, any information associated to a file that was sent like what every has been read out of the socket? What about the request headers?
Why is a socket passed to the logger? I must admit that I assume this to be a bug. The user has a very limited way of interacting with the socket via the string formatting syntax and the methods of the socket (as introspected via dir) don't lend them selves to this form of access.
I'm currently using django 1.10 if that helps.
Thanks for any help.
Tim Graham
Sep 15, 2016, 9:21:59 AM9/15/16
to Django users
If true, it does seem like a bug. Could you provide a test for Django's test suite or a sample project to reproduce it?
Ben Whale
Sep 15, 2016, 6:16:09 PM9/15/16
to Django users
Thanks for the reply Tim
Some testing seems to indicate that it is an issue with django-rest-framework. When I contact the web server using urls managed by django rest the issues occurs, when I do the same via url managed by vanilla django the request variable in the context object is an instance of WSGIRequest, which is far more sensible.
I'm doing to do some more digging today to prove this and, assuming I'm right, will pass the bug onto the django rest guys.
Any hints on debugging this? I haven't entered the django code base much before.
Ben Whale
Sep 15, 2016, 7:32:25 PM9/15/16
to Django users
Well my last reply was preemptery.
A minimal working example can be produced via the following commands. First navigate to a suitable directory then,
# virtualenv venv --no-site-packages
# source venv/bin/activate
# pip install django
# django-admin startproject mwe
# vim mwe/mwe/settings.y
and then entering the following at the end of the settings.py file:
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'django.server': {
'()': 'django.utils.log.ServerFormatter',
'format': '[%(server_time)s] %(message)s %(request)r',
}
},
'handlers': {
'django.server': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'django.server',
},
},
'loggers': {
'django.server': {
'handlers': ['django.server'],
'level': 'INFO',
'propagate': False,
},
}
}
Then :wq
# cd mwe
# python manage.py runserver
Navigate to http://127.0.0.1:8000/blargh
The normal error message about routing will show. Switch back to the console and you'll see:
# python manage.py runserver
Performing system checks...
System check identified no issues (0 silenced).
September 15, 2016 - 23:12:05
Django version 1.10.1, using settings 'mwe.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
Not Found: /blargh
[15/Sep/2016 23:12:09] "GET /blargh HTTP/1.1" 404 1918 <socket._socketobject object at 0x7fa14d58da60>
That representation of the socket object is being produced by the "%(request)r" in the formatter.
Chasing this back through the call stack the request object is set in /usr/lib/python2.7/SocketServer.py(652)__init__() as the socket. This is seems reasonable to me, so I guess some kind of processing of the request isn't being performed somewhere.
Tim Graham
Sep 15, 2016, 8:28:45 PM9/15/16
to Django users
The logging is coming from here: https://github.com/django/django/blob/43c471e81c27542e4dc392dfa2310c5a52db35d9/django/core/servers/basehttp.py#L103 where self.request is indeed a "socketobject"
I'm not sure if the WSGIRequest object is available at that point, so possibly this just needs a documentation clarification.
I'm not sure if the WSGIRequest object is available at that point, so possibly this just needs a documentation clarification.
Ben Whale
Sep 16, 2016, 1:09:13 AM9/16/16
to Django users
Thanks for a link to the blob, that is very helpful.
The logging message is generated in django/utils/log.py in the ServerFormatter format() method. If the logging setting is
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
},
'simple': {
'format': '%(levelname)s %(message)s'
},
'django.server': {
'()': 'django.utils.log.ServerFormatter',
'format': '[%(server_time)s] %(message)s %(request)r',
}
},
'filters': {
'require_debug_false': {
'()': 'django.utils.log.RequireDebugFalse',
},
'require_debug_true': {
'()': 'django.utils.log.RequireDebugTrue',
},
},
'handlers': {
'console': {
'level': 'DEBUG',
'filters': ['require_debug_true'],
'class': 'logging.StreamHandler',
},
'django.server': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'django.server',
},
'mail_admins': {
'level': 'DEBUG',
'filters': ['require_debug_false'],
'class': 'django.utils.log.AdminEmailHandler'
},
'log_file': {
'level': 'DEBUG',
'filters': ['require_debug_false'],
'class': 'logging.FileHandler',
'formatter': 'verbose',
'filename': './django.log'
}
},
'loggers': {
'django.server': {
'handlers': ['django.server'],
'level': 'INFO',
'propagate': False,
},
}
}
then record.request is a socket object. If, however, the logging setting is
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
},
'simple': {
'format': '%(levelname)s %(message)s'
},
'django.server': {
'()': 'django.utils.log.ServerFormatter',
'format': '[%(server_time)s] %(message)s %(request)r',
}
},
'filters': {
'require_debug_false': {
'()': 'django.utils.log.RequireDebugFalse',
},
'require_debug_true': {
'()': 'django.utils.log.RequireDebugTrue',
},
},
'handlers': {
'console': {
'level': 'DEBUG',
'filters': ['require_debug_true'],
'class': 'logging.StreamHandler',
},
'django.server': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'django.server',
},
'mail_admins': {
'level': 'DEBUG',
'filters': ['require_debug_false'],
'class': 'django.utils.log.AdminEmailHandler'
},
'log_file': {
'level': 'DEBUG',
'filters': ['require_debug_false'],
'class': 'logging.FileHandler',
'formatter': 'verbose',
'filename': './django.log'
}
},
'loggers': {
'django': {
'handlers': ['console', 'mail_admins', 'log_file'],
'level': 'DEBUG',
},
'django.server': {
'handlers': ['django.server'],
'level': 'INFO',
'propagate': False,
},
'django.request': {
'handlers': ['django.server', 'mail_admins', 'console'],
'level': 'DEBUG',
'propagate': False,
},
'django.template': {
'handlers': ['log_file', 'mail_admins', 'console'],
'level': 'DEBUG',
'propagate': False,
},
}
}
the format() method is entered twice the first time record.request is a WSGIRequest object and the second time it is a socket.
Interestingly there is a definite bug here as the method generates an IndexError. The stack trace is:
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 173, in format
if args[1][0] == '2':
IndexError: tuple index out of range
This occurs because the args object is (u'/foo',) and I think it's expecting something like (u'/foo', 404, 234324) instead. This occurs on the first pass through the format() method but not the second.
In any case, with the appearance of an honest to god bug I'll write up two bug reports and link them. At this point I don't really want to spend to time necessary to determine exactly what's happening.
Ben Whale
Sep 16, 2016, 1:25:21 AM9/16/16
to Django users
I should add that this difference in behavior occurs because the handlers array in the Logger class is different in the two cases. Specifically in the line " for hdlr in c.handlers:" in the file <python>/logging/__init__.py the variable c.handlers is empty ([]) in the first case and is a list of handlers in the second case.
Because of this it seems like there is some django custom logging occuring that doesn't use the built in python logging? In which case record.request being a socket object would be associated with this django custom logging? I know I don't know the django code base, but I find this sort of behavior surprising and as a result... I suspect a bug.
Justin Wilson
Nov 7, 2016, 4:48:14 PM11/7/16
to Django users
Stumbled across this post while trying to solve the same issue (we've had this issue since 1.10 release, but have kept with 1.9 due to this issue).
We're only getting this with Django 1.10+ when running behind uWSGI.
The issue goes away if we just run the Django dev server.
We're only getting this with Django 1.10+ when running behind uWSGI.
The issue goes away if we just run the Django dev server.
Justin Wilson
Nov 7, 2016, 6:05:10 PM11/7/16
to Django users
Sorry, I had those reversed. It works find WITH uWSGI, and fails with the Django dev server.
Reply all
Reply to author
Forward
0 new messages