d · Santé, journaux et arrêt propre

Project: Werewolf
About 65 minutes
3 exercises

This content is not available in your language yet.

Une fois en production, ton API n’a plus personne devant elle. Trois questions se posent alors, qu’on se pose d’habitude en regardant la console : est-ce qu’elle va bien ? que s’est-il passé à 3 h 12 ? et que devient la partie en cours quand on la redémarre pour une mise à jour ? Cette section donne une réponse que des programmes peuvent lire : l’orchestrateur (Docker Compose, plus tard Kubernetes en partie 12), l’outil qui collecte les journaux, et le système qui arrête les conteneurs.

Vivant, et prêt

La route /sante de la partie 8 répond { "statut": "ok" } dès que le serveur tourne. C’est utile, mais ça ne dit pas tout : un serveur qui tourne peut très bien avoir perdu sa base. On distingue deux questions :

Vivant (liveness) : le processus répond-il ? Si non, le redémarrer a un sens.
Prêt (readiness) : peut-il servir des requêtes, avec sa base et son Redis ? Si non, il faut ne plus lui envoyer de trafic, mais le redémarrer ne servirait à rien : ce n’est pas lui qui est en panne.

Mélanger les deux est une erreur classique. Une route « vivant » qui vérifie la base fait redémarrer l’API en boucle pendant une panne de PostgreSQL, sans rien réparer. On garde donc /sante telle quelle (vivant, sans rien vérifier) et on ajoute /sante/pret.

npm install @nestjs/terminus

@nestjs/terminus fournit des vérifications toutes faites (la base TypeORM, la mémoire, le disque…) et une façon uniforme de les combiner.

import { Controller, Get, Inject, UseFilters } from '@nestjs/common';
import { HealthCheck, HealthCheckService, HealthIndicatorService, TypeOrmHealthIndicator } from '@nestjs/terminus';
import { SkipThrottle } from '@nestjs/throttler';
import { Redis } from 'ioredis';
import { Public } from '../auth/public.decorator.js';
import { REDIS } from '../redis/redis.module.js';
import { SanteFilter } from './sante.filter.js';

@Public()
@SkipThrottle()
@UseFilters(SanteFilter)
@Controller('sante')
export class SanteController {
  constructor(
    private readonly sante: HealthCheckService,
    private readonly base: TypeOrmHealthIndicator,
    private readonly indicateurs: HealthIndicatorService,
    @Inject(REDIS) private readonly redis: Redis,
  ) {}

  @Get()
  vivant() {
    return { statut: 'ok' };
  }

  @Get('pret')
  @HealthCheck()
  pret() {
    return this.sante.check([
      () => this.base.pingCheck('base').withTimeout(1000),
      () => this.indicateurs.check('redis').attempt(async () => {
        await this.redis.ping();
      }).withTimeout(1000),
    ]);
  }
}

import { Module } from '@nestjs/common';
import { TerminusModule } from '@nestjs/terminus';
import { SanteController } from './sante.controller.js';

@Module({
  imports: [TerminusModule],
  controllers: [SanteController],
})
export class SanteModule {}

Importe SanteModule dans AppModule, et retire l’ancien contrôleur sante de la partie 8.

Lignes 29 à 33 : check lance les vérifications et rassemble leurs résultats. pingCheck envoie une requête minimale à la base (SELECT 1) ; pour Redis, qui n’a pas de vérification toute faite, attempt exécute une fonction : si elle lève une erreur, Redis est déclaré down. withTimeout(1000) compte aussi comme un échec une réponse qui met plus d’une seconde : une base qui répond en dix secondes n’est pas prête.
Lignes 9 à 11 : trois décorateurs sur toute la classe, qui corrigent chacun un problème qu’on a rencontré, détaillés plus bas.

Quand tout va bien, /sante/pret répond 200 :

{
  "status": "ok",
  "info": { "base": { "responseTime": 2, "status": "up" }, "redis": { "responseTime": 1, "status": "up" } },
  "error": {},
  "details": { "base": { "responseTime": 2, "status": "up" }, "redis": { "responseTime": 1, "status": "up" } }
}

Et après docker compose kill db, 503, avec la cause :

