Project

General

Profile

Development #29149

Revoir le fonctionnement des logs de debug

Added by Frédéric Péters over 1 year ago. Updated about 2 months ago.

Status:
Solution proposée
Priority:
Normal
Category:
-
Target version:
-
Start date:
17 Dec 2018
Due date:
% Done:

0%

Patch proposed:
Yes
Planning:
No

Description

Parce que ça s'adresse au développeur qui devrait lire ça sur son terminal, pas à un fichier de log qui va se remplir sans lecteur.

(peut-être à réaffecter à hobo pour modifier la configuration exposée dans le packaging)

PS: ancien nom "ne pas logguer de manière persistante le niveau "debug""

0001-set-syslog-handlers-to-level-INFO-29149.patch View (1.04 KB) Emmanuel Cazenave, 18 Dec 2018 10:36 AM

0001-matomo-adapt-translations-32940.patch View (3.56 KB) Benjamin Dauvergne, 16 May 2019 05:46 PM

0002-agent-adapt-to-authentic2-spring-cleaning-33120.patch View (1.86 KB) Benjamin Dauvergne, 16 May 2019 05:46 PM

0001-debian-add-debug-log-in-var-log-app-debug-29149.patch View (5.56 KB) Benjamin Dauvergne, 24 May 2019 11:07 AM

0002-debian-add-InternalIpMiddleware-29149.patch View (2.48 KB) Benjamin Dauvergne, 24 May 2019 11:07 AM

0001-debian-add-debug-log-in-var-log-app-debug-29149.patch View (6.29 KB) Benjamin Dauvergne, 19 Jun 2019 09:56 AM

0002-debian-add-InternalIpMiddleware-29149.patch View (2.48 KB) Benjamin Dauvergne, 19 Jun 2019 09:56 AM

0001-debian-add-debug-log-in-var-log-app-debug-29149.patch View (6.29 KB) Benjamin Dauvergne, 19 Sep 2019 06:08 PM

0002-debian-add-InternalIpMiddleware-29149.patch View (2.48 KB) Benjamin Dauvergne, 19 Sep 2019 06:08 PM

0001-debian-add-debug-log-in-var-log-app-debug-29149.patch View (6.29 KB) Benjamin Dauvergne, 13 Apr 2020 06:40 PM

0002-debian-add-InternalIpMiddleware-29149.patch View (3.24 KB) Benjamin Dauvergne, 13 Apr 2020 06:40 PM

0003-tests_multitenant-fix-non-deterministic-behaviour-29.patch View (1.02 KB) Benjamin Dauvergne, 13 Apr 2020 06:40 PM

0001-debian-add-fixup-to-test-29149.patch View (3.83 KB) Nicolas Roche, 18 Apr 2020 08:37 PM

0001-debian-add-debug-log-in-var-log-app-debug-29149.patch View (13.3 KB) Benjamin Dauvergne, 21 Apr 2020 12:27 AM

0002-debian-add-InternalIpMiddleware-29149.patch View (5.67 KB) Benjamin Dauvergne, 21 Apr 2020 12:27 AM


Related issues

Related to Publik - Autre #29234: variables non définies utilisées dans les templates django ? Solution déployée 20 Dec 2018
Related to Hobo - Development #29240: Avoir un écran pour gérer le paramétrage de debug Solution déployée 20 Dec 2018

History

#2 Updated by Emmanuel Cazenave over 1 year ago

Pas sur que ça suffise, compliqué à tester chez moi, mais à mon sens ça peut pas faire de mal.

#3 Updated by Emmanuel Cazenave over 1 year ago

J'ai été un peu vite, ça viendrait contrarier ce qui a été mis en place dans #7906.

#4 Updated by Benjamin Dauvergne over 1 year ago

On pourrait très bien remplacer tout ce que j'ai fait dans #7906 par le filtre django.utils.log.RequireDebugTrue sur un handler spécial "debug".

#5 Updated by Frédéric Péters over 1 year ago

  • Related to Autre #29234: variables non définies utilisées dans les templates django ? added

