Logging & Monitoring - Yolino/t211-dbox-fm GitHub Wiki
Introduction
Nous avons décidé de mettre en place un service de centralisation des logs, ainsi qu'un monitoring basique. Cela nous offre de nombreux avantages, notamment une méthode rapide et efficace de détection et d'analyse des problèmes potentiels, une optimisation du temps de réaction, et des possibilités d'amélioration continue en observant le comportement des utilisateurs.
Une vidéo de présentation a été réalisée pour illustrer le fonctionnement global du système.
Choix de la stack
ELK (ElasticSearch, Logstash, Kibana)
Disposant de peu de connaissances sur les différentes options technologiques disponibles pour notre cas d'utilisation, nous nous sommes rapidement tournés vers notre cours d'administration de systèmes et réseau, recommendant la stack ELK, réputée pour sa robustesse et sa richesse en termes de fonctionnalités. Nous sommes parvenus à intégrer les différents services à notre infrastructure Docker en développement, ainsi qu'en staging. Cependant, lorsque nous avons tenté d'effectuer la mise en production, nous avons dû faire face à de gros problèmes de performances, et ELK, en plus de tourner très difficilement, empiétait sur les performances nécessaires pour l'application même. Nous avons tenté de délocaliser la stack sur un second serveur, mais même seule, les programmes souffraient du manque de performances, et la récupération des logs était très saccadée, voire incomplète. Nous avons donc été contraints d'abandonner ELK, dans la mesure où nous préférions opter pour des technologies plus légères plutôt que d'upgrade le serveur.
Sentry
Comme conseillé par Mr Ramsamy, nous nous sommes renseignés sur Sentry pour potentiellement se charger du monitoring. Cependant, en lisant la documentation et des posts sur des forums, nous étions suspicieux du rôle que Sentry jouerait dans notre application. Notre objectif principal était de centraliser toute l'information afin de pouvoir la lire et la visualiser, alors que Sentry est une solution adaptée pour la gestion d'erreurs/exceptions, mais pas vraiment le logging. Nous avons donc écarté cette option car elle s'écartait de nos intentions pour ce projet. Nous conservons cependant l'éventualité de rajouter Sentry en parallèle d'une solution de logging afin de bénéficier du meilleur des deux mondes.
LAG (Loki, Alloy, Grafana)
En effectuant des recherches sur une solution légère (en comparaison avec ELK), nous sommes tombés sur l'option de Grafana, réputé pour sa légèreté, mais également sa modernité. En creusant un peu sur le site Grafana Labs, nous avons réussi à constituer une stack entière sous Docker, basée sur leurs logiciels Open Source :
- Loki : Système d'agrégation de logs, solution de stockage de la stack.
- Alloy : Récupère les logs de l'ensemble des conteneurs, effectue des traitements selon une pipeline customisable, avant de les forwarder vers Loki.
- Grafana : Logiciel de visualisation des données permettant d'effectuer des recherches avancées sur les données contenues dans Loki, ainsi que de générer des visuels permettant un monitoring global de l'application.
Infrastructure
Nous avons pris la décision d'héberger le système de monitoring sur un second serveur, afin d'améliorer notre résilience face à un crash du serveur exposant l'application. Nous retrouvons donc les conteneurs de base de l'application (nginx, Django, PostgreSQL et Docker Mailserver) sur le serveur principal. Nous y avons également ajouté un conteneur Alloy, qui dispose d'un accès au socket du Docker Engine, afin de récupérer les logs et le statut des healthchecks des différents services. Il est chargé de transférer l'information à Loki, qui se trouve sur le second serveur, accessible par Internet. Étant donné que les communications entre Alloy et Loki ne sont pas chiffrées, nous avons mis en place un VPN WireGuard afin de bénéficier d'un tunnel chiffré pour nos communications.
Sur le VPS de monitoring, Loki et Grafana, également sous forme de conteneurs, communiquent entre eux pour permettre la visualisation des données. Afin d'accéder à l'information de manière efficace et sécurisée, nous avons configuré nginx pour qu'il puisse servir l'interface web de Grafana. Cette interface est protégée par une authentification par mot de passe au niveau de l'application, mais également au niveau du reverse proxy par la vérification d'un certificat TLS client. Seuls les clients disposant d'un certificat signé et approuvé par l'autorité de certification de notre site sont autorisés à accéder à l'endpoint /grafana
. Cette décision d'employer des certificats clients dans le cadre de notre application est peu commune, mais est justifiée par l'absence de réelle infrastructure réseau nous permettant d'accéder au monitoring de manière sécurisée en filtrant le trafic par IP par exemple (car nos adresses varient sans cesse).
Configuration
Pour plus d'explications sur le comportement des services, la documentation officielle de Grafana Labs est très user-friendly et riche en informations.
Loki
La configuration de Loki est minimale et confère un comportement basique d'ingestion de logs. Comme indiqué ci-dessous, le serveur écoute sur le port 3100 de son interface virtuelle exposée au VPN :
server:
http_listen_address: 10.0.0.1 # VPN IP
http_listen_port: 3100
grpc_listen_port: 9095
ingester:
lifecycler:
ring:
kvstore:
store: inmemory
replication_factor: 1
chunk_idle_period: 5m
max_chunk_age: 1h
schema_config:
configs:
- from: 2024-01-01
store: boltdb-shipper
object_store: filesystem
schema: v11
index:
prefix: index_
period: 24h
storage_config:
boltdb_shipper:
active_index_directory: /tmp/loki/index
cache_location: /tmp/loki/boltdb-cache
shared_store: filesystem
filesystem:
directory: /tmp/loki/chunks
limits_config:
reject_old_samples: true
reject_old_samples_max_age: 168h
Alloy
Le service Alloy nécessite peu de configuration au niveau de l'infrastructure. Nous avons monté plusieurs volumes dans le conteneur pour lui permettre de travailler. Nous y retrouvons un volume standard pour la persistance de ses données, son fichier de configuration, un accès à la socket du Docker Engine pour récupérer les logs et healthcheks des conteneurs, et enfin, un accès au fichier d'output des healthchecks Docker.
alloy:
...
volumes:
- prod_alloy_data:/var/lib/alloy/data
- ./alloy/config.alloy:/etc/alloy/config.alloy
- /var/run/docker.sock:/var/run/docker.sock
- /var/log/docker-health.log:/var/log/docker-health.log
...
Les healthchecks sont effectués par le système hôte grâce à un cron job :
*/5 * * * * docker ps --format "timestamp=$(date -Iseconds) container={{.Names}} status={{.Status}}" >> /var/log/docker-health.log 2>&1
Il a pour objectif de vérifier le statut de santé des conteneurs toutes les cinq minutes. Alloy sera chargé d'envoyer ces données à Loki, de manière similaire à un heartbeat. Nous ne nous attarderons pas sur les healthchecks des différents conteneurs qui peuvent être consulté sur le fichier Compose.
La logique principale est présente dans une pipeline contenue dans le fichier config.alloy
:
discovery.docker "containers" {
host = "unix:///var/run/docker.sock"
refresh_interval = "5s"
}
discovery.relabel "containers" {
targets = []
rule {
target_label = "job"
replacement = "docker"
}
rule {
source_labels = ["__meta_docker_container_name"]
regex = "/(.*)"
target_label = "container"
}
}
loki.source.docker "containers" {
host = "unix:///var/run/docker.sock"
targets = discovery.docker.containers.targets
relabel_rules = discovery.relabel.containers.rules
forward_to = [loki.write.grafana_loki.receiver]
}
local.file_match "docker_health" {
path_targets = [{"__path__" = "/var/log/docker-health.log"}]
}
loki.source.file "docker_health" {
targets = local.file_match.docker_health.targets
forward_to = [loki.process.docker_health.receiver]
tail_from_end = true
}
loki.process "docker_health" {
stage.static_labels {
values = {
job = "docker_health",
}
}
forward_to = [loki.write.grafana_loki.receiver]
}
loki.write "grafana_loki" {
endpoint {
url = "http://10.0.0.1:3100/loki/api/v1/push"
}
}
Chaque bloc de code, appelé "composant", possède un rôle unique et agit comme une chaine. Ici, nous avons une source loki.source.docker.containers
, qui représente le flux de logs des conteneurs. Ce flux est récupéré sur les conteneurs discovery.docker.containers
liés à la socket Docker, et passent par une étape d'étiquetage définie par discovery.relabel.containers
, qui a pour but de tagger les logs avec un job (type de log) docker
et le nom du conteneur. Ces étiquettes permettent une structuration des logs et sont la base du filtrage pour nos visualisations avec Grafana. Une fois étiquetés, les logs sont simplement forwardés au conteneur Loki à travers le VPN.
On retrouve également une seconde source d'information, loki.source.file.docker_health
, provenant du fichier de logs des healthchecks. Les logs seront étiquetés avec un job docker_health
, et seront également transmis à l'instance de Loki.
Grafana
L'intégralité de notre configuration initiale de Grafana est réalisée depuis le fichier Compose grâce à des variables d'environnement, comme affiché ci-dessous. Nous remarquons qu'il a été nécessaire d'adapter la racine du serveur à notre cas d'usage où Grafana est servi comme une sous-URL. Il est également nécessaire d'autoriser les requêtes Cross-Origin venant de notre site pour permettre au service de fonctionner correctement. Notons ici que Grafana n'est exposé que sur l'interface réseau du VPN (10.0.0.1
), pour éviter d'être contacté depuis l'extérieur, et donc sans passer par le reverse proxy et son authentification.
grafana:
container_name: grafana
environment:
- GF_SERVER_ROOT_URL=https://dbox-fm.be/grafana
- GF_SERVER_SERVE_FROM_SUB_PATH=true
- GF_PATHS_PROVISIONING=/etc/grafana/provisioning
- GF_FEATURE_TOGGLES_ENABLE=alertingSimplifiedRouting,alertingQueryAndExpressionsStepMode
- GF_CORS_ENABLED=true
- GF_CORS_ALLOW_ORIGINS=https://dbox-fm.be
env_file:
- .secrets/grafana.env
image: grafana/grafana:11.2.10
volumes:
- grafana_data:/var/lib/grafana
ports:
- "10.0.0.1:3000:3000"
networks:
- loki
restart: always
Fonctionnement
Émission et acquisition des logs
Comme expliqué plus haut, Alloy dispose d'un accès à la socket Docker, ce qui lui permet
d'accéder aux logs de l'ensemble de nos conteneurs en autonomie. Étant donné que Docker possède une fonctionnalité intégrée de logging, nous n'avons simplement qu'à émettre nos logs en stdout
de chaque conteneur (ce qui est fait de base, mais également renforcé par l'utilisation du package logging
en Python et de l'instruction access_log
de nginx).
En ce qui concerne les healthchecks, nous avons exploré l'option d'employer l'accès à la socket Docker pour récupérer les états de santé. Cependant, nous sommes tombés face à une limitation de l'intégration de Loki avec Alloy, par l'impossibilité de faire tourner des processus périodiquement (ce qui était possible avec Alloy + Prometheus). Nous avons donc trouvé une solution alternative, qui consiste à placer Alloy en surveillance d'un fichier avec loki.source.file
. Il ne reste plus qu'à faire tourner un cron job qui a pour objectif d'écrire dans ce fichier.
Ces deux méthodes de récupération diffèrent de notre approche précédente avec la stack ELK, où nous avions configuré Django et nginx pour transférer eux-mêmes les logs au serveur Logstash, qui se chargeait alors du traitement.
Traitement
Une pipeline de traitement a pour fonction de centraliser l'acquisition des logs, et ensuite de les stocker, souvent par le biais d'un autre service. Il s'agit ici effectivement d'Alloy, dont la fin de chaine de traitement consiste à envoyer le contenu vers notre instance de Loki.
Format
Lorsqu'un log est émis en stdout
d'un conteneur puis récupéré par Alloy, nous effectuons un traitement préalable pour uniformiser correctement l'information, et ainsi simplifier sa visualisation. Cela passe premièrement par l'étiquetage, comme expliqué plus tôt. Voici les différents types de labels que nous attribuons :
job
: présent sur tous les logs, précise la nature globale du message (docker
pour les logs applicatifs,docker_health
pour les healthchecks)container
: pour les logs applicatifs, identifie l'émetteur du log par son nom de conteneur (dbox-frontend
,dbox-backend
, ...)
Nous tirons profit des différents niveaux de sévérité proposés par le package logging
pour Django. Ces niveaux permettent d'ajouter du contexte aux logs, et en plus de permettre une lecture plus simple, il est possible d'effectuer un tri sur ces derniers. Voici un exemple d'instructions de logging dans notre code :
user = authenticate(username=username, password=password)
if user:
login(info.context, user)
logger.info(f"{user} (id {user.id}) just connected from {get_client_ip(info.context)}")
return LoginUser(success=True, user=user)
else:
logger.warning(f"Failed authentication with username {username} from {get_client_ip(info.context)}")
raise GraphQLError("Invalid credentials")
Dans cette implémentation d'une connexion d'un utilisateur à un compte, nous faisons bon usage des niveaux d'importance. Si la connexion est réussie, nous émettons un log d'information. Cependant, si les credentials ne correspondent pas, nous entrons cela comme un avertissement, il s'agit peut-être d'un utilisateur malveillant.
Notre format est pour l'instant imparfait et pourrait subir d'importantes améliorations, parmi lesquelles la première serait un passage complet au JSON. Avec des logs relativement simples, il est encore possible d'effectuer des traitements efficaces sur les chaines de caractères notamment grâce aux expressions régulières, mais nous atteindrons une limitation en termes de scaling. Ce changement de format nous permettrait une manipulation aisée de l'information, avec la possibilité d'extraire aisément des propriétés afin de les traiter depuis Grafana.
Synchronisation des horloges
Avec des horloges désynchronisées, un système de centralisation de logs perdrait tout son sens, car il a pour objectif de permettre une traçabilité des suites d'évènements. En effet, si deux sources différentes émettent des logs physiquement en même temps, mais avec une ou plusieurs heures de décalage virtuel, il devient fastidieux dans une petite application, et réalistiquement impossible à plus grande échelle, de retracer les actions et réponses du système.
Pour permettre une synchronisation simple, Alloy ajoute automatiquement le timestamp de son ingestion avant de l'envoyer à Loki. Cela permet de réduire grandement l'impact d'un décalage entre plusieurs horloges. C'est le cas de notre application, où nous nous fions majoritairement au timestamp annoté par la pipeline plutôt que celui émis par nginx, Django et les autres.
Cependant, un tel système n'est pas parfait et peut rencontrer des limites. Et si Alloy recevait une grande quantité de logs d'un conteneur, et pendant qu'il traite ces derniers, d'autres conteneurs envoyaient de l'information ? Ou si Alloy expérimentait des problèmes pour une raison ou une autre, qui le forceraient à faire une pause ou à redémarrer ? Dans ces situations, les logs émis seraient étiquetés avec un timestamp décalé, ou encore pire, ils pourraient ne plus être ordonnés (par exemple si plusieurs serveurs Alloy traitent les informations de conteneurs différents). Pour annuler ces problèmes, il est possible de synchroniser les horloges internes des conteneurs avec NTP (Network Time Protocol). Cela assurerait alors la cohérence des timestamps internes des applications, et il serait donc possible d'utiliser ceux-ci plutôt que ceux ajoutés par Alloy.
Visualisation des données
Une fois les logs envoyés à Loki par Alloy, nous pouvons à présent les visualiser depuis Grafana. Notre service est disponible à l'URL https://dbox-fm.be/grafana
, et son accès est protégé par un certificat TLS client (voir Sécurisation). La première chose à faire est de vérifier que la source Loki est correctement configurée, dans notre cas il s'agit de http://localhost:3100
car les deux conteneurs tournent sur le même serveur. Une fois la source disponible nous avons accès à l'exploration des logs. Nous pouvons effectuer des queries simples (ex: tri par label) et avancées (ex: extraction d'une colonne JSON, agrégation) grâce à une interface intuitive et la possibilité d'écrire manuellement nos queries LogQL. Il est également possible d'observer ces logs sous forme de tableau. Voici par exemple les logs émis par le conteneur nginx le 27 mai entre 00:00 et 02:00 (en notant que beaucoup de crawlers portent un intérêt visible pour le site) :
Au-delà de ça, nous avons également mis en place une dashboard composée de deux visualisations, nous permettant aisément d'observer certaines informations significatives. La première visualtion est une ligne du temps des healthchecks, nous permettant d'avoir un aperçu du statut des différents services, et la seconde est un compteur du nombres d'utilisateurs authentifiés par jour :
Ces visualisations ont demandé un traitement strict des logs, ce qui fût fastidieux étant donné la structuration laxe de nos logs. Nous avons été contraints d'employer des regex pour altérer cette structure, là où du JSON aurait grandement simplifié le processus. Encore une fois, nous envisageons de migrer vers ce format afin de simplifier le travail nécessaire pour analyser les données.