{
  "status": "error",
  "info": { "redis": { "responseTime": 4, "status": "up" } },
  "error": { "base": { "message": "getaddrinfo ENOTFOUND db", "responseTime": 96, "status": "down" } },
  "details": { "…": "…" }
}

Pendant ce temps, /sante répond toujours 200 : le processus va bien. Le healthcheck de la section c appelle /sante/pret : une trentaine de secondes après l’arrêt de la base (trois échecs espacés de dix secondes), docker compose ps affiche l’API en unhealthy, sans la redémarrer ; au retour de la base, elle redevient healthy toute seule, et les villages sont toujours là (le volume).

Trois pièges, trois décorateurs

Sans les lignes 9 à 11, on a observé trois comportements faux.

Le filtre d’exceptions avale le détail. Quand une vérification échoue, Terminus lève une ServiceUnavailableException qui contient tout le rapport. Le ToutesExceptionsFilter de la partie 8 attrape toutes les exceptions et n’en garde que le message, absent ici. Résultat, avec la base coupée :

{ "statusCode": 503, "message": "Service Unavailable Exception", "chemin": "/sante/pret", "…": "…" }

Impossible de savoir ce qui est tombé. La partie 8 l’a montré : quand plusieurs filtres sont possibles, le plus précis gagne. Un filtre posé sur le contrôleur, qui ne traite que cette exception, rend le rapport tel quel :

import { ArgumentsHost, Catch, ExceptionFilter, ServiceUnavailableException } from '@nestjs/common';
import type { Response } from 'express';

@Catch(ServiceUnavailableException)
export class SanteFilter implements ExceptionFilter {
  catch(exception: ServiceUnavailableException, hote: ArgumentsHost) {
    hote.switchToHttp().getResponse<Response>().status(503).json(exception.getResponse());
  }
}

Le rapport nomme les composants et leur erreur (getaddrinfo ENOTFOUND db), sans mot de passe ni requête SQL. Si ta route de santé est accessible depuis Internet, demande-toi quand même si tu veux publier ces détails.

La limitation de débit s’applique à la santé. Le guard global de la partie 7 compte aussi les appels à /sante (les réponses portaient un en-tête X-RateLimit-Limit). Un orchestrateur qui interroge la route toutes les dix secondes n’est pas un abus. Surtout, depuis que les compteurs sont dans Redis, Redis arrêté faisait répondre /sante en 500 : le guard échouait avant même d’atteindre la route. La route « vivant » disait donc « mort » à cause de Redis : exactement l’erreur décrite plus haut. @SkipThrottle() la sort de la limitation.

Le middleware ne l’exclut qu’à moitié. En partie 8, on a exclu /sante du RequeteIdMiddleware, pour ne pas remplir les journaux d’un appel toutes les dix secondes. Mais exclude compare le chemin exactement : /sante/pret recevait un identifiant et une ligne de journal. On a essayé trois écritures :

`exclude(…)`	`/sante`	`/sante/pret`
`{ path: 'sante', … }` (partie 8)	exclue	journalisée
`'sante/{*reste}'`	journalisée	exclue
`{ path: 'sante{/*reste}', method: RequestMethod.GET }`	exclue	exclue

Les accolades rendent la suite facultative : sante, suivi ou non d’un / et du reste. L’ancienne écriture 'sante/*', elle, déclenche un avertissement de l’Express 5 de NestJS 12 (Unsupported route path: "/sante/*") et n’exclut pas /sante.

consumer.apply(RequeteIdMiddleware).exclude({ path: 'sante{/*reste}', method: RequestMethod.GET }).forRoutes('*');

Tester