#6 Updated by Thomas Noël over 1 year ago

Juste pour clarifier ce qui est attendu, du moins par moi: actuellement quand on a DEBUG=True, on se retrouve avec les log de niveau debug, mais ça ne devrait pas être lié. DEBUG=True devrait rester uniquement dans son rôle d'afficher des traces à l'écran (et autres messages par ci par là), mais les log devraient rester en mode INFO par défaut. On aurait à trouver un autre settings (genre settings.LOG_LEVEL ?) pour permettre de forcer le niveau de log sur un tenant particulier, via son settings.json, pendant une phase de diagnostic.

#7 Updated by Benjamin Dauvergne over 1 year ago

Thomas Noël a écrit :

Juste pour clarifier ce qui est attendu, du moins par moi: actuellement quand on a DEBUG=True, on se retrouve avec les log de niveau debug, mais ça ne devrait pas être lié. DEBUG=True devrait rester uniquement dans son rôle d'afficher des traces à l'écran (et autres messages par ci par là), mais les log devraient rester en mode INFO par défaut. On aurait à trouver un autre settings (genre settings.LOG_LEVEL ?) pour permettre de forcer le niveau de log sur un tenant particulier, via son settings.json, pendant une phase de diagnostic.

Je pense qu'on peut tout faire avec un filtre comme dit plus haut, on peut imaginer un filtre DebugLog gérait par un setting DEBUG_LOG:
  • DEBUG_LOG=False : le filtre bloque tout ce qui est au niveau DEBUG ou moins
  • DEBUG_LOG=True : le filtre laisse passer tout ce qui est au niveau DEBUG ou moins
  • DEBUG_LOG="authentic2" : le filtre laisse passer tous ce qui est au niveau DEBUG ou moins pour les domaines "authentic2.*"
  • DEBUG_LOG="authentic2,django" : le filtre laisse passer tous ce qui est au niveau DEBUG ou moins pour les domaines "authentic2*" ou "django.*"

Pour reprendre des remarques récentes de Fred ça pourrait utilement être géré depuis hobo via un écran dédié.

#8 Updated by Benjamin Dauvergne over 1 year ago

Quand à DEBUG=True, je serai assez pour avoir un setting DEBUG_IP="<ip1> <ip2>", idem géré par hobo (je clique sur activate debug et ça ajoute mon ip cliente dans le truc), et avoir un middleware qui quand il voit l'IP pose DEBUG=True pour la durée de la requête.

Bon je vais faire des tickets au lieu de tout polluer.

Pour revenir au ticket, Emmanuel ce que tu modifies n'a pas d'effet sur le code de #7906, juste qu'il ne servira à rien si il n'y a plus aucun handler de niveau DEBUG, alors go si tu veux (mais les gens vous ne verrez plus les logs de debug pendant un moment).

#9 Updated by Benjamin Dauvergne over 1 year ago

  • Subject changed from ne pas logguer de manière persistante le niveau "debug" to Revois le fonctionnement des logs de debug
  • Description updated (diff)
  • Status changed from Solution proposée to En cours
  • Assignee set to Benjamin Dauvergne

#10 Updated by Benjamin Dauvergne over 1 year ago

  • Subject changed from Revois le fonctionnement des logs de debug to Revoir le fonctionnement des logs de debug
Nouveau plan :
  • effectivement remonter le niveau à INFO sur syslog,journal,etc...
  • supprimer toutes les bidouilles de loglevel, créer un OnlyDebug qui se base sur DEBUG_LOG
  • coté front hobo avoir une checkbox pour activer DEBUG_LOG
  • middleware pour avoir un DEBUG_IP
  • coté front hobo avoir un champ pour activer DEBUG_IP
  • pour chaque brique logger dans /var/log/brique/debug avec un TimedRotatingFileHandler utilisant le filtre OnlyDebug avec une rotation journalière sur 7 jours (je me dis que ça évitera de prévoir cela au niveau logrotate), ça pas super multiprocess proof mais si on perd une ligne de debug de temps en temps je ne pense pas que ce soit trop grave

