Pino + Pino-Pretty

O que é Pino?

Pino é um logger JSON de baixo overhead para Node.js, projetado para ser extremamente rápido e eficiente. Pino-pretty é uma ferramenta complementar que formata os logs JSON do Pino para leitura humana durante desenvolvimento.

Por que utilizamos Pino na IngenioLab?

Performance extrema: Até 5x mais rápido que Winston
Structured logging: Logs JSON estruturados para análise
Low overhead: Impacto mínimo na performance da aplicação
Child loggers: Contexto hierárquico e isolado
Transport system: Flexível para diferentes destinos
Production ready: Usado por empresas como Netflix e Uber

Instalação

# Pino core
npm install pino

# Pino-pretty para desenvolvimento
npm install -D pino-pretty

# Transports adicionais
npm install pino-http pino-elasticsearch pino-cloudwatch

Configuração Base IngenioLab

1. Logger principal:

// src/lib/logger.ts
import pino from 'pino'
import { env } from '../utils/env'

// Configuração baseada no ambiente
const pinoConfig = {
  level: env.LOG_LEVEL || 'info',
  
  // Configuração para desenvolvimento
  ...(env.NODE_ENV === 'development' && {
    transport: {
      target: 'pino-pretty',
      options: {
        colorize: true,
        translateTime: 'SYS:standard',
        ignore: 'pid,hostname',
        singleLine: false,
        hideObject: false
      }
    }
  }),
  
  // Configuração para produção
  ...(env.NODE_ENV === 'production' && {
    formatters: {
      log: (record) => ({
        ...record,
        service: 'ingeniolab-api',
        version: process.env.npm_package_version,
        environment: env.NODE_ENV
      })
    },
    timestamp: pino.stdTimeFunctions.isoTime,
    redact: {
      paths: [
        'password',
        'token',
        'authorization',
        'cookie',
        'req.headers.authorization',
        'req.headers.cookie'
      ],
      censor: '[REDACTED]'
    }
  })
}

export const logger = pino(pinoConfig)

// Child loggers para diferentes módulos
export const dbLogger = logger.child({ module: 'database' })
export const authLogger = logger.child({ module: 'auth' })
export const apiLogger = logger.child({ module: 'api' })

export default logger

2. Integração com Fastify:

// src/app.ts
import fastify from 'fastify'
import { logger } from './lib/logger'

export async function build(opts = {}) {
  const app = fastify({
    ...opts,
    logger: logger, // Usar Pino como logger do Fastify
  })

  // Plugin para logging de requisições HTTP
  await app.register(import('@fastify/sensible'))
  
  // Configurar context para cada requisição
  app.addHook('onRequest', async (request, reply) => {
    // Criar child logger para cada requisição
    request.log = logger.child({
      reqId: request.id,
      method: request.method,
      url: request.url,
      userAgent: request.headers['user-agent'],
      ip: request.ip
    })
  })

  // Logging de resposta
  app.addHook('onSend', async (request, reply, payload) => {
    request.log.info({
      statusCode: reply.statusCode,
      responseTime: reply.getResponseTime()
    }, 'Request completed')
  })

  // Error handler com logging
  app.setErrorHandler((error, request, reply) => {
    // Log do erro com contexto completo
    request.log.error({
      err: error,
      reqId: request.id,
      statusCode: error.statusCode || 500
    }, 'Request error')

    const statusCode = error.statusCode || 500
    
    reply.status(statusCode).send({
      error: error.name || 'Internal Server Error',
      message: statusCode < 500 ? error.message : 'Something went wrong',
      reqId: request.id
    })
  })

  return app
}

Padrões de Logging IngenioLab

1. Níveis de Log:

// src/services/userService.ts
import { logger } from '../lib/logger'

export class UserService {
  private static log = logger.child({ service: 'UserService' })

  async createUser(userData: any) {
    // TRACE: Informações muito detalhadas (debugging)
    this.log.trace({ userData }, 'Creating user with data')

    try {
      // DEBUG: Informações de debugging
      this.log.debug('Validating user data')

      // Validação...

      // INFO: Operações importantes do sistema
      this.log.info({ email: userData.email }, 'Creating new user')

      const user = await prisma.user.create({ data: userData })

      // INFO: Sucesso da operação
      this.log.info({ userId: user.id }, 'User created successfully')

      return user
    } catch (error) {
      // ERROR: Erros que precisam de atenção
      this.log.error({
        err: error,
        userData: { email: userData.email } // Dados seguros apenas
      }, 'Failed to create user')

      throw error
    }
  }