describe('Santé (e2e)', () => {
  let app: INestApplication;
  const journal = vi.fn();
  const http = () => request(app.getHttpServer());

  beforeAll(async () => {
    const module = await Test.createTestingModule({ imports: [AppModule] }).compile();
    app = module.createNestApplication();
    app.useLogger({ log: journal, warn: vi.fn(), error: vi.fn() });
    configurerApp(app);
    await app.init();
  });

  afterAll(async () => {
    await app.close();
  });

  it('vivant : 200 sans jeton, sans rien vérifier', async () => {
    const reponse = await http().get('/sante').expect(200);
    expect(reponse.body).toEqual({ statut: 'ok' });
  });

  it('prêt : 200 quand la base et Redis répondent', async () => {
    const reponse = await http().get('/sante/pret').expect(200);
    expect(reponse.body).toMatchObject({ status: 'ok', info: { base: { status: 'up' }, redis: { status: 'up' } } });
  });

  it('n\'est ni limité, ni identifié, ni journalisé', async () => {
    const reponse = await http().get('/sante/pret');
    expect(reponse.headers['x-ratelimit-limit']).toBeUndefined();
    expect(reponse.headers['x-request-id']).toBeUndefined();
    expect(journal).not.toHaveBeenCalledWith(expect.stringContaining('/sante'), expect.anything(), 'HTTP');
  });

  it('prêt : 503 et le détail quand la base est coupée ; vivant reste à 200', async () => {
    await app.get(DataSource).destroy();
    const reponse = await http().get('/sante/pret').expect(503);
    expect(reponse.body).toMatchObject({ status: 'error', error: { base: { status: 'down' } }, info: { redis: { status: 'up' } } });
    await http().get('/sante').expect(200);
    await app.get(DataSource).initialize();
  });
});

Pour simuler une panne de la base sans arrêter PostgreSQL, le dernier test ferme la connexion de l’application (destroy), puis la rouvre (initialize) pour ne pas gêner la suite.

Des journaux JSON

En développement, tu lis les journaux. En production, ce sont des outils qui les lisent : ils les collectent, les indexent, et te laissent chercher « toutes les erreurs de l’identifiant abc-123 ». Une ligne de texte comme GET /api/villages 200 3 ms [abc-123] oblige à deviner où est chaque information. Une ligne JSON les nomme. Le logger de NestJS sait écrire en JSON :

import { ConsoleLogger } from '@nestjs/common';

export function creerLogger(production: boolean) {
  return new ConsoleLogger({
    json: production,
    logLevels: production ? ['log', 'warn', 'error', 'fatal'] : ['verbose', 'debug', 'log', 'warn', 'error', 'fatal'],
  });
}

async function bootstrap() {
  const production = process.env.NODE_ENV === 'production';
  const app = await NestFactory.create(AppModule, { logger: creerLogger(production) });
  configurerApp(app);
  if (!production) configurerSwagger(app);
  app.enableShutdownHooks();
  const config = app.get(ConfigService);
  await app.listen(config.get('PORT') ?? 3000);
}

json: production : du JSON en production, le texte coloré habituel sur ta machine.
logLevels : les niveaux à écrire. Du plus bavard au plus grave : verbose, debug, log, warn, error, fatal. En production, on coupe verbose et debug, qui servent à chercher un problème sur ta machine et noieraient le reste.
Le logger est passé à NestFactory.create : tous les new Logger(...) de ton code, et ceux de NestJS lui-même, l’utilisent.

Pour que l’identifiant de requête soit un champ, et pas seulement du texte dans le message, le RequeteIdMiddleware de la partie 8 passe un second argument au logger :

reponse.on('finish', () => {
  const duree = Math.round(performance.now() - debut);
  this.logger.log(`${requete.method} ${requete.originalUrl} ${reponse.statusCode} ${duree} ms [${id}]`, {
    requeteId: id,
    methode: requete.method,
    url: requete.originalUrl,
    statut: reponse.statusCode,
    dureeMs: duree,
  });
});

Voici une vraie ligne, lue dans docker compose logs api :

{"level":"log","pid":1,"timestamp":1790342248329,"message":"POST /api/villages 201 7 ms [abc-123]","context":"HTTP","params":{"requeteId":"abc-123","methode":"POST","url":"/api/villages","statut":201,"dureeMs":7}}

Une ligne par événement, le niveau, l’heure (en millisecondes depuis 1970), le contexte (HTTP, le nom donné à new Logger('HTTP')), et les paramètres sous params. Une erreur 500 journalisée par le ToutesExceptionsFilter de la partie 8 porte en plus un champ stack avec la pile d’appels. pid vaut 1 : dans le conteneur, node est le premier processus (on y revient plus bas).

Ce second argument change la façon dont le logger est appelé, et le test de la partie 8 (toHaveBeenCalledWith(…, 'HTTP')) échoue : le faux logger reçoit maintenant trois arguments, le message, les paramètres, puis 'HTTP'. On met l’assertion à jour :