#11 Updated by Benjamin Dauvergne over 1 year ago

Renommage de DEBUG_IP en INTERNAL_IPS ce qui nous donne le supporte de django-debug-toolbar au passage.

#12 Updated by Benjamin Dauvergne about 1 year ago

  • Related to Development #29240: Avoir un écran pour gérer le paramétrage de debug added

#13 Updated by Benjamin Dauvergne about 1 year ago

Première implémentation.

Reste à faire des tests pour InternalIPMiddleware.

Cela va de de paire avec les écrans de #29240, le cas DEBUG_LOG='app1,app2' n'est pas gérable via ces écrans.

#14 Updated by Benjamin Dauvergne about 1 year ago

Mauvais commits dans mon dernier commentaire. Branche basé sur #29240.

0001: les logs de debug ne partent plus vers syslog/journald mais vers /var/log/<app>/debug, c'est activé via DEBUG_LOG = True ou DEBUG_LOG=app1,app2
0002: INTERNAL_IPS = (ip1, ip2), active DEBUG = True pour les IPs indiquées

#16 Updated by Benjamin Dauvergne 10 months ago

Rebasé suite au push de #29240, j'ai juste un doute sur InternalIPMiddleware, j'ai un peu peur que DEBUG reste à True en cas d'exception; je ne vois pas vraiment comment faire mieux sans les middleware moderne de Django 1.11 basés sur une fonction recevant un get_response() en paramètre.

#17 Updated by Benjamin Dauvergne 10 months ago

Benjamin Dauvergne a écrit :

Rebasé suite au push de #29240, j'ai juste un doute sur InternalIPMiddleware, j'ai un peu peur que DEBUG reste à True en cas d'exception; je ne vois pas vraiment comment faire mieux sans les middleware moderne de Django 1.11 basés sur une fonction recevant un get_response() en paramètre.

Non en fait ça devrait aller process_response() est toujours appelé.

#18 Updated by Nicolas Roche 3 months ago

Désolé de demander ça, mais à l'occasion, est-ce que tu pourrais rebaser (pour me donner une chance de relire) ?

#19 Updated by Benjamin Dauvergne 3 months ago

Ok, le dernier patch c'est parce que chez moi un test que tu as ajouté récemment ne passe pas, étonnament ça semble marcher un peu tout le temps sur jenkins je dois avoir un postgres facétieux.

#20 Updated by Nicolas Roche 3 months ago

Chouette, des logs !
Deux petites remarques :
  • Déplacer la déclaration du middleware dans debian/config_degian_common.py après que TenantMiddleware soit inclus afin que les variables issues d'_hobo.json_ soient disponibles dans le middleware.
  • Faire hériter DebugLogFilter de RequestContextFilter afin le filtre 'debug_log' renseigne les informations affichées par le formatter 'debug'.

Voici un patch qui donne ces modifications si d'autres veulent tester.

#22 Updated by Benjamin Dauvergne 3 months ago

Je n'ai pas traité cet aspect du problème :

Parce que ça s'adresse au développeur qui devrait lire ça sur son terminal, pas à un fichier de log qui va se remplir sans lecteur.

#23 Updated by Frédéric Péters 3 months ago

Entre le titre du ticket qui a changé et 80% de se description du ticket qui n'est pas traitée, on pourrait s'interroger sur le rapport entre le travail fait ici et la situation initiale.

Pour reprendre, donc, la situation initiale c'est DEBUG=True posé sur la recette, qui amenait à avoir des logs chargés de mille choses, et plus d'espace disque. Et je posais comme idée que les logs de debug étaient juste utiles sur le moment, qu'ils pouvaient défiler sur un terminal, suivis à un moment précis (et pas réunis par milliers dans des fichiers).

La partie de pas logguer en debug, elle doit être arrivée dans #29240, ok.

Et ce ticket gère l'autre côté, avoir un endroit qui puisse être consulté sur le moment (tail -f /var/log/authentic2/debug).

