test(bufflog): add a jest suite and a CI workflow

.github/workflows/ci.yml

@@ -0,0 +1,35 @@
+name: CI
+
+on:
+  pull_request:
+  push:
+    branches:
+      - main
+
+permissions:
+  contents: read
+
+jobs:
+  build-and-test:
+    name: node ${{ matrix.node-version }}
+    runs-on: ubuntu-latest
+    strategy:
+      fail-fast: false
+      matrix:
+        node-version:
+          - 18
+          - 20
+    steps:
+      - uses: actions/checkout@v7
+
+      - uses: actions/setup-node@v7
+        with:
+          node-version: ${{ matrix.node-version }}
+          cache: npm
+
+      - run: npm ci
+
+      # tsc is the regression gate for this package: it ships compiled types.
+      - run: npm run build
+
+      - run: npm test

.gitignore

@@ -8,3 +8,4 @@ coverage
 out
 dist
 *.tgz
+.worktrees

__tests__/bufflog.test.ts

@@ -0,0 +1,95 @@
+jest.mock('pino', () => {
+  const actualPino = jest.requireActual('pino')
+  const { sink } = require('./sink')
+  const pinoToSink = (options: object) => actualPino(options, sink)
+  return Object.assign(pinoToSink, actualPino)
+})
+
+import BuffLog from '../bufflog'
+import { lastLine, lines, reset } from './sink'
+
+const CENSOR = '[ REDACTED ]'
+
+describe('custom log levels', () => {
+  beforeEach(reset)
+
+  it('exposes only the six custom levels, with their numeric values', () => {
+    expect(BuffLog.getLogger().levels.values).toEqual({
+      debug: 100,
+      info: 200,
+      notice: 250,
+      warn: 300,
+      error: 400,
+      fatal: 500,
+    })
+  })
+
+  const cases: Array<[string, (message: string) => void, number]> = [
+    ['debug', BuffLog.debug, 100],
+    ['info', BuffLog.info, 200],
+    ['notice', BuffLog.notice, 250],
+    ['warning', BuffLog.warning, 300],
+    ['error', BuffLog.error, 400],
+    ['critical', BuffLog.critical, 500],
+  ]
+
+  cases.forEach(([name, log, level]) => {
+    it(`logs ${name} at level ${level}`, () => {
+      log(`hello ${name}`)
+
+      expect(lines).toHaveLength(1)
+      expect(lastLine().level).toBe(level)
+      // messageKey is overridden, so the text lands on "message", not "msg"
+      expect(lastLine().message).toBe(`hello ${name}`)
+      expect(lastLine().msg).toBeUndefined()
+    })
+  })
+})
+
+describe('redaction', () => {
+  beforeEach(reset)
+
+  it('redacts the whole req.headers object, cookie included', () => {
+    BuffLog.notice('request context', {
+      req: { headers: { cookie: 'buffer_session=secret' } },
+    })
+
+    expect(lastLine().context.req.headers).toBe(CENSOR)
+  })
+
+  it('redacts a password in the request body and query', () => {
+    BuffLog.notice('request context', {
+      req: {
+        body: { password: 'hunter2', email: 'joe@buffer.com' },
+        query: { password: 'hunter2' },
+      },
+    })
+
+    expect(lastLine().context.req.body.password).toBe(CENSOR)
+    expect(lastLine().context.req.query.password).toBe(CENSOR)
+    // redaction is path-scoped, so a sibling key survives
+    expect(lastLine().context.req.body.email).toBe('joe@buffer.com')
+  })
+
+  it('redacts every server key from constants.ts, on req and on res', () => {
+    const serverKeys = {
+      cookies: { buffer_session: 'secret' },
+      fresh: true,
+      secure: true,
+      signedCookies: { buffer_session: 'secret' },
+      stale: false,
+      xhr: true,
+      headers: { cookie: 'buffer_session=secret' },
+    }
+
+    BuffLog.notice('request and response context', {
+      req: serverKeys,
+      res: serverKeys,
+    })
+
+    Object.keys(serverKeys).forEach((key: string) => {
+      expect(lastLine().context.req[key]).toBe(CENSOR)
+      expect(lastLine().context.res[key]).toBe(CENSOR)
+    })
+  })
+})

__tests__/middleware.test.ts

