[DEPRECATED] Gestion des logs
Résumé
Mise en place d'une première version des logs pour les moteurs Go à l'aide de la bibliothèque zerolog.
Issue: #53 (moved)
Related merge requests : https://git.canopsis.net/cat/go-engines/merge_requests/18
Processus de tests
-
S'assurer que les dépendances sont à jour (supprimer le répertoire
vendor
etglide.lock
puis lancermake init
peut aider). -
Lancer les moteurs Go avec les options que vous utilisez habituellement plus ces deux options :
-
-d
pour le niveau de log. Si-d
est présent, alors les logs à partir du niveau debug seront affichés, sinon ce sera qu'à partir du niveau info. -
-log
(nom provisoire ?) pour la sortie de log.journal
,journald
oujournalctl
va pousser les logs versjournald
,stderr
va pousser les logs versstderr
etstdout
va pousser les logs versstdout
. Par défaut, si le paramètre donné n'est pas reconnu ou s'il n'y a pas de paramètre, les logs seront poussés surstdout
.
-
-
Vérifier que les moteurs fonctionnent bien. Les logs ne doivent pas impacter le workflow des moteurs (la question d'un benchmark sur performances se posera sans doute un peu plus tard).
-
Vérifier l'affichage des logs.
stdout
etstderr
devraient s'afficher dans la console soit directement, soit avecdocker(-compose) logs
si le moteur Go fonctionne dans un container Docker. Pour ce qui est dejournald
,journalctl -f
n'affiche que le message, maisjournalctl --output=json-pretty -f
devrait afficher la totalité du contexte.
Zerolog
Pour une première approche de la gestion des logs (cf l'issue #53 (moved)), je me suis basé sur la bibliothèque zerolog. Voici le contenu de cette MR.
zerologger.go
Le fichier zerologger.go
va créer par défaut un Logger
(quand on importe un package, la fonction init()
est appelé automatiquement).
Ensuite, au démarrage du moteur, la fontion InitLogger
est appelé pour configurer ce Logger
. Les deux options disponibles sont :
- l'
output
, une chaîne de caractères qui indique vers quelle sortie pousser les logs, - et le
debug
, un booléen qui indique le niveau de logs.
output
peut valoir journald
, stderr
et stdout
et les logs seront redirigés respectivement vers journald
, stderr
et stdout
. Par défaut, la sortie du Logger
est stdout
.
Si debug
, qui existait auparavant pour la fonction DebugPrint
, est mis à true
alors tous les logs du niveau debug
ou plus seront poussés. Sinon, seuls les logs à part du niveau info
seront poussés.
Logger
Principes et utilisation du Pour utiliser le Logger
dans le moteur, il faut importer la bibliothèque puis appeler InitLogger
.
import (
zl "git.canopsis.net/canopsis/go-revolution/lib/canopsis/zerologger"
)
func main() {
zl.InitLogger("", false)
zl.Info().Msg("Hello, world!")
}
On peut voir que l'envoi du message de log se fait en deux appels. D'abord, zl.Info()
va créer un Event
et cet évènement sera ensuite poussé avec un message Msg("Hello, world!")
.
La logique de zerolog
est de créer un évènement puis de l'envoyer avec un message. Un événèment possède un niveau et les différentes fonctions renvoient un Event
. zl.Debug()
renvoie un Event
avec un niveau debug, zl.Info()
renvoie un Event
avec un niveau info, etc.
Puis la création du message se fait avec Msg("this is a string")
ou Msgf("who run the world? %+v", girls)
à l'instar du Print
et Printf
en Go.
Logging simple
Pour envoyer des logs, il faut donc créer un Event
qui sera envoyé avec un message.
var sum int = 19
zl.Debug().Msgf("9 + 10 = %+v", sum)
zl.Info().Msg("Hello, world!")
zl.Warn().Msg("Something weird happened but it's still fine")
err := fmt.Errorf("unable to do something")
zl.Error().Msgf("Oops, something wrong happened : %+v", err)
zl.Fatal().Msg("Will stop everything!!!")
zl.Panic().Msg("Will end the goroutine")
Note :
zl.Fatal().Msg()
va appeleros.Exit(1)
, ce qui va arrêter le moteur directement.zl.Panic().Msg()
va appelerpanic()
, ce qui va arrêter la goroutine.
Logging avec contexte
Si le message ne suffit pas, zerolog
permet d'ajouter du contexte aux logs envoyés, sous le format clé-valeur. La clé est toujours un string
, le type de valeur peut varier.
certDir := os.Getenv("SSL_CERT_DIR")
certFile := os.Getenv("SSL_CERT_FILE")
httpProxy := os.Getenv("HTTPS_PROXY")
httpsProxy := os.Getenv("HTTP_PROXY")
zl.Info().Str("SSL_CERT_DIR", certDir).Str("SSL_CERT_FILE", certFile).Str("HTTPS_PROXY", httpProxy).Str("HTTP_PROXY", httpsProxy).Msg("Environment variables will be used by the HTTP client")
{"level":"info","SSL_CERT_DIR":"","SSL_CERT_FILE":"","HTTPS_PROXY":"","HTTP_PROXY":"","time":"2019-04-18T16:51:49+02:00","caller":"/home/capensis/go/src/git.canopsis.net/cat/go-engines/plugins/axepostprocessor/webhook/main.go:82","message":"Environment variables will be used by the HTTP client"}
Ici, Str()
a été utilisé pour ajouter un string
dans le contexte. De même, Int()
ajoute un entier au contexte, Err()
une error
ou Dur()
pour une time.Duration
.
zl.Warn().Str("webhook", webhook.ID).Err(err).Msg("Failed to generate url template for webhook")
// 10 May 19 16:41 CEST WRN home/capensis/go/src/git.canopsis.net/cat/go-engines/plugins/axepostprocessor/webhook/main.go:301 > Failed to generate url template for webhook error="template: webhook-url-459963:1: unexpected \"{\" in command" webhook id=master-webhook
zl.Info().Int("alarms", len(cancelResolved)).Msg("Resolved cancels")
// 10 May 19 16:41 CEST INF home/capensis/go/src/git.canopsis.net/canopsis/go-revolution/cmd/engine-axe/engine.go:109 > Resolved cancels alarms=0
Note: Le contexte apparaît directement dans la console quand on redirige les logs vers stdout
ou stderr
, mais pas avec journalctl -f
. Cela s'explique par le fait que journalctl
n'affiche que le MESSAGE
.
Pour voir la totalité du contexte, on peut par exemple utiliser journalctl --output=json-pretty -f
qui affiche le MESSAGE
mais également ALARMS
qui est un élément qu'on a ajouté dans le contexte et JSON
qui contient la totalité de ce que zerolog envoie vers journald : niveau de log, contexte, message, timestamp.
{
"_COMM" : "engine-axe",
"_EXE" : "/home/capensis/go/src/git.canopsis.net/canopsis/go-revolution/build/engine-axe",
"_CMDLINE" : "./engine-axe -postProcessorsDirectory /home/capensis/go/src/git.canopsis.net/cat/go-engines/build/plugins/axepostprocessor -d -log journald",
"ALARMS" : "0",
"MESSAGE" : "updated flapping alarms",
"CALLER" : "/home/capensis/go/src/git.canopsis.net/canopsis/go-revolution/cmd/engine-axe/engine.go:130",
"JSON" : "{\"level\":\"info\",\"alarms\":0,\"time\":\"2019-05-10T15:24:29+02:00\",\"caller\":\"/home/capensis/go/src/git.canopsis.net/canopsis/go-revolution/cmd/engine-axe/engine.go:130\",\"message\":\"updated flapping alarms\"}\n"
}
Utilisation des logs
Ca dépasse un peu le cadre de cette MR, qui n'est qu'une MR pour mettre en place les système de logs, mais il faut discuter dans l'équipe de dev (@cdewarumez @tplockyn @lseguinot @vlaroye) et avec les intégrateurs / le support (@dwatteau @fbride @rfremont) des pratiques des niveaux de logs dans les moteurs.
-
Quel niveau de logs par défaut dans les moteurs ? (Ici, c'est info mais avec l'option
-d
pour passer en debug) -
Quel usage du contexte proposé par
zerolog
? On peut très bien écrire.Msgf("error %+v", err)
au lieu de.Err(err).Msg("error")
mais l'erreur ne sera pas dans le contexte. -
A quel moment logger l'erreur ? Remplacer tous les
return something.doesathing()
et laisser la fonction qui reçoit la réponse logger l'erreur ? Ou faireerr = something.doesathing()
et vérifiererr != nil
?
Pour les niveaux de logs, je me permets de partager cette rule of thumb que j'ai trouvé sur blog.xebia.fr pour poser les bases des niveau de log.
DEBUG : information détaillée pour le suivi d’exécution du programme (identification et résolution d’éventuelles anomalies).
INFO : information essentielle sur le programme, suivi de l’exécution d’un point de vue global.
WARN : situation d’exécution non idéale (utilisation d’API dépréciées, ressource non critique absente…).
ERROR : situation d’erreur ou inattendue, qui n’entraine pas forcément une situation de blocage (accès à un service externe non critique et dont l’accès est re-testé périodiquement).
FATAL / PANIC : situation d’erreur critique, qui entraîne un blocage voire un arrêt du système (problème de connexion à la DB par exemple).
Pour adapter aux moteurs Go, on peut imaginer par exemple :
-
DEBUG
à l'intérieur de chaque fonction -
INFO
au démarrage, chargement de plugins (webhook), au beat du moteur et à l'extinction -
WARN
quand on n'arrive pas à charger des webhooks, des watchers ou des event-filter -
ERROR
en cas d'erreur inattendue (n'arrive pas à gérer les resolve done, resolve cancel, etc) -
FATAL / PANIC
en cas d'erreur critique (pas d'accès à Influx, pas d'accès à Mongo, n'arrive pas à charger les plugins)