[TECH] Ajouter les infos de corrélation à chaque log via le logger

laura-bergoens commented 2 weeks ago

:unicorn: Problème

Il est bien pratique de pouvoir avoir dans datadog les informations de corrélation (request_id et user_id). Aujourd'hui, on avait besoin d'appeler spécifiquement une méthode maison, laquelle récupérait ces infos depuis le AsyncLocalStorage et appelait le logger Pino avec ces éléments. Idéalement, on aimerait maintenant que ce soit le cas pour tous les logs tout le temps, mais c'était pas un super design de remplacer tous les logger.error et logger.info par nos méthodes maison.

:robot: Proposition

Il se trouve qu'il existe un moyen de configurer pino pour qu'il fasse le travail de récupération de contexte et d'ajout de données dans le log : https://github.com/pinojs/pino/blob/main/docs/api.md#mixin-function

Donc on configure en deux temps :

const logger = pino(
  {
    level: logging.logLevel,
    redact: ['req.headers.authorization'],
    enabled: logging.enabled,
    // Méthode appelée avant chaque log. Permet de fournir de l'info supplémentaire pour alimenter le log
    // Ici, on récupère les infos de corrélation
    mixin() {
      return getCorrelationContext();
    },
    // Juste après, il faut définir cette méthode pour lui expliquer quoi faire avec le truc retourné de mixin()
   // Ici je reproduis le comportement qu'il y avait dans les méthodes logErrorWithCorrelationId et logInfoWithCorrelationId
   // à savoir merger les deux objets et retirer la clé "message"
    mixinMergeStrategy(originalMessage, correlationContext) {
      return {
        ...correlationContext,
        ...originalMessage,
        message: undefined,
      };
    },
  },
  prettyPrint,
);

:rainbow: Remarques

J'ai gardé le même comportement qu'avant, et je suis repassée dans le code pour déplacer les paramètres "message" en deuxième argument d'appel des loggers comme le dit la doc (les méthodes logErrorWithCorrelationId et logInfoWithCorrelationId faisaient ce tour de passe-passe mais maintenant elles ne sont plus là !)

:100: Pour tester

Tester avec du code sur dév, capturer un log d'info et un log d'error émis depuis les "vieilles méthodes". Les reproduire sur cette branche et voir que c'est le même log

pix-bot-github commented 2 weeks ago

Une fois les applications déployées, elles seront accessibles via les liens suivants :

Les variables d'environnement seront accessibles via les liens suivants :

xav-car commented 1 week ago

{"level":50,"time":1725441595740,"pid":20,"hostname":"pix-api-review-pr10044-web-1","data":{"campaignParticipationId":163970},"handlerName":"ParticipationSharedJob","error":"Cannot read properties of undefined (reading 'info') (see dedicated log for more information)","type":"JOB_LOG_ERROR","jobId":"dcc48c59-5b9d-469b-a07d-942ccb0704ef"}

il doit manquer une injection du logger quelque part pour le job participation-shared-job-controller.js .

edit : maintenant c'est okay

xav-car commented 1 week ago

Func OK pour les Job FT :

2024-09-04 11:40:03.069390497 +0200 CEST[web-1] {"level":30,"time":1725442803068,"pid":21,"hostname":"pix-api-review-pr10044-web-1","event":"participation-send-pole-emploi","pole-emploi-action":"refresh-token","participation-state":"PARTICIPATION_STARTED","expired-date":"2024-08-21T08:21:10.797Z"}
2024-09-04 11:40:03.341975972 +0200 CEST[web-1] {"level":50,"time":1725442803341,"pid":21,"hostname":"pix-api-review-pr10044-web-1","metrics":{"responseTime":272.16076699999394},"msg":"End POST request to https://authentification-candidat-r.pe-qvr.fr/connexion/oauth2/access_token?realm=%2Findividu error: 400 {\"error_description\":\"grant is invalid\",\"error\":\"invalid_grant\"}"}

C'est normal de ne pas avoir le correlationId içi, c'est dans un job asynchrone ( donc sans utilisateur connecté )

xav-car commented 1 week ago

import en masse d'une orga :

Avant :

{"level":50,"time":1725444371686,"pid":21,"hostname":"pix-api-review-pr10035-web-1","context":"create-organizations-with-tags-and-target-profiles","event":"add-organizations-target-profiles","team":"acces","error":{"name":"DatabaseError"},"msg":"/* path: */ insert into \"target-profile-shares\" (\"organizationId\", \"targetProfileId\") values ($1, $2), ($3, $4), ($5, $6), ($7, $8), ($9, $10), ($11, $12), ($13, $14), ($15, $16) - insert or update on table \"target-profile-shares\" violates foreign key constraint \"target_profile_shares_targetprofileid_foreign\""}

{"level":50,"time":1725444128804,"pid":21,"hostname":"pix-api-review-pr10044-web-1","context":"create-organizations-with-tags-and-target-profiles","event":"add-organizations-target-profiles","team":"acces","error":{"name":"DatabaseError"},"msg":"/* path: */ insert into \"target-profile-shares\" (\"organizationId\", \"targetProfileId\") values ($1, $2), ($3, $4), ($5, $6), ($7, $8), ($9, $10), ($11, $12), ($13, $14), ($15, $16), ($17, $18), ($19, $20), ($21, $22), ($23, $24) - insert or update on table \"target-profile-shares\" violates foreign key constraint \"target_profile_shares_targetprofileid_foreign\""}

Par contre ni avant ni maintenant je vois le userId dans les log pour celui là 🤔 .

En activant sur la RA la var d'env ENABLE_REQUEST_MONITORING

{"level":50,"time":1725453767388,"pid":21,"hostname":"pix-api-review-pr10044-web-1","user_id":90000,"request_id":"5b777947-5db3-424c-8cb9-dd60d2005e32","id":"1725453767325:pix-api-review-pr10044-web-1:21:m0nulx30:10003","context":"create-organizations-with-tags-and-target-profiles","event":"add-organizations-target-profiles","team":"acces","error":{"name":"DatabaseError"},"msg":"/* path: /api/admin/organizations/import-csv */ insert into \"target-profile-shares\" (\"organizationId\", \"targetProfileId\") values ($1, $2), ($3, $4), ($5, $6), ($7, $8), ($9, $10), ($11, $12), ($13, $14), ($15, $16) - insert or update on table \"target-profile-shares\" violates foreign key constraint

c'est ok du coup :)

dlahaye commented 1 week ago

@laura-bergoens ça merge alors ?

1024pix / pix