  async authenticateUser(email: string, password: string) {
    const authLog = this.log.child({ email, operation: 'authenticate' })

    try {
      authLog.info('Authentication attempt')

      const user = await prisma.user.findUnique({ where: { email } })
      
      if (!user) {
        // WARN: Situações suspeitas mas não críticas
        authLog.warn('Authentication failed - user not found')
        throw new Error('Invalid credentials')
      }

      const isValid = await bcrypt.compare(password, user.password)
      
      if (!isValid) {
        authLog.warn('Authentication failed - invalid password')
        throw new Error('Invalid credentials')
      }

      authLog.info({ userId: user.id }, 'Authentication successful')
      return user
    } catch (error) {
      authLog.error({ err: error }, 'Authentication error')
      throw error
    }
  }
}

2. Child Loggers Contextuais:

// src/routes/users.ts
import { FastifyInstance } from 'fastify'
import { logger } from '../lib/logger'

export default async function userRoutes(fastify: FastifyInstance) {
  const routeLogger = logger.child({ route: 'users' })

  fastify.get('/:id', async (request, reply) => {
    const { id } = request.params as { id: string }
    
    // Child logger específico para esta operação
    const opLogger = routeLogger.child({
      operation: 'getUser',
      userId: id,
      reqId: request.id
    })

    opLogger.info('Fetching user')

    try {
      const user = await userService.getUserById(id)
      
      opLogger.info('User fetched successfully')
      
      return reply.send(user)
    } catch (error) {
      opLogger.error({ err: error }, 'Failed to fetch user')
      throw error
    }
  })

  fastify.post('/', {
    preHandler: [fastify.authenticate]
  }, async (request, reply) => {
    const userData = request.body
    const currentUser = request.user
    
    const opLogger = routeLogger.child({
      operation: 'createUser',
      createdBy: currentUser.id,
      reqId: request.id
    })

    opLogger.info({ targetEmail: userData.email }, 'Creating user')

    try {
      const newUser = await userService.createUser(userData)
      
      opLogger.info({ newUserId: newUser.id }, 'User created')
      
      return reply.status(201).send(newUser)
    } catch (error) {
      opLogger.error({ err: error }, 'Failed to create user')
      throw error
    }
  })
}

3. Database Query Logging:

// src/lib/prisma-logger.ts
import { PrismaClient } from '@prisma/client'
import { dbLogger } from './logger'

export const prisma = new PrismaClient({
  log: [
    { level: 'query', emit: 'event' },
    { level: 'error', emit: 'event' },
    { level: 'info', emit: 'event' },
    { level: 'warn', emit: 'event' }
  ]
})

// Log de queries
prisma.$on('query', (e) => {
  dbLogger.debug({
    query: e.query,
    params: e.params,
    duration: `${e.duration}ms`,
    target: e.target
  }, 'Database query executed')
})

// Log de erros do banco
prisma.$on('error', (e) => {
  dbLogger.error({
    target: e.target,
    message: e.message
  }, 'Database error')
})

// Middleware para logging de operações
prisma.$use(async (params, next) => {
  const start = Date.now()
  
  const operationLogger = dbLogger.child({
    model: params.model,
    action: params.action
  })

  operationLogger.trace(params.args, 'Database operation starting')

  try {
    const result = await next(params)
    const duration = Date.now() - start

    operationLogger.info({
      duration: `${duration}ms`,
      affected: Array.isArray(result) ? result.length : 1
    }, 'Database operation completed')

    return result
  } catch (error) {
    const duration = Date.now() - start

    operationLogger.error({
      err: error,
      duration: `${duration}ms`
    }, 'Database operation failed')

    throw error
  }
})

Configurações Avançadas

1. Redaction (Ocultar dados sensíveis):

// src/lib/logger-config.ts
import pino from 'pino'

