Skip to content

Lire les logs (Envoy, API, événements)

Contexte : ADR 015 pour la collecte, issue #253 et INC-079 pour l'exemple du 503. Toutes les lignes de cette page sont réelles, relevées sur le montage du 2026-10-15. Seule l'IP publique du client a été remplacée par 203.0.113.7, une adresse réservée à la documentation.

Un log sert à répondre à une question : qui a demandé quoi, qui a répondu, et pourquoi ça a raté. Sans savoir lire ses champs, une ligne de log est un bloc de texte inutile. Cette page explique les trois sources du projet, champ par champ, puis donne les requêtes Grafana prêtes à copier.

En trois phrases

Envoy (la gateway devant l'API) écrit une ligne JSON pour chaque requête, même celles que l'API ne voit jamais. L'API (uvicorn) écrit une ligne par requête qu'elle a reçue, sans savoir qui était le vrai client. Pour comprendre une erreur, on part d'Envoy : son champ response_flags dit qui a produit la réponse et pourquoi.

Le vocabulaire

Terme Ce que c'est
Log d'accès une ligne par requête HTTP, écrite par le serveur qui l'a traitée
Downstream le côté client vu par Envoy : le navigateur, curl, un test
Upstream le côté serveur vu par Envoy : le pod de l'API
Cluster Envoy un groupe de pods candidats pour une route. Rien à voir avec un cluster Kubernetes
response_flags le code court d'Envoy qui explique une réponse anormale (UF, UT, RL…)
stdout la sortie standard d'un conteneur. Kubernetes l'écrit dans un fichier sur le nœud
Alloy le collecteur qui lit ces fichiers et pousse les lignes vers Loki
Loki la base qui stocke les logs. Grafana l'interroge en LogQL
Préfixe CRI <horodatage> stdout F ajouté devant chaque ligne par le runtime de conteneurs

Où naissent les logs

Une requête vers api.devopsyouss.com traverse deux programmes qui écrivent chacun leur ligne. Les deux finissent dans Loki par le même chemin.

flowchart LR
    C["Client<br/>(navigateur, curl, test)"] --> N["NLB AWS"]
    N --> E["Envoy<br/>(gateway)"]
    E -->|"route + choix d'un pod"| A["Pod API<br/>(uvicorn)"]
    E -. "1 ligne JSON<br/>par requête" .-> S1[("stdout Envoy")]
    A -. "1 ligne texte<br/>par requête reçue" .-> S2[("stdout API")]
    S1 --> AL["Alloy"]
    S2 --> AL
    AL --> L[("Loki")]
    L --> G["Grafana<br/>Explore"]

Deux conséquences, à garder en tête pour toute la suite :

  • Envoy voit tout. Une requête refusée par Envoy lui-même (rate limit, pod injoignable) n'a aucune ligne côté API.
  • L'API ne voit pas le client. Elle reçoit la connexion d'Envoy, et note l'IP d'Envoy.

Lire une ligne Envoy

Une requête normale

GET /posts/public?limit=2 sur dev, réponse 200 :

{
  ":authority": "api-dev.devopsyouss.com",
  "method": "GET",
  "x-envoy-origin-path": "/posts/public?limit=2",
  "protocol": "HTTP/2",
  "user-agent": "doc-lire-les-logs",
  "downstream_remote_address": "203.0.113.7:53112",
  "x-forwarded-for": "203.0.113.7",
  "start_time": "2026-10-15T12:44:10.817Z",
  "route_name": "httproute/fastapi-dev/fastapi/rule/1/match/0/api-dev_devopsyouss_com",
  "upstream_cluster": "httproute/fastapi-dev/fastapi/rule/1",
  "upstream_host": "10.42.1.182:8080",
  "response_code": 200,
  "response_flags": "-",
  "response_code_details": "via_upstream",
  "duration": 6,
  "bytes_sent": 2
}

Les champs se lisent par question, pas dans l'ordre.

Qui demande quoi ?

Champ Exemple Sens
:authority api-dev.devopsyouss.com le host demandé, donc l'environnement
method + x-envoy-origin-path GET /posts/public?limit=2 la requête
downstream_remote_address 203.0.113.7:53112 l'IP et le port du client
user-agent python-httpx/0.28.1 le programme client : un navigateur, un test…
start_time 12:44:10.817Z l'heure réelle de la requête, en UTC

Où Envoy l'a-t-il envoyée ?

Champ Exemple Sens
route_name httproute/fastapi-dev/fastapi/... la règle d'HTTPRoute qui a matché : namespace, puis route
upstream_cluster httproute/fastapi-dev/fastapi/rule/1 le groupe de pods candidats
upstream_host 10.42.1.182:8080 le pod choisi, par son IP. null si aucun pod n'a été contacté

Comment ça s'est passé ?

Champ Exemple Sens
response_code 200 le code renvoyé au client
response_flags - - = rien d'anormal. Sinon, voir la section suivante
response_code_details via_upstream qui a produit la réponse. via_upstream = c'est le pod
duration 6 durée totale en millisecondes
upstream_transport_failure_reason null la raison réseau quand la connexion au pod échoue

Le premier réflexe

Lire response_code_details. S'il vaut via_upstream, l'API a choisi ce code : un 401, 404 ou 422 est alors une réponse normale de l'application. Sinon, c'est Envoy qui a répondu à sa place, et response_flags dit pourquoi.

Le champ qui tranche : response_flags

Les codes vus sur le montage du 2026-10-15, avec leur cas réel :

Flag Nom Code vu Cas réel du 15/10 Qui est en cause
- aucun 200, 401, 403, 404, 422 réponses normales de l'API personne
RL Rate Limited 429 11e POST /login en une minute Envoy refuse, volontairement (rate limit)
UF Upstream connection Failure 503 pod en cours d'arrêt pendant un rollout le pod : son port est fermé
UT Upstream request Timeout 504 flux live de l'UI ArgoCD coupé à 15 s le pod n'a pas fini dans le délai d'Envoy
UC Upstream Connection termination 101 fin d'un Live tail Grafana (websocket) le pod a fermé la connexion
DR Downstream Remote reset 0 ou 200 onglet ArgoCD fermé ou changé le client a coupé
DPE Downstream Protocol Error 400 requête illisible, sans host ni méthode le client, sans doute un scanner d'Internet

Deux flags à connaître même s'ils ne sont pas apparus ce jour-là : UH (aucun pod sain dans le groupe) et NR (aucune route ne correspond au host ou au chemin).

Un même code, plusieurs pannes

Un 503 ne dit pas quelle panne a eu lieu. UF (port fermé, rollout), UC (connexion réutilisée que le pod avait fermée, le 503 sous charge) et UH (aucun pod sain) donnent tous un 503, avec trois correctifs différents. Et un 200 peut porter un flag : un flux qui a bien démarré, puis a été coupé (200 UT, 200 DR).

Exemple complet : le 503 du rollout

Le 2026-10-15, juste après la promotion en prod, le test e2e-prod a pris trois 503. Voici une des trois lignes, réduite aux champs utiles :

{
  ":authority": "api.devopsyouss.com",
  "x-envoy-origin-path": "/posts/public",
  "user-agent": "python-httpx/0.28.1",
  "start_time": "2026-10-15T12:12:03.078Z",
  "upstream_host": "10.42.1.253:8080",
  "response_code": 503,
  "response_flags": "UF",
  "response_code_details": "upstream_reset_before_response_started{remote_connection_failure|delayed_connect_error:_Connection_refused}",
  "upstream_transport_failure_reason": "delayed_connect_error:_Connection_refused",
  "x-envoy-upstream-service-time": null,
  "duration": 4
}

La lecture, question par question :

  1. response_code_details ne vaut pas via_upstream : c'est Envoy qui a répondu.
  2. response_flags: UF et Connection_refused : Envoy n'a pas pu se connecter au pod.
  3. upstream_host: 10.42.1.253 : ce pod-là. Avec kubectl get events, on retrouve que cette IP était l'ancien pod mc8zs, arrêté à 12:12:02, une seconde plus tôt.
  4. x-envoy-upstream-service-time: null : le pod n'a jamais répondu.

Le mécanisme, sur une ligne de temps :

sequenceDiagram
    participant K as kubelet
    participant P as Ancien pod (10.42.1.253)
    participant E as Envoy
    participant C as Client
    K->>P: 12:12:02 SIGTERM
    Note over P: uvicorn ferme son port tout de suite
    C->>E: 12:12:03 GET /posts/public
    E->>P: connexion TCP
    P--xE: Connection refused
    E->>C: 503 UF (généré par Envoy)
    Note over E: ~1 s plus tard, Envoy apprend que<br/>l'endpoint a disparu

Le pod s'arrête avant qu'Envoy ne l'ait retiré de sa liste. Le correctif est suivi dans

253.

Lire une ligne de l'API (uvicorn)

Le format est du texte, pas du JSON :

INFO:     10.42.1.69:38586 - "GET /posts/public?limit=2 HTTP/1.1" 200 OK
Morceau Sens
INFO: le niveau. Une erreur Python apparaît en ERROR: suivie d'un Traceback
10.42.1.69:38586 l'IP d'Envoy, pas celle du client
"GET /posts/public?limit=2 HTTP/1.1" la requête telle qu'elle est arrivée au pod
200 OK la réponse de l'application

Trois pièges :

  • L'IP n'est pas le client. Pour savoir qui a appelé, il faut la ligne Envoy correspondante (downstream_remote_address, x-forwarded-for).
  • Les sondes noient tout. Toutes les 5 et 10 secondes, kubelet appelle /healthz/ready et /healthz/live, et Prometheus appelle /metrics. Sur deux minutes de logs d'un pod de dev, 26 lignes sur 40 sont des sondes. Les filtrer d'abord.
  • Ce qu'Envoy refuse n'apparaît pas. Le même jour, 12 POST /login d'affilée : Envoy en a vu 12, l'API 10. Les deux derniers ont reçu un 429 RL d'Envoy et ne sont jamais arrivés au pod.

Une même requête, vue des deux côtés

Requête Envoy API
GET /posts/public?limit=2 200 - via_upstream 200 OK
GET /posts/ (sans jeton) 401 - via_upstream 401 Unauthorized
GET /inexistant 404 - via_upstream 404 Not Found
GET /posts/public?limit=1000 422 - via_upstream 422 Unprocessable Entity
POST /login (mauvais mot de passe) 403 - via_upstream 403 Forbidden
POST /login, 11e en une minute 429 RL local_rate_limited rien
pendant un rollout 503 UF rien

Règle simple : si l'API n'a pas de ligne, c'est Envoy qui a répondu.

Les événements Kubernetes

Les événements disent ce que Kubernetes a fait : créer, arrêter, déplacer un pod. Ils donnent les heures qui manquent aux logs, comme le Killing de l'exemple du rollout.

kubectl -n fastapi-prod get events --sort-by=.lastTimestamp
Raison Sens Vu le 15/10
ScalingReplicaSet un déploiement ajoute ou retire des pods à chaque rollout
Killing kubelet arrête un conteneur (SIGTERM) Stopping container fastapi à 12:12:02
FailedGetResourceMetric le HPA n'a pas de métrique pour un pod au démarrage, pods pas encore prêts
BackOff un conteneur redémarre en boucle non

Les événements expirent au bout d'une heure environ. Pour un redémarrage plus ancien, le pod garde la cause de son dernier arrêt :

kubectl -n argocd get pod <pod> -o jsonpath='{.status.containerStatuses[*].lastState.terminated}'

Le 15/10, cette commande a montré "reason":"OOMKilled","exitCode":137 sur argocd-repo-server : le conteneur a dépassé sa limite mémoire pendant le bootstrap.

Dans Grafana : les requêtes prêtes à copier

Grafana, menu Explore, source Loki, éditeur en mode Code. La plage de temps s'affiche à l'heure du navigateur (Paris), alors que les champs start_time sont en UTC (deux heures de moins en été).

Le piège du préfixe CRI

Chaque ligne stockée dans Loki commence par trois morceaux ajoutés par le runtime :

2026-10-15T12:12:13.006Z stdout F {":authority":"api.devopsyouss.com", ...}
└──── préfixe CRI : horodatage, flux, F ────┘ └──── le JSON d'Envoy ────┘

Avec ce préfixe, | json ne reconnaît pas la ligne. Loki la marque JSONParserErr, et tout filtre sur un champ ne renvoie rien, sans message d'erreur visible. Il faut d'abord découper le préfixe :

| pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json
  • pattern coupe aux trois premiers espaces et range le reste dans body ;
  • line_format remplace la ligne par ce body, donc par le JSON seul ;
  • json découpe ensuite le JSON en champs filtrables.

Les recettes

Toutes ont été testées sur Loki le 2026-10-15.

Les 503 d'un host : 

{namespace="envoy-gateway-system"} |= "api.devopsyouss.com" | pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json | response_code="503"

Toutes les réponses 5xx : 

{namespace="envoy-gateway-system"} |= "response_code" | pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json | response_code >= 500

Les refus du rate limit : 

{namespace="envoy-gateway-system"} |= "response_code" | pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json | response_flags="RL"

Toute l'activité d'un pod, par son IP (trouvée dans upstream_host) : 

{namespace="envoy-gateway-system"} |= "10.42.1.253:8080" | pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json

Le tableau de bord en une requête : nombre de réponses par code et par flag. Le résultat se lit en mode Table : 

sum by (response_code, response_flags) (count_over_time({namespace="envoy-gateway-system"} |= "response_code" | pattern "<_> <_> <_> <body>" | line_format "{{.body}}" | json | __error__="" [1h]))

Les logs de l'API sans les sondes : 

{namespace="fastapi-prod", container="fastapi"} != "/healthz" != "/metrics"

Les erreurs 5xx vues par l'API, et les plantages Python : 

{namespace=~"fastapi-.*", container="fastapi"} |~ "\" 5[0-9]{2} "
{namespace=~"fastapi-.*"} |= "Traceback"

Filtrer avant de parser

|= "texte" est rapide : il garde les lignes qui contiennent le texte, sans rien découper. Le placer avant pattern et json réduit le travail de Loki. C'est le rôle du |= "response_code", qui ne garde que les logs d'accès : le même namespace contient aussi les logs du contrôleur Envoy Gateway, qui ne sont pas des logs d'accès.

Les pièges, en résumé

  • Le préfixe CRI fait échouer | json en silence. Toujours pattern d'abord.
  • start_time est l'heure de la requête. L'horodatage de la ligne dans Loki est celui de la collecte, quelques secondes plus tard.
  • Grafana affiche l'heure de Paris, les champs JSON sont en UTC.
  • L'API note l'IP d'Envoy. Le vrai client est dans la ligne Envoy.
  • Pas de ligne côté API = Envoy a répondu seul.
  • Loki ne garde rien d'un montage à l'autre (#154). Lire et recopier les preuves avant le teardown.
  • Un code ne suffit pas. Lire response_flags et response_code_details.

Pour aller plus loin