structured-logging（结构化日志记录）

Structured Logging

Best practices for production-ready logging in Node.js applications using Pino and structured JSON output.

Philosophy

Logs are data, not text. Structured logging treats every log entry as a queryable data point, enabling powerful analysis, alerting, and debugging in production.

Three core principles:

1. Machine-readable first: JSON structure enables programmatic querying
2. Context-rich: Include all relevant metadata (correlation IDs, user IDs, request info)
3. Security-conscious: Never log sensitive data (passwords, tokens, PII)

Why Pino

Pino is the recommended logging library for Node.js (2025):

• 5x faster than Winston: Minimal CPU overhead, async by default
• Structured JSON: Every log is a JSON object, no string templates
• Low latency: Critical for high-throughput applications
• Async transports: Heavy operations (file writes, network calls) happen in worker threads
• Child loggers: Easy context propagation
• Redaction built-in: Automatic sensitive data removal

Performance Comparison

Installation & Setup

# Install Pino and pretty-printing for development
pnpm add pino
pnpm add -D pino-pretty

Basic Configuration

// lib/logger.ts
import pino from 'pino'

const isDevelopment = process.env.NODE_ENV === 'development'

export const logger = pino({
  level: process.env.LOG_LEVEL || 'info',

  // Use pretty printing in development, JSON in production
  transport: isDevelopment
    ? {
        target: 'pino-pretty',
        options: {
          colorize: true,
          translateTime: 'SYS:standard',
          ignore: 'pid,hostname',
        },
      }
    : undefined,

  // Base context included in every log
  base: {
    env: process.env.NODE_ENV || 'development',
    revision: process.env.VERCEL_GIT_COMMIT_SHA || 'local',
  },

  // Format timestamps as ISO 8601
  timestamp: pino.stdTimeFunctions.isoTime,

  // Redact sensitive fields automatically
  redact: {
    paths: [
      'password',
      'passwordHash',
      'secret',
      'apiKey',
      'token',
      'accessToken',
      'refreshToken',
      'authorization',
      'cookie',
      'req.headers.authorization',
      'req.headers.cookie',
      '*.password',
      '*.passwordHash',
      '*.secret',
      '*.apiKey',
      '*.token',
    ],
    censor: '[REDACTED]',
  },
})

// Export type for use in application
export type Logger = typeof logger

Log Levels

Pino supports six log levels (from lowest to highest):

logger.trace('Extremely detailed debugging')  // Level 10
logger.debug('Detailed debugging')            // Level 20
logger.info('General information')            // Level 30
logger.warn('Warning, non-critical issue')    // Level 40
logger.error('Error, requires attention')     // Level 50
logger.fatal('Fatal error, app cannot continue') // Level 60

When to use each level:

• trace: Function entry/exit, loop iterations (extremely verbose)
• debug: Variable values, conditional branches, algorithm steps
• info: HTTP requests, user actions, state changes, startup/shutdown
• warn: Deprecated API usage, retry attempts, degraded performance
• error: Exceptions caught, failed operations, data validation errors
• fatal: Database connection lost, critical service unavailable, unrecoverable errors

Production recommendation: Set LOG_LEVEL=info by default, use debug or trace only when debugging specific issues.

Child Loggers (Context Propagation)

Create child loggers to add context that persists across multiple log statements:

// Without child logger (repetitive)
logger.info({ userId: '123', requestId: 'abc' }, 'User logged in')
logger.info({ userId: '123', requestId: 'abc' }, 'Profile fetched')
logger.info({ userId: '123', requestId: 'abc' }, 'Settings updated')

// With child logger (clean)
const requestLogger = logger.child({ userId: '123', requestId: 'abc' })
requestLogger.info('User logged in')
requestLogger.info('Profile fetched')
requestLogger.info('Settings updated')

Middleware Pattern (Express/Next.js)

// middleware/logging.ts
import { v4 as uuidv4 } from 'uuid'
import { logger } from '@/lib/logger'
import type { NextRequest } from 'next/server'

export function createRequestLogger(req: NextRequest) {
  // Generate correlation ID for request tracing
  const correlationId = req.headers.get('x-correlation-id') || uuidv4()

  // Create child logger with request context
  return logger.child({
    correlationId,
    method: req.method,
    path: req.nextUrl.pathname,
    userAgent: req.headers.get('user-agent'),
    ip: req.headers.get('x-forwarded-for') || req.headers.get('x-real-ip'),
  })
}

// Usage in API route
export async function GET(req: NextRequest) {
  const log = createRequestLogger(req)

  log.info('Processing request')

  try {
    const data = await fetchData()
    log.info({ dataCount: data.length }, 'Data fetched successfully')
    return Response.json(data)
  } catch (error) {
    log.error({ error }, 'Failed to fetch data')
    return Response.json({ error: 'Internal error' }, { status: 500 })
  }
}

