Produits Entr'ouvert » Passerelle

À un moment il y a ça qui apparait (8f8c54f70bfa3aa8e311514297f1eeded2c32593, ticket django 25099)

        # Since we add a nicely formatted traceback on our own, create a copy
        # of the log record without the exception data.
        no_exc_record = copy(record)
        no_exc_record.exc_info = None
        no_exc_record.exc_text = None

et ça pourrait venir de là mais d'une manière ou d'une autre sur le SaaS de dev il y a de toute façon des tracebacks dans les emails d'erreurs (j'y ai fait des modifs locales dans passerelle pour tester); je ne pige absolument pas comment tout tourne et je ne vais pas planter la recette pour creuser ça.

Je ne trouve pas le commit 8f8c54f70bfa3aa8e311514297f1eeded2c32593; c'est bien un commit du dépôt hobo ? Ok dépôt Django.

Non, je fais référence au commit django correspondant au numéro de ticket django cité.

Mystère sur pourquoi ça marchait en 1.11, peut-être un signal quelque part, je n'ai pas d'anciennes traces pour pousser l'investigation (est-ce que d'autres traces que celles de clicrdv avaient une traceback ?).

Oui, par exemple :

Date: Wed, 17 Mar 2021 09:01:32 +0100
From: admin+passerelle.node1.prod.saas.entrouvert.org@entrouvert.org
Subject: [passerelle.icitoyen.fr] ERROR (EXTERNAL IP): Error occurred while processing request
To: admin+passerelle.prod@entrouvert.com

Error occurred while processing request

APIError at /api-particulier/api_particulier/situation-familiale/
API-particulier platform "prod" returned a non 200 status 500: {'error': 'internal_server_error', 'reason': 'Erreur serveur', 'message': 'Erreur serveur'}

Request Method: GET
Request URL:
https://passerelle.icitoyen.fr/api-particulier/api_particulier/situation-familiale/?code_postal=42300&numero_allocataire=None&orig=demarches.icitoyen.fr&algo=sha256&timestamp=2021-03-17T08%3A01%3A31Z&nonce=4567c09f1d69916dc4349f7756fff475&signature=ILz2jA06ZK7dIz1
tBbU6aYxIa4fUYCV6xOLVtuFzGCM%3D
Django Version: 1.11.29
Python Executable: /usr/bin/uwsgi-core
Python Version: 3.7.3
Python Path: ['.', '', '/usr/lib/python37.zip', '/usr/lib/python3.7', '/usr/lib/python3.7/lib-dynload', '/usr/local/lib/python3.7/dist-packages', '/usr/lib/python3/dist-packages']
Server time: mer, 17 Mar 2021 09:01:32 +0100
Installed Applications:
''
Installed Middleware:
''

Traceback:

File "/usr/lib/python3/dist-packages/passerelle/utils/jsonresponse.py" in api
  131.             resp = f(*args, **kwargs)

File "/usr/lib/python3/dist-packages/passerelle/views.py" in perform
  511.         result = self.endpoint(request, **params)

File "/usr/lib/python3/dist-packages/passerelle/apps/api_particulier/models.py" in v2_situation_familiale
  285.             user=user,

File "/usr/lib/python3/dist-packages/passerelle/apps/api_particulier/models.py" in get
  124.                     'content': data,

Exception Type: APIError at /api-particulier/api_particulier/situation-familiale/
Exception Value: API-particulier platform "prod" returned a non 200 status 500: {'error': 'internal_server_error', 'reason': 'Erreur serveur', 'message': 'Erreur serveur'}

Ou encore, (mais celle-ci est avant le système d'endpoint),

Date: Wed, 07 Apr 2021 14:38:05 +0200
From: admin+montoulouse-prod@entrouvert.com
Subject: [prod montoulouse.fr passerelle][passerelle.eservices.toulouse-metropole.fr] ERROR (EXTERNAL IP): Internal Server Error:
        /toulouse-axel/axel-famille/clae_children_activities_info
To: admin+prod.montoulouse.combo@entrouvert.com

Internal Server Error: /toulouse-axel/axel-famille/clae_children_activities_info

OperationalError at /toulouse-axel/axel-famille/clae_children_activities_info
FATAL:  les emplacements de connexions restants sont réservés pour les connexions
superutilisateur non relatif à la réplication

Request Method: GET
Request URL:
https://passerelle.eservices.toulouse-metropole.fr/toulouse-axel/axel-famille/clae_children_activities_info?booking_date=2021-04-07&NameID=8d9cbb97bf074e45a8499d5f80e0220e&orig=demarches-montoulouse.eservices.toulouse-metropole.fr&algo=sha256&timestamp=2021-04-07T12%3A38%3A05Z&nonce=eee15e994d8840415f3a0617dcf42687&
signature=aJkLmPDug%2BQyEtRAnXLrbRCoV//yqXm87e2hML55hJY%3D
Django Version: 1.11.29
Python Executable: /usr/bin/uwsgi-core
Python Version: 3.7.3
Python Path: ['.', '', '/usr/lib/python37.zip', '/usr/lib/python3.7', '/usr/lib/python3.7/lib-dynload', '/usr/local/lib/python3.7/dist-packages', '/usr/lib/python3/dist-packages']
Server time: mer, 7 Avr 2021 14:38:05 +0200
Installed Applications:
''
Installed Middleware:
''

Traceback:

File "/usr/lib/python3/dist-packages/django/db/backends/base/base.py" in ensure_connection
  213.                 self.connect()

File "/usr/lib/python3/dist-packages/django/db/backends/base/base.py" in connect
  189.         self.connection = self.get_new_connection(conn_params)

File "/usr/lib/python3/dist-packages/django/db/backends/postgresql/base.py" in get_new_connection
  176.         connection = Database.connect(**conn_params)

File "/usr/lib/python3/dist-packages/psycopg2/__init__.py" in connect
  130.     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)

      The above exception (FATAL:  les emplacements de connexions restants sont réservés pour les connexions
superutilisateur non relatif à la réplication
) was the direct cause of the following exception:

File "/usr/lib/python3/dist-packages/django/core/handlers/exception.py" in inner
  41.             response = get_response(request)

File "/usr/lib/python3/dist-packages/django/core/handlers/base.py" in _get_response
  187.                 response = self.process_exception_by_middleware(e, request)
...

Valentin Deniaud a écrit :

Je pense que sur passerelle on a toujours bien actuellement les traces normales, j'ose pas torturer la recette pour confirmer.

La réponse est oui, j'ai bien la trace complète de #55667 dans mes mails.

Je ne sais pas pour le reste mais pour la trace ClicRdv ça vient d'une interaction entre une utilisation direct de jsonresponse qui produit une 500 en cas d'erreur et le fait que django 2.2 en tout cas log toutes les requêtes 500 en faisant passé le message de log pour une exception (mais donc sans trace) :

# là on voit que to_json renvoie 500 par défaut
class to_json(object):
    def __init__(self, error_code=500, logger=None, **kwargs):
.....
            else:
                logger.warning("Error occurred while processing request", extra=extras) <- pas de log visible, c'est une exception lambda qui pose souci pas une APIError
.....
            data = self.err_to_response(e)
            if getattr(e, 'err_code', None):
                data['err'] = e.err_code
            if getattr(e, 'http_status', None):
                status = e.http_status
            elif isinstance(e, (ObjectDoesNotExist, Http404)):
                status = 404
            elif isinstance(e, PermissionDenied):
                status = 403
            else:
                status = self.error_code <-- ici

et coté Django :

# log_response est appelé sur chaque réponse retournée
def log_response(message, *args, response=None, request=None, logger=request_logger, level=None, exc_info=None):
    """ 
    Log errors based on HttpResponse status.

    Log 5xx responses as errors and 4xx responses as warnings (unless a level
    is given as a keyword argument). The HttpResponse status_code and the
    request are passed to the logger's extra parameter.
    """ 
    # Check if the response has already been logged. Multiple requests to log
    # the same response can be received in some cases, e.g., when the
    # response is the result of an exception and is logged at the time the
    # exception is caught so that the exc_info can be recorded.
    if getattr(response, '_has_been_logged', False):
        return

    if level is None:
        if response.status_code >= 500:
            level = 'error' <-- ici ça passe le niveau du log en erreur
        elif response.status_code >= 400:
            level = 'warning'
        else:
            level = 'info'

    getattr(logger, level)(
        message, *args,
        extra={
            'status_code': response.status_code,
            'request': request,
        },
        exc_info=exc_info,
    )

et dans AdminEmailHandler on a ce bout de code qui va prendre record.getMessage() et faire passer ça pour une exception_value :

        # Since we add a nicely formatted traceback on our own, create a copy
        # of the log record without the exception data.
        no_exc_record = copy(record)
        no_exc_record.exc_info = None
        no_exc_record.exc_text = None

        if record.exc_info:
            exc_info = record.exc_info
        else:
            exc_info = (None, record.getMessage(), None)

C'est comme ça qu'on se retrouve avec un Internal Server Error: <request.path> mais sans trace. Pour moi on mélange deux choses, le passage à 2.2 et certainement deux types d'erreur différentes, la première est une exception qui est remonté jusqu'à Django (aussi je ne sais pas trop comment on obtient un "Failed to retrieve theme" dans une vue qui renvoie du JSON) pas la deuxième, c'est une 500 interne.

Je ne sais pas trop comment on retourne une 500 sans que Django ne log en erreur alors qu'on ne veut visiblement pas (ou en tout cas si on le souhaite c'est dans jsonresponse qu'il faut traiter ça); on peut poser '__already_logged__' sur HttpResponse mais ça supprime tout le log "HTTP" sur le logger "django.request" (qu'on fait déjà 2 fois dans nginx et uwsgi...).

Après réflexion je pense qu'il faut juste ajouter au logger.warning par défaut de to_json un django.utils.log.log_response, ça posera already_logged et on pourra passer sys.exc_info() et récupérer le comportement par défaut de Django tout en retournant une erreur formatée en JSON (et ça ne le fera que sur une 500, i.e. pas une exception d'un type géré comme APIError qui retournent une 400).

Benjamin Dauvergne a écrit :

Après réflexion je pense qu'il faut juste ajouter au logger.warning par défaut de to_json un django.utils.log.log_response, ça posera already_logged et on pourra passer sys.exc_info() et récupérer le comportement par défaut de Django tout en retournant une erreur formatée en JSON (et ça ne le fera que sur une 500, i.e. pas une exception d'un type géré comme APIError qui retournent une 400).

En fait on log déjà bien ce qu'il faut quand il faut via le if ..getattr(e, 'log_error', True):... on est juste pollué par des mails d'erreur inutiles par Django parce qu'on le laisse décider du niveau de log.

PS: mais si quelqu'un peut sortir un mail d'erreur dont il est sûr qu'elle correspond bien à quelque chose qui aurait du contenir un traceback, je le veux bien ici; en attendant #56139.