await vi.waitFor(() => {
  expect(journal).toHaveBeenCalledWith(
    expect.stringMatching(/^GET \/inconnue 404 \d+ ms \[abc-123\]$/),
    expect.objectContaining({ requeteId: 'abc-123', statut: 404 }),
    'HTTP',
  );
});

Et le format se teste sans application, en interceptant ce que le logger écrit sur la sortie standard :

import { creerLogger } from './journal.js';

describe('creerLogger', () => {
  let ecrit: string[];

  beforeEach(() => {
    ecrit = [];
    vi.spyOn(process.stdout, 'write').mockImplementation((texte) => {
      ecrit.push(String(texte));
      return true;
    });
  });

  afterEach(() => {
    vi.restoreAllMocks();
  });

  it('en production, écrit une ligne JSON par message, avec le contexte et les paramètres', () => {
    creerLogger(true).log('GET /api/villages 200 3 ms [abc-123]', { requeteId: 'abc-123', statut: 200 }, 'HTTP');

    expect(ecrit).toHaveLength(1);
    expect(JSON.parse(ecrit[0]!)).toEqual({
      level: 'log',
      pid: process.pid,
      timestamp: expect.any(Number),
      message: 'GET /api/villages 200 3 ms [abc-123]',
      context: 'HTTP',
      params: { requeteId: 'abc-123', statut: 200 },
    });
  });

  it('en production, ignore les niveaux debug et verbose', () => {
    const logger = creerLogger(true);
    logger.debug('détail', 'Test');
    logger.verbose('encore plus de détail', 'Test');
    expect(ecrit).toHaveLength(0);
  });

  it('en développement, écrit du texte, pas du JSON', () => {
    creerLogger(false).log('bonjour', 'Test');
    expect(() => JSON.parse(ecrit[0]!)).toThrow();
    expect(ecrit[0]).toContain('bonjour');
  });
});

Espionner process.stdout.write ne pose pas le problème de la partie 8 (espionner Logger.prototype cassait NestJS) : on ne touche pas au logger, seulement à l’endroit où il écrit.

S’arrêter sans couper

Pour arrêter un conteneur (docker compose stop, un déploiement, un redémarrage du serveur), Docker envoie le signal SIGTERM au premier processus du conteneur, attend, puis, s’il tourne encore, le tue avec SIGKILL, qu’aucun programme ne peut intercepter. Entre les deux, l’application doit : refuser les nouvelles requêtes, terminer celles en cours, fermer ses connexions à la base et à Redis, puis s’arrêter.

C’est ce que fait NestJS avec app.enableShutdownHooks() (section a). Pour le voir, une route qui simule un long traitement, et qui lit la base à la fin :

@Controller('api/demo')
export class DemoController {
  constructor(private readonly dataSource: DataSource) {}

  @Get('lente')
  async lente() {
    await new Promise((resoudre) => setTimeout(resoudre, 5000));
    const [{ total }] = await this.dataSource.query('SELECT count(*)::int AS total FROM villages');
    return { termine: true, villages: total };
  }
}

Et un message au moment où le signal arrive, grâce à un hook (une méthode que NestJS appelle à un moment précis de la vie de l’application, comme onApplicationShutdown du module Redis) :

export class AppModule implements NestModule, BeforeApplicationShutdown {
  private readonly logger = new Logger('Arret');

  beforeApplicationShutdown(signal?: string) {
    this.logger.log(`Signal ${signal} reçu : fin des requêtes en cours, puis arrêt`);
  }
  // … configure(consumer) comme avant
}

On lance GET /api/demo/lente (avec un jeton, la route n’est pas publique), et une seconde plus tard on arrête le conteneur (docker stop, ce que fait aussi docker compose stop). Voici ce qu’on a mesuré :

Situation	La requête lente	L’arrêt
`enableShutdownHooks()`, `CMD ["node", "dist/main.js"]`	terminée : `200` en 5,02 s, lecture en base comprise	4,1 s, code de sortie `0`
Sans `enableShutdownHooks()`	terminée : `200`	10,2 s, code `137` (tué par `SIGKILL`)
Avec, mais `docker stop -t 2` (2 s de délai)	coupée : `Empty reply from server`	2,2 s, code `137`
Avec, mais `CMD ["npm", "run", "start:prod"]`	terminée : `200`	4,7 s, code `1`, et des lignes `npm error`

