structured logging

[wasaga]

Is your feature request related to a problem? Please describe.

currently the application is logging in plaintext without any identification of which user's request the message is related to.

Describe the solution you'd like

1. use structured JSON logging
2. we need a way to identify a user current chat with whatever is happening in the logs

Describe alternatives you've considered

Explain any additional use-cases

If there are any use-cases that would help us understand the use/need/value please share them as they can help us decide on acceptance and prioritization.

Additional context

Add any other context or screenshots about the feature request here.

[nickytonline]

replace all console.* with structured logging as defined in the PRD

PRD: Structured Logging in TypeScript Applications

Overview

This document provides guidance for implementing structured logging in TypeScript applications using Pino, a high-performance JSON logger optimized for Node.js applications.

Why Structured Logging?

Benefits:

• Searchable: Query logs by any field (userId, requestId, status, etc.)
• Machine-readable: JSON format for log aggregation tools
• Rich context: Include structured metadata with every log entry
• Performance: Async logging with minimal overhead
• Production-ready: Integrates with Elasticsearch, Datadog, CloudWatch, etc.

Use Cases:

• Web APIs and REST services
• Microservices architectures
• Applications requiring observability
• Production systems with centralized logging
• Any project needing log analysis and monitoring

---

Implementation Guide

Step 1: Install Dependencies

npm install pino
npm install --save-dev pino-pretty

Package versions:

• pino: ^8.16.0 or later (production logger)
• pino-pretty: ^10.2.0 (development formatting, optional)

Step 2: Create Logger Configuration

// src/utils/logger.ts
import pino from 'pino';

const isProduction = process.env.NODE_ENV === 'production';
const isTest = process.env.NODE_ENV === 'test';

export const logger = pino({
  // Log level configuration
  level: process.env.LOG_LEVEL || (isProduction ? 'info' : 'debug'),

  // Disable logging during tests unless explicitly enabled
  enabled: !isTest || process.env.ENABLE_TEST_LOGGING === 'true',

  // Pretty printing in development (optional)
  transport: !isProduction ? {
    target: 'pino-pretty',
    options: {
      colorize: true,
      translateTime: 'HH:MM:ss Z',
      ignore: 'pid,hostname'
    }
  } : undefined,

  // Base fields included in every log entry
  base: {
    service: 'your-service-name',
    environment: process.env.NODE_ENV || 'development'
  },

  // Custom formatters
  formatters: {
    level: (label) => {
      return { level: label };
    }
  }
});

// Create child loggers for different modules
export const createLogger = (module: string) => {
  return logger.child({ module });
};

Step 3: Basic Usage

import { createLogger } from './utils/logger.js';

const log = createLogger('user-service');

// Simple logging
log.info('Application started');
log.error('Database connection failed');
log.warn('Configuration missing, using defaults');

// Structured logging with context
log.info({
  userId: 'user-123',
  action: 'login',
  ip: '192.168.1.1'
}, 'User logged in');

// Error logging with error objects
try {
  await performOperation();
} catch (error) {
  log.error({
    err: error,
    operation: 'performOperation',
    userId: 'user-123'
  }, 'Operation failed');
}

Step 4: Log Levels

Use appropriate log levels for different scenarios:

// FATAL (60) - System is unusable, immediate attention required
log.fatal({ err, dbHost }, 'Database connection permanently lost');

// ERROR (50) - Error conditions that need attention
log.error({ err, userId, endpoint }, 'Request processing failed');

// WARN (40) - Warning messages, potentially harmful situations
log.warn({ retryCount: 3, endpoint }, 'Approaching rate limit');

// INFO (30) - Informational messages (default in production)
log.info({ operation: 'cache-refresh', duration: 150 }, 'Cache refreshed');

// DEBUG (20) - Debug-level messages (development/troubleshooting)
log.debug({ cacheSize: 1024, hitRate: 0.85 }, 'Cache statistics');

