Logging Everything and Nothing Useful — The Noise Problem

// ❌ Classic noise logging
app.get('/health', (req, res) => {
  logger.info('Health check requested')  // 60 times/minute — pure noise
  res.json({ status: 'ok' })
  logger.info('Health check completed')  // doubles the noise
})

// ❌ Every database query logged at INFO
async function getUser(id: string) {
  logger.info(`Executing query: SELECT * FROM users WHERE id = '${id}'`)  // security risk too
  const user = await db.query('SELECT * FROM users WHERE id = $1', [id])
  logger.info(`Query returned ${user.rows.length} rows`)
  return user.rows[0]
}

// ❌ Every cache operation logged
async function getCached(key: string) {
  logger.info(`Cache GET: ${key}`)
  const val = await redis.get(key)
  logger.info(`Cache ${val ? 'HIT' : 'MISS'}: ${key}`)
  return val
}
// Result: 80% of log volume is health checks, SQL, and cache ops
// When a real error occurs, it's page 47 in the log viewer

// Use log levels intentionally — each level has a specific audience

logger.error(...)   // An error that requires IMMEDIATE human attention
                    // → Alerts fire, on-call engineer woken up
                    // → "Payment processing completely down"

logger.warn(...)    // Something unexpected but the system is still working
                    // → Reviewed in morning standup
                    // → "Retry 3/3 succeeded for payment", "Cache miss rate high"

logger.info(...)    // Business-significant events (not operational noise)
                    // → Reviewed for trend analysis
                    // → "Order created", "User registered", "Payment succeeded"

logger.debug(...)   // Development and deep debugging only
                    // → NEVER enabled in production by default
                    // → SQL queries, cache hits, internal state

// ❌ Logging technical operations (noise)
logger.info('DB query executed')
logger.info('Cache key set')
logger.info('HTTP request received')
logger.info('HTTP response sent: 200')

// ✅ Logging business events (signal)
// What matters to a human reading this later?
logger.info({ userId, orderId, total, paymentMethod }, 'Order placed')
logger.warn({ userId, orderId, attempt: 3 }, 'Payment retry required')
logger.error({ userId, orderId, error: err.message }, 'Payment failed — customer action required')
logger.info({ userId, plan: 'pro', mrr: 99 }, 'User upgraded')
logger.warn({ userId, daysOverdue: 3 }, 'Invoice payment overdue')

import morgan from 'morgan'

// Custom morgan format — skip health check logs
app.use(morgan('combined', {
  skip: (req) => req.path === '/health' || req.path === '/metrics',
}))

// Or with pino-http:
import pinoHttp from 'pino-http'
app.use(pinoHttp({
  autoLogging: {
    ignore: (req) => ['/health', '/ready', '/metrics'].includes(req.url ?? ''),
  },
  customLogLevel: (req, res) => {
    if (res.statusCode >= 500) return 'error'
    if (res.statusCode >= 400) return 'warn'
    if (res.statusCode >= 300) return 'silent'  // redirects aren't interesting
    return 'info'
  },
}))

// For very high volume operations, sample — don't log every instance
let requestCount = 0

app.use((req, res, next) => {
  requestCount++

  // Log 1% of successful requests for performance sampling
  // Log 100% of errors
  const shouldLog = res.statusCode >= 400 || requestCount % 100 === 0

  if (shouldLog) {
    logger.info({
      method: req.method,
      path: req.path,
      status: res.statusCode,
      duration: Date.now() - req.startTime,
      sampled: res.statusCode < 400,
    }, 'HTTP request')
  }

  next()
})

// ❌ String concatenation — not queryable
logger.error('Failed to process order ' + orderId + ' for user ' + userId + ': ' + error.message)

// ✅ Structured fields — every field is queryable in Elasticsearch/Loki
logger.error({
  orderId,
  userId,
  error: error.message,
  errorCode: error.code,
  attempt: 3,
  duration: Date.now() - startTime,
}, 'Order processing failed')

// Now you can query: error_code:"PAYMENT_DECLINED" AND user_id:"u123"
// Or alert: count of error logs with error_code:"DB_CONNECTION_FAILED" > 5 in 1 minute

// Normally INFO — increase to DEBUG only during incidents
const logLevel = process.env.LOG_LEVEL ?? 'info'
const logger = pino({ level: logLevel })

// Runtime log level change without restart (via admin API)
app.post('/admin/log-level', adminAuth, (req, res) => {
  const { level } = req.body
  if (!['error', 'warn', 'info', 'debug'].includes(level)) {
    return res.status(400).json({ error: 'Invalid level' })
  }

  logger.level = level
  logger.info({ level }, 'Log level changed')
  res.json({ level })
})
// During incident: POST /admin/log-level { "level": "debug" }
// After incident: POST /admin/log-level { "level": "info" }