const logger = pino({
  redact: {
    paths: [
      // Campos de senha
      'password',
      'currentPassword',
      'newPassword',
      
      // Tokens e chaves
      'token',
      'jwt',
      'apiKey',
      'authorization',
      
      // Headers HTTP sensíveis
      'req.headers.authorization',
      'req.headers.cookie',
      'req.headers["x-api-key"]',
      
      // Dados pessoais (LGPD/GDPR)
      'cpf',
      'ssn',
      'creditCard',
      'bankAccount',
      
      // Objetos aninhados
      'user.password',
      'userData.password',
      'body.password'
    ],
    
    // Função customizada de redação
    censor: (value, path) => {
      if (path.includes('email')) {
        // Mascarar email: user@domain.com → u***@***.com
        return value.replace(/(.{1}).*(@.{1}).*/, '$1***$2***')
      }
      return '[REDACTED]'
    }
  }
})

2. Transports para múltiplos destinos:

// src/lib/logger-transports.ts
import pino from 'pino'

const transports = pino.transport({
  targets: [
    // Console (desenvolvimento)
    ...(process.env.NODE_ENV === 'development' ? [{
      target: 'pino-pretty',
      options: {
        colorize: true,
        translateTime: 'SYS:standard'
      },
      level: 'debug'
    }] : []),
    
    // Arquivo local (produção)
    {
      target: 'pino/file',
      options: {
        destination: './logs/app.log',
        mkdir: true
      },
      level: 'info'
    },
    
    // Arquivo de erros separado
    {
      target: 'pino/file',
      options: {
        destination: './logs/error.log',
        mkdir: true
      },
      level: 'error'
    },
    
    // Elasticsearch (produção)
    ...(process.env.NODE_ENV === 'production' ? [{
      target: 'pino-elasticsearch',
      options: {
        index: 'ingeniolab-logs',
        node: process.env.ELASTICSEARCH_URL,
        auth: {
          username: process.env.ELASTICSEARCH_USER,
          password: process.env.ELASTICSEARCH_PASS
        }
      },
      level: 'info'
    }] : []),
    
    // CloudWatch (AWS)
    ...(process.env.AWS_REGION ? [{
      target: 'pino-cloudwatch',
      options: {
        logGroupName: '/ingeniolab/api',
        logStreamName: `${process.env.NODE_ENV}-${Date.now()}`,
        region: process.env.AWS_REGION
      },
      level: 'warn'
    }] : [])
  ]
})

export const logger = pino(transports)

3. Correlation IDs para rastreamento:

// src/middleware/correlation.ts
import { FastifyRequest, FastifyReply } from 'fastify'
import { v4 as uuidv4 } from 'uuid'
import { AsyncLocalStorage } from 'async_hooks'

// Armazenamento local para context
const asyncLocalStorage = new AsyncLocalStorage<{ correlationId: string }>()

export function correlationMiddleware(
  request: FastifyRequest,
  reply: FastifyReply,
  done: Function
) {
  // Pegar correlation ID do header ou gerar novo
  const correlationId = 
    (request.headers['x-correlation-id'] as string) || 
    uuidv4()
  
  // Adicionar ao response header
  reply.header('X-Correlation-ID', correlationId)
  
  // Executar request dentro do context
  asyncLocalStorage.run({ correlationId }, () => {
    // Adicionar ao logger da request
    request.log = request.log.child({ correlationId })
    done()
  })
}

// Utilidade para pegar correlation ID em qualquer lugar
export function getCorrelationId(): string | undefined {
  return asyncLocalStorage.getStore()?.correlationId
}

// Logger que sempre inclui correlation ID
export function createContextLogger(baseLogger: any) {
  return {
    ...baseLogger,
    info: (obj: any, msg?: string) => {
      const correlationId = getCorrelationId()
      return baseLogger.info({ ...obj, correlationId }, msg)
    },
    error: (obj: any, msg?: string) => {
      const correlationId = getCorrelationId()
      return baseLogger.error({ ...obj, correlationId }, msg)
    }
    // ... outros métodos
  }
}

Monitoring e Alertas

1. Health Check com logging:

// src/routes/health.ts
import { FastifyInstance } from 'fastify'
import { logger } from '../lib/logger'
import { prisma } from '../lib/prisma'