Ce qu’il faut en retenir :

Avec enableShutdownHooks(), le journal affiche Signal SIGTERM reçu…, le serveur n’accepte plus de nouvelles connexions (hors Docker, une requête envoyée juste après le signal a été refusée : c’est voulu, un autre conteneur doit la recevoir), et la requête en cours va au bout, y compris sa requête SQL : la connexion à la base n’est fermée qu’après la dernière réponse, par les hooks onApplicationShutdown (celui de TypeORM, et celui du module Redis de la section c). Puis le processus se termine proprement.
Sans, le résultat surprend. Dans le conteneur, node est le processus numéro 1, et Linux traite ce processus à part : un signal pour lequel il n’a prévu aucune réaction est ignoré. Le SIGTERM ne fait donc rien, Docker attend ses 10 secondes, puis tue tout avec SIGKILL. Ici, la requête de 5 secondes a eu le temps de finir, mais chaque arrêt coûte 10 secondes, et une requête plus longue serait coupée net. Hors conteneur, c’est l’inverse : le même SIGTERM a tué node immédiatement, et curl n’a reçu aucune réponse.
Le délai compte. Docker attend 10 secondes par défaut avant SIGKILL. Si tes requêtes peuvent durer plus longtemps, allonge-le dans le service api du docker-compose.yml avec stop_grace_period: 30s.
Pas de npm pour lancer. Avec npm run start:prod, c’est npm le premier processus. Il transmet bien le signal à node, mais sort avec le code 1 et écrit des lignes qui ne sont pas du JSON (npm error signal SIGTERM, npm error command sh -c node dist/main), et un outil de surveillance y voit un plantage. D’où le CMD ["node", "dist/main.js"] de la section b, et le pid: 1 dans les journaux.

Exercises 10.10 to 10.12

Project: marketplace

10.10: Vivant et prêt

Installe @nestjs/terminus et ajoute à ta marketplace GET /sante/pret (base et Redis), en gardant GET /sante de l’exercice 8.6, avec SanteFilter, @SkipThrottle() et l’exclusion sante{/*reste} du middleware. Écris test/sante.e2e-spec.ts : /sante/pret répond 200 avec status: 'ok', sans en-têtes X-RateLimit-Limit ni X-Request-Id (lance ce test avec THROTTLE_ACTIF=true : limitation coupée, l’absence de l’en-tête ne prouve rien) ; après destroy() de la DataSource, 503 avec error.base.status à down, et /sante toujours à 200. Attention à l’enveloppe du 8.13 : la réponse 200 arrive sous data (reponse.body.data.status), pas la 503, qui passe par le filtre. Remets /sante/pret dans le healthcheck de ton compose.yaml (exercice 10.7).

10.11: Des journaux JSON

Ajoute creerLogger et passe-le à NestFactory.create. Fais passer à ton RequeteIdMiddleware (exercice 8.4) les paramètres requeteId, methode, url, statut et dureeMs, puis corrige le test de l’exercice 8.5, qui doit échouer avant ta correction. Écris src/journal.spec.ts (une ligne JSON avec context et params en production, rien pour debug en production, du texte en développement). Enfin, avec Compose, envoie curl -H 'X-Request-Id: essai-10-11' http://localhost:3000/api/produits et retrouve la ligne avec docker compose logs api | grep essai-10-11.

10.12: Arrêter sans couper

Ajoute à ta marketplace GET /api/demo/longue : attend 5 secondes, puis compte les produits en base et renvoie { termine: true, produits: N } (sans l’interceptor de délai de l’exercice 8.12). Avec Compose, lance-la puis, une seconde plus tard, docker compose stop api : la requête doit recevoir 200 et le journal contenir ton message BeforeApplicationShutdown. Recommence sans enableShutdownHooks() : relève la durée de l’arrêt et le code de sortie (docker inspect --format '{{.State.ExitCode}}'). Recommence enfin avec docker compose stop -t 2 api : cette fois la requête est coupée, et curl doit afficher Empty reply from server. Remets tout, et ajoute stop_grace_period: 30s au service api.

To check your work: npm run test:partie-10 (exercises repository)