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 [email protected].
To post to this group, send email to [email protected].
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/3fad7e7c-430b-4030-b190-d38515ee7d2c%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