export default async function healthRoutes(fastify: FastifyInstance) {
  const healthLogger = logger.child({ route: 'health' })

  fastify.get('/health', async (request, reply) => {
    const checks = {
      timestamp: new Date().toISOString(),
      status: 'healthy',
      version: process.env.npm_package_version,
      uptime: process.uptime(),
      checks: {}
    }

    try {
      // Check database
      const dbStart = Date.now()
      await prisma.$queryRaw`SELECT 1`
      const dbTime = Date.now() - dbStart
      
      checks.checks.database = {
        status: 'healthy',
        responseTime: `${dbTime}ms`
      }

      // Check memory
      const memUsage = process.memoryUsage()
      checks.checks.memory = {
        status: memUsage.heapUsed > 100 * 1024 * 1024 ? 'warning' : 'healthy',
        heapUsed: `${Math.round(memUsage.heapUsed / 1024 / 1024)}MB`,
        heapTotal: `${Math.round(memUsage.heapTotal / 1024 / 1024)}MB`
      }

      healthLogger.info(checks, 'Health check passed')
      
      return reply.send(checks)
    } catch (error) {
      checks.status = 'unhealthy'
      checks.checks.database = {
        status: 'unhealthy',
        error: error.message
      }

      healthLogger.error({
        err: error,
        checks
      }, 'Health check failed')

      return reply.status(503).send(checks)
    }
  })

  // Readiness check (Kubernetes)
  fastify.get('/ready', async (request, reply) => {
    try {
      await prisma.$queryRaw`SELECT 1`
      healthLogger.debug('Readiness check passed')
      return reply.send({ status: 'ready' })
    } catch (error) {
      healthLogger.error({ err: error }, 'Readiness check failed')
      return reply.status(503).send({ status: 'not ready' })
    }
  })
}

2. Performance Monitoring:

// src/utils/performance.ts
import { logger } from '../lib/logger'

export class PerformanceMonitor {
  private static performanceLogger = logger.child({ module: 'performance' })

  static trackOperation<T>(
    operationName: string,
    operation: () => Promise<T>,
    context?: Record<string, any>
  ): Promise<T> {
    return new Promise(async (resolve, reject) => {
      const start = Date.now()
      const opLogger = this.performanceLogger.child({
        operation: operationName,
        ...context
      })

      try {
        opLogger.debug('Operation started')
        
        const result = await operation()
        const duration = Date.now() - start

        // Log de performance
        if (duration > 5000) {
          opLogger.warn({ duration }, 'Slow operation detected')
        } else if (duration > 1000) {
          opLogger.info({ duration }, 'Operation completed (slow)')
        } else {
          opLogger.debug({ duration }, 'Operation completed')
        }

        resolve(result)
      } catch (error) {
        const duration = Date.now() - start
        
        opLogger.error({
          err: error,
          duration
        }, 'Operation failed')

        reject(error)
      }
    })
  }

  static trackDatabaseQuery<T>(
    queryName: string,
    query: () => Promise<T>
  ): Promise<T> {
    return this.trackOperation(`db:${queryName}`, query)
  }

  static trackApiCall<T>(
    endpoint: string,
    call: () => Promise<T>
  ): Promise<T> {
    return this.trackOperation(`api:${endpoint}`, call)
  }
}

// Uso
const users = await PerformanceMonitor.trackDatabaseQuery(
  'getUsersList',
  () => userService.getUsers({ page: 1, limit: 10 })
)

Scripts de Desenvolvimento

1. package.json:

{
  "scripts": {
    "dev": "NODE_ENV=development tsx watch src/server.ts | pino-pretty",
    "start": "NODE_ENV=production node dist/server.js",
    "logs:dev": "tail -f logs/app.log | pino-pretty",
    "logs:error": "tail -f logs/error.log | pino-pretty",
    "logs:analyze": "cat logs/app.log | jq '.level' | sort | uniq -c"
  }
}

2. Análise de logs:

# Ver logs em tempo real (desenvolvimento)
npm run logs:dev

# Ver apenas erros
npm run logs:error

# Contar logs por nível
cat logs/app.log | jq -r '.level' | sort | uniq -c

# Buscar por usuário específico
cat logs/app.log | jq 'select(.userId == "123")'

# Logs de performance lenta
cat logs/app.log | jq 'select(.duration and (.duration | tonumber > 1000))'

Configuração de Ambiente

# .env
LOG_LEVEL=info          # trace, debug, info, warn, error, fatal
NODE_ENV=development    # development, production
ELASTICSEARCH_URL=http://localhost:9200
AWS_REGION=us-east-1

Boas Práticas

1. ✅ Faça:

Use structured logging (JSON)
Inclua context nos child loggers
Redact dados sensíveis
Use correlation IDs
Monitore performance
Configure diferentes níveis por ambiente

2. ❌ Evite:

Logging síncrono em produção
Logs de senhas ou dados sensíveis
Logging excessivo em hot paths
String interpolation em logs
Logs sem context