|
| 1 | +# Structured Logging with Pino |
| 2 | + |
| 3 | +This document describes the structured logging implementation in the Gemini Flow backend using [Pino](https://getpino.io/). |
| 4 | + |
| 5 | +## Overview |
| 6 | + |
| 7 | +The backend uses Pino for production-ready structured logging with the following features: |
| 8 | + |
| 9 | +- **Log Levels**: debug, info, warn, error, fatal |
| 10 | +- **Development Mode**: Pretty-printed, colorized output |
| 11 | +- **Production Mode**: JSON output for log aggregation |
| 12 | +- **Request Tracking**: Unique request IDs for correlation |
| 13 | +- **Error Serialization**: Full stack traces and error details |
| 14 | +- **Module Loggers**: Context-aware logging per module |
| 15 | + |
| 16 | +## Configuration |
| 17 | + |
| 18 | +### Environment Variables |
| 19 | + |
| 20 | +Configure logging via `.env` file: |
| 21 | + |
| 22 | +```bash |
| 23 | +# Log level (trace, debug, info, warn, error, fatal) |
| 24 | +LOG_LEVEL=info |
| 25 | + |
| 26 | +# Environment (affects output format) |
| 27 | +NODE_ENV=production |
| 28 | +``` |
| 29 | + |
| 30 | +**Recommended Settings:** |
| 31 | +- Development: `LOG_LEVEL=debug`, `NODE_ENV=development` |
| 32 | +- Production: `LOG_LEVEL=info`, `NODE_ENV=production` |
| 33 | + |
| 34 | +## Usage |
| 35 | + |
| 36 | +### Basic Logging |
| 37 | + |
| 38 | +```javascript |
| 39 | +import { logger } from './utils/logger.js'; |
| 40 | + |
| 41 | +// Simple message |
| 42 | +logger.info('Server started'); |
| 43 | + |
| 44 | +// With structured data |
| 45 | +logger.info({ port: 3001, env: 'production' }, 'Server started'); |
| 46 | + |
| 47 | +// Error logging |
| 48 | +logger.error({ err: error, userId: '123' }, 'Request failed'); |
| 49 | +``` |
| 50 | + |
| 51 | +### Module-Specific Logging |
| 52 | + |
| 53 | +Create child loggers for different modules: |
| 54 | + |
| 55 | +```javascript |
| 56 | +import { createModuleLogger } from './utils/logger.js'; |
| 57 | + |
| 58 | +const logger = createModuleLogger('gemini-api'); |
| 59 | + |
| 60 | +logger.info({ requestId: 'abc123' }, 'Processing request'); |
| 61 | +logger.debug({ prompt: 'test' }, 'Built prompt'); |
| 62 | +logger.error({ err: error }, 'API request failed'); |
| 63 | +``` |
| 64 | + |
| 65 | +### Log Levels |
| 66 | + |
| 67 | +Use appropriate log levels for different scenarios: |
| 68 | + |
| 69 | +```javascript |
| 70 | +// Detailed debugging info (development only) |
| 71 | +logger.debug({ variable: value }, 'Debug information'); |
| 72 | + |
| 73 | +// General information |
| 74 | +logger.info({ userId: '123' }, 'User logged in'); |
| 75 | + |
| 76 | +// Warning conditions |
| 77 | +logger.warn({ retries: 3 }, 'Retry limit approaching'); |
| 78 | + |
| 79 | +// Error conditions |
| 80 | +logger.error({ err: error }, 'Operation failed'); |
| 81 | + |
| 82 | +// Fatal errors (application crash) |
| 83 | +logger.fatal({ err: error }, 'Application cannot continue'); |
| 84 | +``` |
| 85 | + |
| 86 | +## Request Tracking |
| 87 | + |
| 88 | +All HTTP requests automatically get unique request IDs for correlation. |
| 89 | + |
| 90 | +### Request ID Middleware |
| 91 | + |
| 92 | +The `requestId` middleware: |
| 93 | +- Checks for `X-Request-ID` header |
| 94 | +- Generates UUID if not present |
| 95 | +- Attaches to `req.id` |
| 96 | +- Adds to response header |
| 97 | + |
| 98 | +### Request Logger Middleware |
| 99 | + |
| 100 | +The `requestLogger` middleware logs: |
| 101 | +- Incoming requests (method, path, IP) |
| 102 | +- Request completion (status code, duration) |
| 103 | +- Appropriate log levels based on status code |
| 104 | + |
| 105 | +## Output Examples |
| 106 | + |
| 107 | +### Development Mode (Pretty Print) |
| 108 | + |
| 109 | +``` |
| 110 | +[23:46:50 UTC] INFO: Server started |
| 111 | + env: "development" |
| 112 | + version: "1.0.0" |
| 113 | + port: 3001 |
| 114 | + healthCheck: "http://localhost:3001/health" |
| 115 | + apiBase: "http://localhost:3001/api" |
| 116 | +
|
| 117 | +[23:47:20 UTC] INFO: Incoming request |
| 118 | + requestId: "12ae5ffc-edf8-44d4-95a3-b9e34ae9d29d" |
| 119 | + method: "GET" |
| 120 | + path: "/health" |
| 121 | + ip: "::1" |
| 122 | + userAgent: "curl/8.5.0" |
| 123 | + |
| 124 | +[23:47:20 UTC] INFO: Request completed |
| 125 | + requestId: "12ae5ffc-edf8-44d4-95a3-b9e34ae9d29d" |
| 126 | + statusCode: 200 |
| 127 | + duration: 4 |
| 128 | +``` |
| 129 | + |
| 130 | +### Production Mode (JSON) |
| 131 | + |
| 132 | +```json |
| 133 | +{"level":"info","time":1761608823254,"env":"production","version":"1.0.0","port":3001,"healthCheck":"http://localhost:3001/health","apiBase":"http://localhost:3001/api","msg":"Server started"} |
| 134 | +{"level":"info","time":1761608840456,"requestId":"550e8400-e29b-41d4-a716-446655440000","method":"POST","path":"/api/gemini/execute","ip":"::1","msg":"Incoming request"} |
| 135 | +{"level":"info","time":1761608840789,"requestId":"550e8400-e29b-41d4-a716-446655440000","statusCode":201,"duration":333,"msg":"Request completed"} |
| 136 | +``` |
| 137 | + |
| 138 | +## Log Aggregation |
| 139 | + |
| 140 | +Pino's JSON output is compatible with popular log aggregation services: |
| 141 | + |
| 142 | +### Elasticsearch + Kibana (ELK Stack) |
| 143 | + |
| 144 | +Stream logs to Elasticsearch: |
| 145 | + |
| 146 | +```bash |
| 147 | +node src/server.js | pino-elasticsearch |
| 148 | +``` |
| 149 | + |
| 150 | +### Datadog |
| 151 | + |
| 152 | +Use Datadog agent to collect logs: |
| 153 | + |
| 154 | +```yaml |
| 155 | +# datadog.yaml |
| 156 | +logs: |
| 157 | + - type: file |
| 158 | + path: /var/log/gemini-flow.log |
| 159 | + service: gemini-flow-backend |
| 160 | + source: nodejs |
| 161 | +``` |
| 162 | +
|
| 163 | +### AWS CloudWatch |
| 164 | +
|
| 165 | +Use CloudWatch agent: |
| 166 | +
|
| 167 | +```bash |
| 168 | +node src/server.js | aws logs put-log-events \ |
| 169 | + --log-group-name gemini-flow \ |
| 170 | + --log-stream-name backend |
| 171 | +``` |
| 172 | + |
| 173 | +### Splunk |
| 174 | + |
| 175 | +Use HTTP Event Collector: |
| 176 | + |
| 177 | +```bash |
| 178 | +node src/server.js | pino-splunk |
| 179 | +``` |
| 180 | + |
| 181 | +## Performance |
| 182 | + |
| 183 | +Pino is optimized for performance: |
| 184 | + |
| 185 | +- **5-10x faster** than console.log in production |
| 186 | +- **Asynchronous** by default (doesn't block event loop) |
| 187 | +- **Minimal memory** overhead |
| 188 | +- **Fast JSON** serialization |
| 189 | + |
| 190 | +## Error Handling |
| 191 | + |
| 192 | +Pino properly serializes errors with full stack traces: |
| 193 | + |
| 194 | +```javascript |
| 195 | +try { |
| 196 | + // ... operation |
| 197 | +} catch (error) { |
| 198 | + logger.error({ |
| 199 | + err: error, |
| 200 | + operation: 'processRequest', |
| 201 | + requestId: req.id |
| 202 | + }, 'Operation failed'); |
| 203 | +} |
| 204 | +``` |
| 205 | + |
| 206 | +Output includes: |
| 207 | +- Error message |
| 208 | +- Stack trace |
| 209 | +- Error type |
| 210 | +- Custom context |
| 211 | + |
| 212 | +## Best Practices |
| 213 | + |
| 214 | +1. **Use appropriate log levels**: Don't log everything as `info` |
| 215 | +2. **Include context**: Add request IDs, user IDs, etc. |
| 216 | +3. **Log structured data**: Use objects for searchable fields |
| 217 | +4. **Avoid sensitive data**: Don't log passwords, tokens, PII |
| 218 | +5. **Use module loggers**: Create child loggers for different components |
| 219 | +6. **Log meaningful messages**: Make messages descriptive and actionable |
| 220 | + |
| 221 | +## Files |
| 222 | + |
| 223 | +- `backend/src/utils/logger.js` - Core logger configuration |
| 224 | +- `backend/src/api/middleware/requestId.js` - Request ID generation |
| 225 | +- `backend/src/api/middleware/requestLogger.js` - HTTP request logging |
| 226 | + |
| 227 | +## References |
| 228 | + |
| 229 | +- [Pino Documentation](https://getpino.io/) |
| 230 | +- [Pino Best Practices](https://getpino.io/#/docs/best-practices) |
| 231 | +- [Log Levels](https://getpino.io/#/docs/api?id=logger-levels) |
| 232 | +- [Child Loggers](https://getpino.io/#/docs/child-loggers) |
0 commit comments