Project

General

Profile

Bug #35629

trace lors des logs, mauvais objet request

Added by Frédéric Péters 19 days ago. Updated about 9 hours ago.

Status:
Solution déployée
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
Start date:
28 Aug 2019
Due date:
% Done:

0%

Patch proposed:
Yes
Planning:
No

Description

Depuis 0f17a562 dans #35302, je me trouve en local (runserver) avec des :

Traceback (most recent call last):
  File "/usr/lib/python2.7/wsgiref/handlers.py", line 86, in run
    self.finish_response()
  File "/usr/lib/python2.7/wsgiref/handlers.py", line 131, in finish_response
    self.close()
  File "/usr/lib/python2.7/wsgiref/simple_server.py", line 33, in close
    self.status.split(' ',1)[0], self.bytes_sent
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 433, in log_request
    self.requestline, str(code), str(size))
  File "/home/fred/src/eo/venv1.11/local/lib/python2.7/site-packages/django/core/servers/basehttp.py", line 124, in log_message
    level(format, *args, extra=extra)
  File "/usr/lib/python2.7/logging/__init__.py", line 1174, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1293, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1303, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1343, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 762, in handle
    rv = self.filter(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 617, in filter
    if not f.filter(record):
  File "/home/fred/src/eo/authentic/src/authentic2/log_filters.py", line 43, in filter
    record.ip = request.META.get('REMOTE_ADDR', self.DEFAULT_IP)
AttributeError: '_socketobject' object has no attribute 'META'

J'ai dégagé ça en local via,

         request = record.request = getattr(record, 'request', middleware.StoreRequestMiddleware.get_request())
+        if request and not hasattr(request, 'META'):
+            record.request = None

mais il doit y avoir davantage à creuser.

0001-misc-ignore-non-request-objects-in-log-filters-35629.patch View (963 Bytes) Frédéric Péters, 10 Sep 2019 10:03 PM

Associated revisions

Revision e18a4852 (diff)
Added by Frédéric Péters 5 days ago

misc: ignore non-request objects in log filters (#35629)

History

#1 Updated by Éloi Rivard 19 days ago

Pour récupérer l'IP à partir d'une socket :

+                if not hasattr(request, "META"):
+                    record.id = request.getpeername()[0]
+
+                else:
+                    record.ip = request.META.get('REMOTE_ADDR', self.DEFAULT_IP)

#2 Updated by Frédéric Péters 5 days ago

#3 Updated by Emmanuel Cazenave 5 days ago

  • Status changed from Solution proposée to Solution validée

#4 Updated by Frédéric Péters 5 days ago

  • Status changed from Solution validée to Résolu (à déployer)
commit e18a48522f0408656b3135d2b3921b1ce23ee171
Author: Frédéric Péters <fpeters@entrouvert.com>
Date:   Tue Sep 10 22:02:45 2019 +0200

    misc: ignore non-request objects in log filters (#35629)

#5 Updated by Benjamin Dauvergne 4 days ago

Bizarre que ce filtre soit actif sur un authentic-multitenant.

#6 Updated by Frédéric Péters 4 days ago

C'est ma config locale, elle peut ne pas tout à fait correspondre à ce qu'on a sur les serveurs. (mais la même erreur a été rencontrée via hobo sur les serveurs).

#7 Updated by Benjamin Dauvergne 4 days ago

Frédéric Péters a écrit :

C'est ma config locale, elle peut ne pas tout à fait correspondre à ce qu'on a sur les serveurs. (mais la même erreur a été rencontrée via hobo sur les serveurs).

Ça dans un sens c'est plus logique, après le patch est là depuis le 5 mars je ne vois pas ce qui a changé récemment pour que ça arrive.

#8 Updated by Benjamin Dauvergne 4 days ago

Benjamin Dauvergne a écrit :

Frédéric Péters a écrit :

C'est ma config locale, elle peut ne pas tout à fait correspondre à ce qu'on a sur les serveurs. (mais la même erreur a été rencontrée via hobo sur les serveurs).

Ça dans un sens c'est plus logique, après le patch est là depuis le 5 mars je ne vois pas ce qui a changé récemment pour que ça arrive.

Je vois que sur hobo c'est aussi sur du devinst par sur un vrai serveur.

#9 Updated by Frédéric Péters 4 days ago

Côté hobo c'est sur une installation serveur (dans le ticket rencontré à GL, rencontré aussi hier côté imio).

#10 Updated by Benjamin Dauvergne 4 days ago

Frédéric Péters a écrit :

Côté hobo c'est sur une installation serveur (dans le ticket rencontré à GL, rencontré aussi hier côté imio).

La trace que je vois sur #36017 c'est un runserver pas gunicorn ou uwsgi, on est d'accord ?

#11 Updated by Frédéric Péters 4 days ago

Oui, tout à fait, installation serveur, mais runserver temporairement exécuté sur cette base.

#12 Updated by Benjamin Dauvergne 4 days ago

Frédéric Péters a écrit :

Oui, tout à fait, installation serveur, mais runserver temporairement exécuté sur cette base.

Ok j'ai trouvé le basehttpserver de Django se trouve dépendre de SocketServer.TcpServer qui pose l'objet socket retourné par socket.accept() dans self.request, et donc il se trouve que les logs venant de basehttpserver ne sont pas compatibles avec l'usage de request dans extra par les autres logs de Django; ça veut juste dire qu'il faudrait un traitement particulier du logger django.server pour reproduire la config de base de Django au niveau formatage et filtre :

# django/utils/log.py
 29     'formatters': {
 30         'django.server': {
 31             '()': 'django.utils.log.ServerFormatter',
 32             'format': '[%(server_time)s] %(message)s',
 33         }
 34     },

On va se contenter de ta correction mais c'est bon de savoir d'où tout ça vient.

#13 Updated by Emmanuel Cazenave 4 days ago

Au passage, maintenant en local je fais des trucs comme ça :

import logging.config

LOGGING_CONFIG = None # pour dire à django ne fais rien sur la config de log, c'est moi qui la gère de A à Z

LOGGING = {
    # définir une config from scratch comme je veux
}
logging.config.dictConfig(LOGGING)

Ça a selon moi l'immense avantage de permettre d'avoir toute la config de log immédiatement sous les yeux, et donc de redevenir compréhensible au lieu d'être aiguille dans botte de foin.

#14 Updated by Benjamin Dauvergne 4 days ago

Emmanuel Cazenave a écrit :

Au passage, maintenant en local je fais des trucs comme ça :

[...]

Ça a selon moi l'immense avantage de permettre d'avoir toute la config de log immédiatement sous les yeux, et donc de redevenir compréhensible au lieu d'être aiguille dans botte de foin.

Ouaip mais ça n'empêche de devoir comprendre comment les softs utilisent logging, c'est dommage mais formateurs sont intimement liés par exemple au contenu des objets record (si tu as un formateur "%(host)s" mais que record.host n'existe pas ça va planter :/ au lieu d'afficher un contenu par défaut, ou "None" ou "-"); idem ici nos filtre supposent que record.request est tooujours un objet Request comme tout ce qui est loggé par défaut sur le logger django.request mais finalement ce n'est pas le cas pour le logger django.server.

#15 Updated by Frédéric Péters about 9 hours ago

  • Status changed from Résolu (à déployer) to Solution déployée

Also available in: Atom PDF