Project

General

Profile

Development #31774

ajouter au log d'un appel à un endpoint la réponse produite

Added by Frédéric Péters 11 months ago. Updated 10 days ago.

Status:
En cours
Priority:
Normal
Assignee:
Target version:
-
Start date:
27 Mar 2019
Due date:
% Done:

0%

Patch proposed:
Yes
Planning:
No

Description

Besoin noté dans #31740, il me semble qu'on pourrait modifier les méthodes de ProxyLogger pour retourner l'objet ResourceLog créé, l'attacher à la requête, et en fin de parcours ajouter dans son .extra le contenu de la réponse.

0001-logging-append-connector-response-to-ressource-log-3.patch View (7.01 KB) Nicolas Roche, 13 Nov 2019 06:34 PM

0001-logging-append-connector-response-to-ressource-log-3.patch View (7.51 KB) Nicolas Roche, 15 Nov 2019 11:26 AM

0001-trivial-correct-a-typographical-error-31774.patch View (1.34 KB) Nicolas Roche, 18 Feb 2020 06:38 PM

0002-logging-append-connector-response-to-ressource-log-3.patch View (13.3 KB) Nicolas Roche, 18 Feb 2020 06:38 PM

History

#1 Updated by Nicolas Roche 4 months ago

  • Assignee set to Nicolas Roche

#2 Updated by Nicolas Roche 4 months ago

J'ai rencontré des difficultés sur l'enregistrement des réponses en base en rejouant les tests.
En l'état, quand ça ne passe pas je ne logue rien.
  • sur test_family.py
    je peux contourner avec un .decode('utf-8', errors='ignore').encode()
      UnicodeDecodeError: 'utf8' codec can't decode byte 0x93
    
  • sur test_opengis.py
    il s'agit d'une image ; même erreur plus une autre que je n'arrive pas à contourner.

Aussi, j'ai fait apparaître dans le nom de la clé du dictionnaire le fait que la réponse provient du cache et non pas de l'application métier : encore un choix discutable.

#3 Updated by Benjamin Dauvergne 4 months ago

Nicolas Roche a écrit :

J'ai rencontré des difficultés sur l'enregistrement des réponses en base en rejouant les tests.
En l'état, quand ça ne passe pas je ne logue rien.
  • sur test_family.py
    je peux contourner avec un .decode('utf-8', errors='ignore').encode()

force_text(..., errors='ignore') lors du log.

[...]
  • sur test_opengis.py
    il s'agit d'une image ; même erreur plus une autre que je n'arrive pas à contourner.

Même avec errors='ignore' ? Dans ce cas fallback sur un chaîne explicative de l'absence des données : '<binary>' ou alors encore une partie en base64 si on juge que ça peut être utile d'avoir un extrait d'un document (m'enfin ça va bien charger les logs).

Aussi, j'ai fait apparaître dans le nom de la clé du dictionnaire le fait que la réponse provient du cache et non pas de l'application métier : encore un choix discutable.

Mouais toujours dans 'response' plutôt que connector_response mais tu peux mettre à coté un 'from_cache': True.

#4 Updated by Nicolas Roche 4 months ago

ou alors encore une partie en base64 si on juge que ça peut être utile

Je pensais qu'on pourrait toujours récupérer cette info via les logs simples (def log_http_request),
mais j'avoue que je n'arrive pas à le mettre en évidence.
(du coup je veux bien une piste pour m'orienter dans ce ticket, svp)

#5 Updated by Benjamin Dauvergne 4 months ago

Nicolas Roche a écrit :

ou alors encore une partie en base64 si on juge que ça peut être utile

Je pensais qu'on pourrait toujours récupérer cette info via les logs simples (def log_http_request),
mais j'avoue que je n'arrive pas à le mettre en évidence.

Désolé je ne comprends pas ta réponse.

#6 Updated by Nicolas Roche 4 months ago

C'est que ce n'est pas clair pour moi non plus (d'ailleurs c'est l'occasion pour moi de voir si j'ai bien compris).
passerelle/utils/_init__.py_:

def log_http_request(logger, ...):    if response is not None:
...
        if logger.level == 10:  # DEBUG
...
                content = response.content[:max_size]
                extra['response_content'] = repr(content)

Je pense que ce code fait déjà ce que demande ce ticket, mais dans les logs "standards" (ie: /var/log/...).
Si vraiment on veux chercher du binaire dans les logs, on peut envisager de ne pas le faire via l'IHM (ie: l'objet de ce ticket)

#7 Updated by Benjamin Dauvergne 4 months ago

Nicolas Roche a écrit :

C'est que ce n'est pas clair pour moi non plus (d'ailleurs c'est l'occasion pour moi de voir si j'ai bien compris).
passerelle/utils/_init__.py_:
[...]
Je pense que ce code fait déjà ce que demande ce ticket, mais dans les logs "standards" (ie: /var/log/...).
Si vraiment on veux chercher du binaire dans les logs, on peut envisager de ne pas le faire via l'IHM (ie: l'objet de ce ticket)