Structured Logging Patterns

✅ Good: Structured Fields

// Queryable, analyzable
logger.info({
  event: 'user_login',
  userId: user.id,
  email: user.email,
  provider: 'google',
  duration: 150,
}, 'User authenticated')

// Easy queries:
// - All Google logins: event='user_login' AND provider='google'
// - Slow logins: event='user_login' AND duration > 1000
// - Specific user: event='user_login' AND userId='123'

❌ Bad: String Templates

// Not queryable, hard to parse
logger.info(`User ${user.email} logged in via ${provider} in ${duration}ms`)

// Cannot easily query by provider or filter by duration

Error Logging

// ✅ Good: Include error object with structured context
try {
  await riskyOperation()
} catch (error) {
  logger.error({
    error,
    operation: 'riskyOperation',
    userId: user.id,
    retryCount: 3,
  }, 'Operation failed after retries')
}

// ❌ Bad: Lose stack trace and context
try {
  await riskyOperation()
} catch (error) {
  logger.error(`Operation failed: ${error.message}`)
}

Note on Error serialization: Pino handles Error objects natively, but JSON.stringify(new Error("msg")) returns {} because message, name, stack are non-enumerable. For custom loggers, manually extract:

function serializeError(err: unknown): Record<string, unknown> {
  if (err instanceof Error) {
    return { name: err.name, message: err.message, stack: err.stack };
  }
  return { value: String(err) };
}

Performance Logging

// Track operation duration
const startTime = Date.now()

try {
  const result = await fetchFromDatabase(query)
  const duration = Date.now() - startTime

  logger.info({
    event: 'database_query',
    query: query.type,
    duration,
    resultCount: result.length,
  }, 'Query completed')

  // Alert if slow
  if (duration > 1000) {
    logger.warn({
      event: 'slow_query',
      query: query.type,
      duration,
    }, 'Database query exceeded threshold')
  }

  return result
} catch (error) {
  logger.error({
    error,
    event: 'database_error',
    query: query.type,
    duration: Date.now() - startTime,
  }, 'Query failed')
  throw error
}

Correlation IDs (Request Tracing)

Correlation IDs enable tracing a single request through multiple services and log statements.

// middleware/correlation.ts
import { v4 as uuidv4 } from 'uuid'

export function correlationMiddleware(req: Request, res: Response, next: NextFunction) {
  // Extract or generate correlation ID
  const correlationId = req.headers['x-correlation-id'] || uuidv4()

  // Add to response headers for client
  res.setHeader('x-correlation-id', correlationId)

  // Attach logger with correlation ID to request
  req.log = logger.child({ correlationId })

  next()
}

// Usage in route
app.get('/api/users', async (req, res) => {
  req.log.info('Fetching users')

  const users = await fetchUsers()
  req.log.info({ count: users.length }, 'Users fetched')

  res.json(users)
})

// All logs will include the same correlationId:
// {"level":"info","correlationId":"abc-123","msg":"Fetching users"}
// {"level":"info","correlationId":"abc-123","count":42,"msg":"Users fetched"}

Sensitive Data Redaction

Critical security practice: Never log sensitive information.

Automatic Redaction (configured in setup)

// Pino automatically redacts these fields (from setup above)
logger.info({
  user: {
    email: 'user@example.com',
    password: 'secret123',  // Will be [REDACTED]
  },
  apiKey: 'sk_live_123',    // Will be [REDACTED]
}, 'User data processed')

// Output:
// {
//   "user": {
//     "email": "user@example.com",
//     "password": "[REDACTED]"
//   },
//   "apiKey": "[REDACTED]",
//   "msg": "User data processed"
// }

Manual Redaction for Dynamic Fields

// Utility function for safe logging
function sanitizeForLogging<T extends Record<string, any>>(obj: T): T {
  const sensitivePatterns = [
    /password/i,
    /secret/i,
    /token/i,
    /key/i,
    /authorization/i,
  ]

  const sanitized = { ...obj }

  for (const key in sanitized) {
    if (sensitivePatterns.some(pattern => pattern.test(key))) {
      sanitized[key] = '[REDACTED]'
    }
  }

  return sanitized
}

// Usage
logger.info(sanitizeForLogging(userData), 'User updated')

Convex-Specific Logging

Convex functions run in a managed environment with built-in logging, but structured logging still applies:

// convex/users.ts
import { query } from './_generated/server'
import { v } from 'convex/values'

