Genarrative/server-node/src/observability.test.ts

import assert from 'node:assert/strict';
import fs from 'node:fs';
import type { AddressInfo } from 'node:net';
import os from 'node:os';
import path from 'node:path';
import { Writable } from 'node:stream';
import test from 'node:test';

import pino, { type Logger } from 'pino';

import { createApp } from './app.ts';
import type { AppConfig } from './config.ts';
import { createAppContext } from './server.ts';
import { httpRequest } from './testHttp.ts';

type LogRecord = Record<string, unknown>;

function createTestConfig(testName: string): AppConfig {
  const tempRoot = fs.mkdtempSync(
    path.join(os.tmpdir(), `genarrative-server-node-${testName}-`),
  );

  return {
    nodeEnv: 'test',
    projectRoot: tempRoot,
    publicDir: path.join(tempRoot, 'public'),
    logsDir: path.join(tempRoot, 'logs'),
    dataDir: path.join(tempRoot, 'data'),
    rawEnv: {},
    databaseUrl: `pg-mem://genarrative-${testName}`,
    serverAddr: ':0',
    logLevel: 'silent',
    editorApiEnabled: true,
    assetsApiEnabled: true,
    jwtSecret: 'test-secret',
    jwtExpiresIn: '7d',
    jwtIssuer: 'genarrative-server-node-test',
    llm: {
      baseUrl: 'https://example.invalid',
      apiKey: '',
      model: 'test-model',
    },
    dashScope: {
      baseUrl: 'https://example.invalid',
      apiKey: '',
      imageModel: 'test-image-model',
      requestTimeoutMs: 1000,
    },
    smsAuth: {
      enabled: true,
      provider: 'mock',
      endpoint: 'dypnsapi.aliyuncs.com',
      accessKeyId: '',
      accessKeySecret: '',
      signName: 'Test Sign',
      templateCode: '100001',
      templateParamKey: 'code',
      countryCode: '86',
      schemeName: '',
      codeLength: 6,
      codeType: 1,
      validTimeSeconds: 300,
      intervalSeconds: 60,
      duplicatePolicy: 1,
      caseAuthPolicy: 1,
      returnVerifyCode: false,
      mockVerifyCode: '123456',
      maxSendPerPhonePerDay: 20,
      maxSendPerIpPerHour: 30,
      maxVerifyFailuresPerPhonePerHour: 12,
      maxVerifyFailuresPerIpPerHour: 24,
      captchaTtlSeconds: 180,
      captchaTriggerVerifyFailuresPerPhone: 3,
      captchaTriggerVerifyFailuresPerIp: 5,
      blockPhoneFailureThreshold: 6,
      blockIpFailureThreshold: 10,
      blockPhoneDurationMinutes: 30,
      blockIpDurationMinutes: 30,
    },
    wechatAuth: {
      enabled: true,
      provider: 'mock',
      appId: '',
      appSecret: '',
      authorizeEndpoint: 'https://open.weixin.qq.com/connect/qrconnect',
      accessTokenEndpoint: 'https://api.weixin.qq.com/sns/oauth2/access_token',
      userInfoEndpoint: 'https://api.weixin.qq.com/sns/userinfo',
      callbackPath: '/api/auth/wechat/callback',
      defaultRedirectPath: '/',
      mockUserId: 'mock_wechat_user',
      mockUnionId: 'mock_wechat_union',
      mockDisplayName: '微信旅人',
      mockAvatarUrl: '',
    },
    authSession: {
      accessCookieName: 'genarrative_access_session',
      accessCookieTtlSeconds: 7200,
      accessCookieSecure: false,
      accessCookieSameSite: 'Lax',
      accessCookiePath: '/',
      refreshCookieName: 'genarrative_refresh_session',
      refreshSessionTtlDays: 30,
      refreshCookieSecure: false,
      refreshCookieSameSite: 'Lax',
      refreshCookiePath: '/api/auth',
    },
  };
}

function createLogCollector() {
  const records: LogRecord[] = [];
  let buffer = '';

  const destination = new Writable({
    write(chunk, _encoding, callback) {
      buffer += chunk.toString('utf8');

      let newlineIndex = buffer.indexOf('\n');
      while (newlineIndex >= 0) {
        const line = buffer.slice(0, newlineIndex).trim();
        buffer = buffer.slice(newlineIndex + 1);

        if (line) {
          records.push(JSON.parse(line) as LogRecord);
        }

        newlineIndex = buffer.indexOf('\n');
      }

      callback();
    },
  });

  return {
    logger: pino(
      {
        level: 'info',
        base: undefined,
        timestamp: false,
      },
      destination,
    ) as Logger,
    records,
  };
}

