Alexandre Moevi requested to merge go-logging into develop Apr 18, 2019

Résumé

Mise en place d'une première version des logs pour les moteurs Go à l'aide de la bibliothèque zerolog.

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 et glide.lock puis lancer make 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 ou journalctl va pousser les logs vers journald, stderr va pousser les logs vers stderr et stdout va pousser les logs vers stdout. 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 sur stdout.
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 et stderr devraient s'afficher dans la console soit directement, soit avec docker(-compose) logs si le moteur Go fonctionne dans un container Docker. Pour ce qui est de journald, journalctl -f n'affiche que le message, mais journalctl --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.

Principes et utilisation du `Logger`

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 appeler os.Exit(1), ce qui va arrêter le moteur directement. zl.Panic().Msg() va appeler panic(), 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 faire err = something.doesathing() et vérifier err != 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)

Edited Aug 27, 2019 by Alexandre Moevi

[DEPRECATED] Gestion des logs