export const getUser = query({
  args: { userId: v.id('users') },
  handler: async (ctx, args) => {
    // Use console with structured data
    console.info({
      operation: 'getUser',
      userId: args.userId,
      timestamp: Date.now(),
    })

    try {
      const user = await ctx.db.get(args.userId)

      if (!user) {
        console.warn({
          operation: 'getUser',
          userId: args.userId,
          result: 'not_found',
        })
        return null
      }

      console.info({
        operation: 'getUser',
        userId: args.userId,
        result: 'success',
      })

      return user
    } catch (error) {
      console.error({
        operation: 'getUser',
        userId: args.userId,
        error: error.message,
      })
      throw error
    }
  },
})

Note: Convex console.log/info/error are automatically structured in the dashboard. Use objects instead of strings for better filtering.

Centralization & Observability

In production, centralize logs to a log aggregation service:

Option 1: Datadog (Recommended for Enterprise)

// lib/logger.ts
import pino from 'pino'

const logger = pino({
  // ... base config

  transport: {
    target: 'pino-datadog-transport',
    options: {
      apiKey: process.env.DATADOG_API_KEY,
      service: 'my-app',
      env: process.env.NODE_ENV,
      tags: ['team:engineering', 'project:webapp'],
    },
  },
})

Option 2: Graylog (Self-Hosted)

import pino from 'pino'

const logger = pino({
  transport: {
    target: 'pino-socket',
    options: {
      address: process.env.GRAYLOG_HOST,
      port: 12201,
      mode: 'udp',
    },
  },
})

Option 3: Vercel Log Drains (for Next.js on Vercel)

Vercel automatically collects logs and can forward to:

• Datadog
• LogDNA
• Logtail
• New Relic
• Sentry
• Custom HTTPS endpoints

Configure in Vercel Dashboard → Project → Settings → Log Drains

Querying Logs

With centralized structured logs, you can query efficiently:

# Datadog query
service:my-app AND env:production AND level:error AND @userId:123

# Find slow database queries
service:my-app AND event:database_query AND duration > 1000

# Track user journey
service:my-app AND @correlationId:abc-123-def

Testing & Development

Development: Pretty Printing

# Pretty output for development
NODE_ENV=development pnpm dev

# Raw JSON for testing centralization
NODE_ENV=production pnpm dev

Testing: Log Capture

// test/logger.test.ts
import { describe, it, expect, vi } from 'vitest'
import { logger } from '@/lib/logger'

describe('Logger', () => {
  it('redacts sensitive fields', () => {
    const logSpy = vi.spyOn(logger, 'info')

    logger.info({
      email: 'user@example.com',
      password: 'secret',
    }, 'User data')

    expect(logSpy).toHaveBeenCalledWith(
      expect.objectContaining({
        email: 'user@example.com',
        password: '[REDACTED]',
      }),
      'User data'
    )
  })
})

Best Practices Summary

Do ✅

• Use structured JSON: {userId: '123', action: 'login'} not "User 123 logged in"
• Include context: Add all relevant fields (IDs, timestamps, metadata)
• Use correlation IDs: Track requests across services
• Redact sensitive data: Passwords, tokens, PII automatically filtered
• Log at appropriate levels: info for normal flow, error for failures
• Use child loggers: Add context once, reuse across log statements
• Centralize in production: Send logs to Datadog/Graylog/ELK
• Query your logs: Use structured fields for powerful analysis

Don't ❌

• Don't use string templates: Breaks queryability
• Don't log sensitive data: Passwords, tokens, credit cards, SSNs
• Don't log in tight loops: Excessive logs hurt performance
• Don't ignore log levels: Trace/debug should be off in production
• Don't concatenate error messages: Log full error object with stack
• Don't use console.log in production: Use proper logging library
• Don't skip correlation IDs: Makes debugging multi-service flows impossible

Quick Setup Checklist

For a new Node.js/Next.js project:

• Install Pino: pnpm add pino pino-pretty
• Create logger singleton in lib/logger.ts
• Configure redaction for sensitive fields
• Set up correlation ID middleware
• Create child logger pattern for requests
• Configure pretty printing for development
• Set up log transport for production (Datadog/Graylog)
• Add environment variable: LOG_LEVEL
• Test redaction with unit tests
• Document logging patterns in project README

Philosophy

"Logs are the voice of your production application."

Structured logging transforms logs from debug statements into queryable data. In production, logs enable:

• Debugging: Trace requests, find errors, understand behavior
• Monitoring: Track metrics, detect anomalies, set alerts
• Analytics: Understand user behavior, measure performance
• Security: Detect attacks, audit access, investigate incidents

Invest in logging infrastructure early. The cost is minimal; the value is immense.

When agents implement logging, they should:

• Default to Pino for Node.js applications (5x faster than Winston)
• Use structured JSON fields, not string templates
• Include correlation IDs for request tracing
• Redact sensitive fields automatically
• Use child loggers for context propagation
• Log at appropriate levels (info for normal, error for failures)
• Centralize logs in production (Datadog, Graylog, or Vercel Log Drains)
• Never log passwords, tokens, API keys, or PII