Ni du patch ni du commentaire de Nicolas je n'arrive à dire si ce fichier de log contiendra tous les niveaux, ou uniquement le niveau debug, et je dirais qu'avoir tous les niveaux pourraient être utiles, les niveaux supérieux pouvant quand même aider à suivre, mais peu importe.

#24 Updated by Benjamin Dauvergne 3 months ago

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

Pour reprendre, donc, la situation initiale c'est DEBUG=True posé sur la recette, qui amenait à avoir des logs chargés de mille choses, et plus d'espace disque. Et je posais comme idée que les logs de debug étaient juste utiles sur le moment, qu'ils pouvaient défiler sur un terminal, suivis à un moment précis (et pas réunis par milliers dans des fichiers).

Oui c'est exactement ce qui est fait ici.

La partie de pas logguer en debug, elle doit être arrivée dans #29240, ok.

#29240 c'est pour contrôler les settings DEBUG_LOG et INTERNAL_IPS depuis le BO d'hobo.

Et ce ticket gère l'autre côté, avoir un endroit qui puisse être consulté sur le moment (tail -f /var/log/authentic2/debug).

Oui ça c'est fait mais il y aussi le fait d'activer DEBUG à la volée en fonction de INTERNAL_IPS, c'était l'autre aspect.

Ni du patch ni du commentaire de Nicolas je n'arrive à dire si ce fichier de log contiendra tous les niveaux, ou uniquement le niveau debug, et je dirais qu'avoir tous les niveaux pourraient être utiles, les niveaux supérieux pouvant quand même aider à suivre, mais peu importe.

Oui c'est exactement ce qui est fait ici, c'est un log classique on a tout à partir de DEBUG.