@@ -0,0 +1,120 @@
+jest.mock('pino', () => {
+  const actualPino = jest.requireActual('pino')
+  const { sink } = require('./sink')
+  const pinoToSink = (options: object) => actualPino(options, sink)
+  return Object.assign(pinoToSink, actualPino)
+})
+
+import express from 'express'
+import * as http from 'http'
+import { AddressInfo } from 'net'
+import BuffLog from '../bufflog'
+import { LogLine, reset, waitForLine } from './sink'
+
+const CENSOR = '[ REDACTED ]'
+
+interface Response {
+  status: number
+  body: string
+}
+
+function get(port: number, path: string): Promise<Response> {
+  return new Promise((resolve, reject) => {
+    const request = http.get(
+      {
+        host: '127.0.0.1',
+        port,
+        path,
+        headers: { cookie: 'buffer_session=secret' },
+      },
+      (response) => {
+        let body = ''
+        response.setEncoding('utf8')
+        response.on('data', (chunk: string) => {
+          body += chunk
+        })
+        response.on('end', () =>
+          resolve({ status: response.statusCode || 0, body })
+        )
+      }
+    )
+    request.on('error', reject)
+  })
+}
+
+function completedRequest(url: string): (line: LogLine) => boolean {
+  return (line: LogLine) => Boolean(line.req) && line.req.url === url
+}
+
+describe('BuffLog.middleware()', () => {
+  let server: http.Server
+  let port: number
+
+  beforeAll(async () => {
+    const app = express()
+    app.use(BuffLog.middleware())
+    app.get('/ok', (_req, res) => {
+      res.send({ hello: 'world' })
+    })
+    app.get('/boom', (_req, res) => {
+      res.status(500).send({ message: 'This is an error 500!' })
+    })
+    app.get('/missing', (_req, res) => {
+      res.status(404).send({ message: 'This is a 404!' })
+    })
+
+    server = await new Promise((resolve) => {
+      const listening = app.listen(0, () => resolve(listening))
+    })
+    port = (server.address() as AddressInfo).port
+  })
+
+  afterAll(async () => {
+    await new Promise((resolve) => server.close(resolve))
+  })
+
+  beforeEach(reset)
+
+  it('passes the request through to the route handler', async () => {
+    const response = await get(port, '/ok')
+
+    expect(response.status).toBe(200)
+    expect(JSON.parse(response.body)).toEqual({ hello: 'world' })
+  })
+
+  it('logs the completed request at info, with a response time', async () => {
+    await get(port, '/ok')
+    const line = await waitForLine(completedRequest('/ok'))
+
+    expect(line.level).toBe(200)
+    expect(line.message).toBe('request completed')
+    expect(line.req.method).toBe('GET')
+    expect(line.res.statusCode).toBe(200)
+    expect(typeof line.responseTime).toBe('number')
+  })
+
+  it('redacts the request and response headers it logs', async () => {
+    await get(port, '/ok')
+    const line = await waitForLine(completedRequest('/ok'))
+
+    expect(line.req.headers).toBe(CENSOR)
+    expect(line.res.headers).toBe(CENSOR)
+  })
+
+  it('logs a 5xx at error level', async () => {
+    const response = await get(port, '/boom')
+    const line = await waitForLine(completedRequest('/boom'))
+
+    expect(response.status).toBe(500)
+    expect(line.level).toBe(400)
+    expect(line.res.statusCode).toBe(500)
+  })
+
+  it('logs a 4xx at info level', async () => {
+    const response = await get(port, '/missing')
+    const line = await waitForLine(completedRequest('/missing'))
+
+    expect(response.status).toBe(404)
+    expect(line.level).toBe(200)
+  })
+})

__tests__/setupEnv.ts

@@ -0,0 +1,3 @@
+// bufflog reads LOG_LEVEL once, at import time, and defaults to "notice".
+// The tests need the two levels below notice to reach the sink.
+process.env.LOG_LEVEL = 'debug'

__tests__/sink.ts

@@ -0,0 +1,55 @@
+import { Writable } from 'stream'
+
+export interface LogLine {
+  [key: string]: any
+}
+
+// bufflog builds its pino logger at import time and writes to stdout. The tests
+// mock the pino module so that logger writes here instead, which keeps the real
+// pino level and redaction config in play.
+export const lines: LogLine[] = []
+
+export const sink = new Writable({
+  write(
+    chunk: Buffer | string,
+    _encoding: BufferEncoding,
+    callback: (error?: Error | null) => void
+  ): void {
+    String(chunk)
+      .split('\n')
+      .filter((line: string) => line.length > 0)
+      .forEach((line: string) => lines.push(JSON.parse(line)))
+    callback()
+  },
+})
+
+export function reset(): void {
+  lines.length = 0
+}
+
+export function lastLine(): LogLine {
+  return lines[lines.length - 1]
+}
+
+export function findLine(
+  predicate: (line: LogLine) => boolean
+): LogLine | undefined {
+  return lines.filter(predicate)[0]
+}
+
+// The middleware logs on the response "finish" event, which can land after the
+// client has already seen the end of the response.
+export async function waitForLine(
+  predicate: (line: LogLine) => boolean,
+  timeoutMs: number = 1000
+): Promise<LogLine> {
+  const deadline = Date.now() + timeoutMs
+  while (Date.now() < deadline) {
+    const match = findLine(predicate)
+    if (match) {
+      return match
+    }
+    await new Promise((resolve) => setTimeout(resolve, 5))
+  }
+  throw new Error('timed out waiting for a matching log line')
+}

jest.config.js

@@ -0,0 +1,8 @@
+/** @type {import('ts-jest').JestConfigWithTsJest} */
+module.exports = {
+  preset: 'ts-jest',
+  testEnvironment: 'node',
+  // Only *.test.ts are tests; the other files in __tests__ are helpers.
+  testMatch: ['<rootDir>/__tests__/**/*.test.ts'],
+  setupFiles: ['<rootDir>/__tests__/setupEnv.ts'],
+}