Ok, je pense qu'il faut coordonner tout le monde et décider si on veut les mêmes informations dans les logs structuré et dans les logs de resource (je pense d'ailleurs que tout le bordel dans ProxyLogger est inutile on aurait pu s'en sortir avec un handler et un LogWrapper qui met juste la resource dans 'extra', mais soit..).

#8 Updated by Nicolas Roche 3 months ago

coordonner tout le monde

Vu ensemble ce lundi, '<binary>' ça passe.

#9 Updated by Valentin Deniaud 11 days ago

  • Status changed from Solution proposée to En cours
Quelque chose bloque ce ticket ? Sinon c'est bon pour moi modulo :
  • import UnicodeDecodeError inutile
  • « troncate » dans un commentaire au lieu de « truncate »
  • dans le test, ajouter une petite ligne pas méchante genre '6.172122' in log.extra['response'] pour vérifier qu'on logge bien quelque chose d'intelligible
  • je ne comprends pas le try/except, qu'est-ce qui lie un DataError du fait que les données soient binaires ? Si rien, l'enlever, si quelque chose, faire un test.
  • dans log_http_request qui logge déjà les réponses du logiciel métier, la clé dans extra s'appelle response_content, pourquoi pas suivre cela
  • je ne suis pas fan de définir une fonction locale vs une nouvelle méthode, parce que perform() est déjà beaucoup trop longue, mais peut-être que c'est que moi
  • en tant que non expert en encodage je ne trouve pas ça clair de passer value dans str puis dans force_text, je serai plus rassuré si on utilisait que force_text
  • et vérifier que les tests passent en python3.

#10 Updated by Nicolas Roche 10 days ago

Remarques prises en compte dans le patch.

dans le test, ajouter une petite ligne pas méchante genre '6.172122' in log.extra['response'] pour vérifier qu'on logge bien quelque chose d'intelligible

ici je logue la réponse ('6.172122' fait parti des paramètres de la requête)

assert eval(log.extra['response'])['data']['text'] == 'HAUSSONVILLE / BLANDAN / MON DESERT / SAURUPT'

je ne comprends pas le try/except, qu'est-ce qui lie un DataError du fait que les données soient binaires ? Si rien, l'enlever, si quelque chose, faire un test.

cf https://dev.entrouvert.org/issues/31774#note-2
sur test_family.py et test_opengis.py, l'enregistrement d'une image plante en base de donnée.

dans log_http_request qui logge déjà les réponses du logiciel métier, la clé dans extra s'appelle response_content, pourquoi pas suivre cela

fait, j'ai aussi ajouté le statut et les en-têtes.

en tant que non expert en encodage je ne trouve pas ça clair de passer value dans str puis dans force_text, je serai plus rassuré si on utilisait que force_text

il s'agit de l'appel à "__str__" sur l'objet HttpResponse ou sur un dictionnaire si la requête est en cache.

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

En fait, une fois qu'on a #38157 (la possibilité d'afficher tous les logs liés à une requête), il n'y a plus vraiment d'intérêt à ce ticket, je pense.

#12 Updated by Valentin Deniaud 10 days ago

  • Status changed from Solution proposée to En cours

Je trouve quand même ça sympa d'avoir des logs les plus complets possibles.
En plus j'aime bien la tête qu'a le patch maintenant, reste que si en raison du loglevel l'objet ResourceLog n'est pas créé, on va se retrouver à faire resource_log.log_response avec resource_log qui est à None et ça va planter.

#13 Updated by Frédéric Péters 10 days ago

Je trouve quand même ça sympa d'avoir des logs les plus complets possibles.

Oui mais tout ne doit pas(plus) nécessairement être dans le même objet, si on a une ligne de log avec la réponse, avec le même transaction_id, on peut y aller, on a tout, sans duplication ici, sans ce truc quand même bizarre de revenir après coup sur une ligne de log.

Et à nouveau je partais de l'idée qu'on avait déjà ce log de la réponse, si ce n'est pas/plus le cas (peut-être parce qu'on retire le logging de to_json, peut-être pour autre chose), je suis bien sûr pour logguer la réponse.

#14 Updated by Valentin Deniaud 10 days ago

Ce qu'on logge ici n'est jamais loggé nulle part, il s'agit du json que renvoie un endpoint, sinon ce qu'on logge déjà c'est la réponse du logiciel métier. Le logging dans to_json logge aussi à ce niveau là, mais que en cas d'erreur, donc jamais la réponse.

sans ce truc quand même bizarre de revenir après coup sur une ligne de log

C'est vrai qu'on aurait pu choisir d'en ajouter une, c'est fonction de ce qui paraît le plus clair dans l'interface.

#15 Updated by Frédéric Péters 10 days ago

Je suis plutôt pour ajouter une ligne, pour ne pas avoir à modifier toutes les méthodes de log pour retourner l'objet, et pour offrir une chronologie lisible des moments de l'appel.

Also available in: Atom PDF