#25 Updated by Benjamin Dauvergne 3 months ago

  • quand request.META['REMOTE_ADDR'] est dans settings.INTERNAL_IPS, alors settings.DEBUG est mis à True activant ainsi les traces HTML,
  • quand on a bool(settings.DEBUG) est vrai on log dans /var/log/brique/debug.log au niveau DEBUG et supérieur,
  • on a un jour d'archive vers /var/log/brique/debug.log.1 et rien de plus,
  • le fichier est parsable (à coup de caractère ASCII \x1f et d'espaces après les sauts de ligne), et via hobo.logger.DebugLog.lines() il est possible d'afficher les lignes de log dans une vue, mais ce travail n'est pas fait ici, je fournis juste l'outil.

Et oui on peut faire tail -f /var/log/brique/debug.log.

#26 Updated by Frédéric Péters 2 months ago

Oui c'est exactement ce qui est fait ici.

Oui mon commentaire était pour pointer que malgré la distance qui pouvait être sentie entre la réalisation et le ticket initial, ça correspondait bien.

#27 Updated by Nicolas Roche 2 months ago

Je corrige une typo dans les explications données en https://dev.entrouvert.org/issues/29149#note-25 :
  • quand on a bool(settings.*DEBUG_LOG*) est vrai on log dans /var/log/brique/debug.log au niveau DEBUG et supérieur,
    (d'après les commentaires par exemple : '''Filter debug log records based on the DEBUG_LOG setting''')

Et j'en profite pour indiquer à nouveau que les deux mécanismes (traces HTML et logs dans fichier debug) sont à présent décorélés.

#28 Updated by Benjamin Dauvergne 2 months ago

Nicolas Roche a écrit :

Et j'en profite pour indiquer à nouveau que les deux mécanismes (traces HTML et logs dans fichier debug) sont à présent décorélés.

Oui, c'était un des objectifs effectivement.

#29 Updated by Nicolas Roche 2 months ago

Le middleware 'InternalIPMiddleware' ne fonctionne toujours pas chez moi.
Cf https://dev.entrouvert.org/issues/29149#note-20, si je le déplace à côté de 'RobotsTxtMiddleware' ça fonctionne.

"user", qui apparaît dans les logs de niveau DEBUG, n'apparaît pas dans les log de niveau supérieur (INFO, ERROR).
Dans ces niveaux, RequestContextFilter est exécuté 2 fois, avec à la seconde fois la variable user "délazifiée".

L'ajout du parseur DebugLog dans le premier patch, et le 3ème patch de la branche, c'est bien pour le point 4 ?
https://dev.entrouvert.org/issues/29149#note-25

#30 Updated by Benjamin Dauvergne 2 months ago

Nicolas Roche a écrit :

Le middleware 'InternalIPMiddleware' ne fonctionne toujours pas chez moi.
Cf https://dev.entrouvert.org/issues/29149#note-20, si je le déplace à côté de 'RobotsTxtMiddleware' ça fonctionne.

J'avais oublié, c'est fait, branche à jour.

"user", qui apparaît dans les logs de niveau DEBUG, n'apparaît pas dans les log de niveau supérieur (INFO, ERROR).
Dans ces niveaux, RequestContextFilter est exécuté 2 fois, avec à la seconde fois la variable user "délazifiée".

J'ai sorti le filtre request_context des handlers pour le mettre au niveau du logger racine, il ne devrait s'exécuter qu'une fois désormais (mais ça rend un peu la configuration des handlers dépendant du logger) :

diff --git debian/debian_config_common.py debian/debian_config_common.py
index 553a1b6..6f0dcae 100644
--- debian/debian_config_common.py
+++ debian/debian_config_common.py
@@ -90,7 +90,6 @@ LOGGING = {
             'address': '/dev/log',
             'class': 'logging.handlers.SysLogHandler',
             'formatter': 'syslog',
-            'filters': ['request_context'],
         },
         'syslog_no_filter': {
             'level': 'INFO',
@@ -111,7 +110,7 @@ LOGGING = {
             'when': 'midnight',
             'backupCount': 1,
             'interval': 1,
-            'filters': ['request_context', 'debug_log'],
+            'filters': ['debug_log'],
         }
     },
     'loggers': {
@@ -169,6 +168,7 @@ LOGGING = {
         },
         '': {
             'level': 'DEBUG',
+            'filters': ['request_context'],
             'handlers': ['syslog', 'mail_admins', 'debug'],
         },
     },

L'ajout du parseur DebugLog dans le premier patch, et le 3ème patch de la branche, c'est bien pour le point 4 ?
https://dev.entrouvert.org/issues/29149#note-25

Dans le patch 0001 c'est surtout pour pouvoir faire des tests qui justifient mon format de log ; le 0003 c'est un goodies si on voulait afficher tout ça quelque part; ça peut ne pas être commité pour le faire correctement plus tard.

Je viens de rajouter un commit pour déprécier SettingsLogLevel, tant qu'à faire retirons du code.

#31 Updated by Benjamin Dauvergne 2 months ago

Encore un nouveau commit pour prévenir plusieurs exécutions de RequestContextFilter, et je l'ai remis dans la configuration des handlers parce qu'à cause de leur chaîne de formatage ils en sont fortement dépendant.

#32 Updated by Nicolas Roche about 2 months ago

Je n'ai pas réussi à exploiter la vue DebugLogView dans les briques, parce que settings.INTERNAL_IPS ne renvoit rien,
mais sinon j'ai relu.

#33 Updated by Benjamin Dauvergne about 2 months ago

Nicolas Roche a écrit :

Je n'ai pas réussi à exploiter la vue DebugLogView dans les briques, parce que settings.INTERNAL_IPS ne renvoit rien,
mais sinon j'ai relu.

Je vais virer DebugLogView et en faire un ticket à part; mais settings.INTERNAL_IPS qui ne renvoie rien, que veux-tu dire par là ?

PS: DebugLogView retiré sur la branche.

#34 Updated by Nicolas Roche about 2 months ago

Je n'ai pas réussi à exploiter la vue DebugLogView dans les briques

Suite à un second essai, je constate qu'en fait ça fonctionne très bien.
Pour info, j'ai copié le template donné en exemple dans combo/public/templates/debug_log.html et j'ai modifié combo/urls.py :

from hobo.logger import DebugLogView
...
urlpatterns = [
    ...
    url(r'^log/$', DebugLogView.as_view(template_name='debug_log.html', paginate=10)),
]

Also available in: Atom PDF