Projet

Général

Profil

Development #57604

suivi global exécution cron

Ajouté par Frédéric Péters il y a plus de 2 ans. Mis à jour il y a plus de 2 ans.

Statut:
Fermé
Priorité:
Normal
Assigné à:
Version cible:
-
Début:
05 octobre 2021
Echéance:
% réalisé:

0%

Temps estimé:
Patch proposed:
Oui
Planning:
Non

Description

Avoir un log global de l'exécution des crons, la motivation principale étant de comprendre/débugger des situations comme "il est mis 20 minutes mais ça s'est exécuté deux heures plus tard, genre #57145).

2021-05-10 15:07:00 starting cron (minutes offset is 23)  (<-- ord(settings.SECRET_KEY[-1])) % 60)
2021-05-10 15:07:02 [tenant XXX] start
2021-05-10 15:07:12 [tenant YYY] start
2021-05-10 15:09:52 [tenant YYY] long job: evaluate_jumps (took 2 minutes)

en anticipant déjà un peu je me dis aussi que ça serait utile d'avoir de l'info un peu plus profonde, genre :

2021-05-10 15:09:52 [tenant YYY] evaluate_jumps: running on "formdef/carddef + url_name" took 2 minutes

histoire de ne pas charger en lignes inutiles, inclure seulement les moments dont la durée dépasse un seuil (on peut commencer à 2 minutes et affiner après selon ce qu'on verra).


Fichiers

Révisions associées

Révision 75727642 (diff)
Ajouté par Lauréline Guérin il y a plus de 2 ans

misc: add log mecanism for cron jobs (#57604)

Révision b3c957c0 (diff)
Ajouté par Lauréline Guérin il y a plus de 2 ans

misc: more logs for some cron jobs (#57604)

Historique

#1

Mis à jour par Lauréline Guérin il y a plus de 2 ans

  • Assigné à mis à Lauréline Guérin
#3

Mis à jour par Lauréline Guérin il y a plus de 2 ans

proposition

comme il s'agit d'un log global, et non d'un log par tenant, j'ai opté pour un logger générique "wcs.cron", mais sans grande conviction

#4

Mis à jour par Frédéric Péters il y a plus de 2 ans

Perso j'ai toujours bien du mal avec logging et comment ça se configure mal (je trouve), on peut faire avec mais qu'il y ait en début d'exécution la configuration du logging pour de forcer taper quelque chose qui serait

            'class': 'logging.handlers.TimedRotatingFileHandler',
            'filename': '/var/lib/wcs/logs/cron.log',
            'when': 'w0',

pour rendre la configuration indépendante de ce qui pourrait arriver via une configuration de LOGGING ?

Ça me va alternativement de faire totalement sans logging, avec juste

+    def log(self, message):
+        self.logger.info('[tenant %s] %s', get_publisher().tenant.hostname, message)

transformé pour faire

with open(..., 'a+') as fd:
    fd.write('la date et le tenant et le message\n')
#5

Mis à jour par Benjamin Dauvergne il y a plus de 2 ans

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

Perso j'ai toujours bien du mal avec logging et comment ça se configure mal (je trouve), on peut faire avec mais qu'il y ait en début d'exécution la configuration du logging pour de forcer taper quelque chose qui serait

Juste un disclaimer : on a un TimedRotatingHandler maintenant pour les logs /var/log/brique/debug, je l'ai utilisé récemment pour débugger l'authentification OIDC sur l'instance intranet du GL (#57517), et ça marche très bizarrement avec uwsgi, la rotation du fichier est faite par un peu n'importe quel worker, donc on se retrouve avec un worker loggant vers debug et un autre vers debug.2021-10-11. Je déconseille vraiment, le plus sûr/simple ça reste de balancer ça sur stdout pour systemd (sans timestamp systemd/syslog l'ajouteront).

PS: et si /var/lib/wcs et sur un NFS c'est encore pire, le mode append ne marche pas avec NFS (et si besoin le soutien de SO https://stackoverflow.com/questions/41559260/djangouwsgi-logging-with-timedrotatingfilehandler-overwrites-rotated-log-file).

#6

Mis à jour par Frédéric Péters il y a plus de 2 ans

Juste un disclaimer (...)

(on est sur un cron qui s'exécute sur un seul nœud et pas via uwsgi).

#7

Mis à jour par Lauréline Guérin il y a plus de 2 ans

  • Statut changé de Solution proposée à En cours
#8

Mis à jour par Lauréline Guérin il y a plus de 2 ans

Solution alternative à base de fichiers.
La date dans le nom du ficher et pour chaque log est en UTC.

#9

Mis à jour par Frédéric Péters il y a plus de 2 ans

Ça m'irait qu'on utilise l'heure locale, ça sera plus simple à comparer avec ce qu'on voit dans l'ui.

                if 'job' in inspect.getfullargspec(job.function).args:

Je serais pour ajouter des **kwargs partout et ne pas ainsi avoir besoin d'utiliser inspect. (désolé ici je m'étais déjà fait cette remarque et j'avais oublié de l'écrire).

CRON_LOG_FILENAME = '/var/lib/wcs/cron.log'

Il faudrait ne pas mettre ça ainsi et se baser sur WcsPublisher.APP_DIR. (je me suis dit 2 minutes que l'erreur jenkins venait peut-être de là mais sans doute que non).

#11

Mis à jour par Lauréline Guérin il y a plus de 2 ans

je me suis dit 2 minutes que l'erreur jenkins venait peut-être de là

très probablement, mais je n'avais pas eu le temps de creuser encore :)

#12

Mis à jour par Frédéric Péters il y a plus de 2 ans

  • Statut changé de Solution proposée à Résolu (à déployer)

Validé poussé,

commit b3c957c071894c96fce700ec6c9cbab28f2139ea
Author: Lauréline Guérin <zebuline@entrouvert.com>
Date:   Mon Oct 11 17:59:15 2021 +0200

    misc: more logs for some cron jobs (#57604)

commit 75727642c1e37b7af1b20d2ff1873e8c84fc1097
Author: Lauréline Guérin <zebuline@entrouvert.com>
Date:   Mon Oct 11 15:15:57 2021 +0200

    misc: add log mecanism for cron jobs (#57604)
#13

Mis à jour par Frédéric Péters il y a plus de 2 ans

  • Statut changé de Résolu (à déployer) à Solution déployée

Formats disponibles : Atom PDF