// TRACE (10) - Very detailed debugging information
log.trace({ headers, body }, 'HTTP request received');

Step 5: Contextual Logging

Create loggers with persistent context for related operations:

// Define context interface
export interface LogContext {
  userId?: string;
  requestId?: string;
  sessionId?: string;
  correlationId?: string;
  operation?: string;
  [key: string]: any;
}

// Create logger with context
export const logWithContext = (context: LogContext) => {
  return logger.child(context);
};

// Usage in request handlers
const requestLogger = logWithContext({
  requestId: 'req-abc-123',
  userId: 'user-456',
  endpoint: '/api/users'
});

requestLogger.info('Processing request');
requestLogger.info({ itemCount: 5 }, 'Items retrieved from database');
requestLogger.error({ err }, 'Request failed');
// All logs include requestId and userId automatically

Step 6: Performance Logging

Track operation duration and performance metrics:

// Simple duration tracking
const startTime = Date.now();

try {
  const result = await expensiveOperation();
  
  log.info({
    duration: Date.now() - startTime,
    operation: 'expensiveOperation',
    resultCount: result.length,
    success: true
  }, 'Operation completed successfully');
} catch (error) {
  log.error({
    duration: Date.now() - startTime,
    operation: 'expensiveOperation',
    success: false,
    err: error
  }, 'Operation failed');
}

// Reusable performance wrapper
async function withTiming<T>(
  operation: string,
  fn: () => Promise<T>
): Promise<T> {
  const startTime = Date.now();
  try {
    const result = await fn();
    log.info({
      operation,
      duration: Date.now() - startTime,
      success: true
    }, `${operation} completed`);
    return result;
  } catch (error) {
    log.error({
      operation,
      duration: Date.now() - startTime,
      success: false,
      err: error
    }, `${operation} failed`);
    throw error;
  }
}

// Usage
const users = await withTiming('fetchUsers', () => db.users.findMany());

Step 7: Module-Specific Loggers

Create dedicated loggers for different parts of your application:

// src/services/auth/logger.ts
import { createLogger } from '../../utils/logger.js';
export const authLogger = createLogger('auth');

// src/services/database/logger.ts
import { createLogger } from '../../utils/logger.js';
export const dbLogger = createLogger('database');

// src/services/api/logger.ts
import { createLogger } from '../../utils/logger.js';
export const apiLogger = createLogger('api');

// Usage
import { authLogger } from './logger.js';

authLogger.info({ userId, method: 'oauth' }, 'User authenticated');
authLogger.error({ userId, err }, 'Authentication failed');

Step 8: Environment Configuration

Configure logging behavior via environment variables:

# .env.example
LOG_LEVEL=debug              # trace, debug, info, warn, error, fatal
ENABLE_TEST_LOGGING=false    # Enable logs during test runs
NODE_ENV=development         # development, production, test

// Access configuration
const config = {
  logLevel: process.env.LOG_LEVEL || 'info',
  enableTestLogs: process.env.ENABLE_TEST_LOGGING === 'true',
  environment: process.env.NODE_ENV || 'development'
};

---

Production Usage

Viewing and Filtering Logs

Pretty print JSON logs:

# View logs with formatting
cat logs/app.log | npx pino-pretty

# Filter by log level
cat logs/app.log | npx pino-pretty --level=error

# Show only specific fields
cat logs/app.log | npx pino-pretty --translateTime --ignore=pid,hostname

Using jq for advanced filtering:

# Show only error-level logs
cat logs/app.log | jq 'select(.level == 50)'

# Filter by userId
cat logs/app.log | jq 'select(.userId == "user-123")'

# Show errors from specific module
cat logs/app.log | jq 'select(.level == 50 and .module == "database")'

# Extract specific fields
cat logs/app.log | jq '{time, level, msg, userId, operation}'

Log Aggregation Transports

Integrate with observability platforms using Pino transports:

Elasticsearch:

npm install pino-elasticsearch

AWS CloudWatch:

npm install pino-cloudwatch

Datadog:

npm install pino-datadog

Sentry (errors only):

npm install pino-sentry

Log Rotation

Use pino with log rotation for file-based logging:

npm install pino-roll

import pino from 'pino';

export const logger = pino({
  transport: {
    target: 'pino-roll',
    options: {
      file: './logs/app.log',
      frequency: 'daily',
      size: '10M',
      mkdir: true
    }
  }
});

---

Best Practices

DO:

• ✅ Use structured context objects instead of string interpolation
• ✅ Include relevant metadata (userId, requestId, operation)
• ✅ Use appropriate log levels (don't log everything as info)
• ✅ Create child loggers for different modules
• ✅ Log errors with the err field for proper serialization
• ✅ Track performance with duration fields
• ✅ Use environment variables for configuration

DON'T:

• ❌ Don't log sensitive data (passwords, tokens, PII)
• ❌ Don't use excessive logging in hot code paths
• ❌ Don't use string concatenation for context
• ❌ Don't log the same information multiple times
• ❌ Don't use synchronous logging in production
• ❌ Don't ignore log levels (every log should have purpose)

Example: Good vs Bad

// ❌ BAD: String interpolation, no structure
log.info(`User ${userId} logged in from ${ip}`);

// ✅ GOOD: Structured data
log.info({ userId, ip, action: 'login' }, 'User logged in');

// ❌ BAD: No context, unclear
log.error('Failed');

// ✅ GOOD: Rich context
log.error({ 
  err, 
  userId, 
  operation: 'updateProfile',
  endpoint: '/api/profile'
}, 'Profile update failed');

// ❌ BAD: Logging sensitive data
log.info({ password, creditCard }, 'Payment processed');

// ✅ GOOD: Sanitized logging
log.info({ 
  userId, 
  amount, 
  lastFourDigits: creditCard.slice(-4) 
}, 'Payment processed');

---

Common Patterns

HTTP Request Logging

import { createLogger } from './utils/logger.js';

const log = createLogger('http');

app.use((req, res, next) => {
  const requestId = generateRequestId();
  const startTime = Date.now();
  
  // Attach logger to request
  req.log = logWithContext({
    requestId,
    method: req.method,
    path: req.path,
    userId: req.user?.id
  });
  
  req.log.info('Request started');
  
  res.on('finish', () => {
    req.log.info({
      statusCode: res.statusCode,
      duration: Date.now() - startTime
    }, 'Request completed');
  });
  
  next();
});

Database Query Logging

const dbLogger = createLogger('database');

async function executeQuery(query: string, params: any[]) {
  const startTime = Date.now();
  
  try {
    const result = await db.query(query, params);
    
    dbLogger.debug({
      query,
      duration: Date.now() - startTime,
      rowCount: result.rowCount
    }, 'Query executed');
    
    return result;
  } catch (error) {
    dbLogger.error({
      query,
      duration: Date.now() - startTime,
      err: error
    }, 'Query failed');
    throw error;
  }
}

Background Job Logging

const jobLogger = createLogger('jobs');

async function processJob(job: Job) {
  const jobLog = jobLogger.child({
    jobId: job.id,
    jobType: job.type
  });
  
  jobLog.info('Job started');
  
  try {
    const result = await job.execute();
    jobLog.info({ result }, 'Job completed successfully');
  } catch (error) {
    jobLog.error({ err: error, retries: job.retries }, 'Job failed');
    throw error;
  }
}

---

Summary

Structured logging with Pino provides:

• Performance: Async, high-throughput JSON logging
• Observability: Rich context for debugging and monitoring
• Integration: Works with major log aggregation platforms
• Flexibility: Environment-aware configuration
• Production-ready: Battle-tested in Node.js applications

Start with basic structured logging and gradually add more context as your observability needs grow.