Django talk: Re: Access request body in the django.request logger

Sorry, I had those reversed. It works find WITH uWSGI, and fails with the Django dev server.

On Monday, November 7, 2016 at 2:48:14 PM UTC-7, Justin Wilson wrote:

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.

On Thursday, September 15, 2016 at 11:09:13 PM UTC-6, Ben Whale wrote:
Thanks for a link to the blob, that is very helpful.

You might be right, but the more I look at this the more I think it is a bug.

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.

On Friday, 16 September 2016 10:28:45 UTC+10, Tim Graham wrote:
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.

On Thursday, September 15, 2016 at 7:32:25 PM UTC-4, Ben Whale wrote:
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.

On Friday, 16 September 2016 08:16:09 UTC+10, Ben Whale wrote:
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.

On Thursday, 15 September 2016 23:21:59 UTC+10, Tim Graham wrote:
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?

On Thursday, September 15, 2016 at 6:53:55 AM UTC-4, Ben Whale wrote:
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.

--
You received this message because you are subscribed to the Google Groups "Django users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-users+unsubscribe@googlegroups.com.
To post to this group, send email to django-users@googlegroups.com.
Visit this group at https://groups.google.com/group/django-users.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-users/f297b70f-9c91-40cf-a773-fdfc25e80b3c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Django talk

Monday, November 7, 2016

Re: Access request body in the django.request logger

No comments:

Post a Comment