async function withTestServer<T>(
  testName: string,
  logger: Logger,
  run: (options: { baseUrl: string }) => Promise<T>,
) {
  const context = await createAppContext(createTestConfig(testName));
  context.logger = logger;
  const app = createApp(context);
  const server = await new Promise<import('node:http').Server>((resolve) => {
    const nextServer = app.listen(0, '127.0.0.1', () => resolve(nextServer));
  });

  try {
    const address = server.address() as AddressInfo;
    return await run({
      baseUrl: `http://127.0.0.1:${address.port}`,
    });
  } finally {
    await new Promise<void>((resolve, reject) => {
      server.close((error) => {
        if (error) {
          reject(error);
          return;
        }
        resolve();
      });
    });
    await context.db.close();
  }
}

async function waitForRecord(
  records: LogRecord[],
  predicate: (record: LogRecord) => boolean,
  timeoutMs = 2000,
) {
  const deadline = Date.now() + timeoutMs;

  while (Date.now() < deadline) {
    const match = records.find(predicate);
    if (match) {
      return match;
    }
    await new Promise((resolve) => setTimeout(resolve, 20));
  }

  assert.fail('Timed out waiting for log record');
}

test('healthz echoes x-request-id and writes access log fields', async () => {
  const { logger, records } = createLogCollector();

  await withTestServer('observability-healthz', logger, async ({ baseUrl }) => {
    const requestId = 'obs-healthz-request';
    const response = await httpRequest(`${baseUrl}/healthz`, {
      headers: {
        'X-Request-Id': requestId,
      },
    });
    const payload = (await response.json()) as {
      ok: boolean;
      service: string;
    };

    assert.equal(response.status, 200);
    assert.equal(response.headers.get('x-request-id'), requestId);
    assert.equal(payload.ok, true);
    assert.equal(payload.service, 'genarrative-node-server');

    const accessLog = await waitForRecord(
      records,
      (record) =>
        record.request_id === requestId &&
        record.path === '/healthz' &&
        record.status === 200,
    );

    assert.equal(accessLog.method, 'GET');
    assert.equal(accessLog.user_id, null);
    assert.equal(accessLog.api_version, '2026-04-08');
    assert.equal(accessLog.route_version, '2026-04-08');
    assert.equal(accessLog.operation, 'health.check');
    assert.equal(typeof accessLog.latency_ms, 'number');
  });
});

test('unauthorized request keeps request trace in error log and response header', async () => {
  const { logger, records } = createLogCollector();

  await withTestServer(
    'observability-unauthorized',
    logger,
    async ({ baseUrl }) => {
      const requestId = 'obs-unauthorized-request';
      const response = await httpRequest(`${baseUrl}/api/auth/me`, {
        headers: {
          'X-Request-Id': requestId,
        },
      });
      const payload = (await response.json()) as {
        error: {
          message: string;
        };
      };

      assert.equal(response.status, 401);
      assert.equal(response.headers.get('x-request-id'), requestId);
      assert.equal(payload.error.message, '缺少 Authorization Bearer Token');

      const errorLog = await waitForRecord(
        records,
        (record) =>
          record.msg === 'request failed' && record.request_id === requestId,
      );

      assert.equal(errorLog.user_id, null);
      assert.equal(
        (errorLog.err as { message?: string } | undefined)?.message,
        '缺少 Authorization Bearer Token',
      );
      assert.equal(errorLog.api_version, '2026-04-08');
      assert.equal(errorLog.route_version, '2026-04-08');
      assert.equal(errorLog.operation, 'auth.me');

      const accessLog = await waitForRecord(
        records,
        (record) =>
          record.request_id === requestId &&
          record.path === '/api/auth/me' &&
          record.status === 401,
      );

      assert.equal(accessLog.method, 'GET');
      assert.equal(accessLog.api_version, '2026-04-08');
      assert.equal(accessLog.route_version, '2026-04-08');
      assert.equal(accessLog.operation, 'auth.me');
      assert.equal(typeof accessLog.latency_ms, 'number');
    },
  );
});