Assist_Design/docs/LOGGING.md

344 lines
8.4 KiB
Markdown
Raw Normal View History

2025-08-22 17:02:49 +09:00
# 📝 Centralized Logging System
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
This guide covers the **centralized, high-performance logging system** implemented using **Pino** - the fastest JSON logger for Node.js applications.
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 🎯 **Architecture Overview**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Single Logger System**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
-**Backend (BFF)**: `nestjs-pino` with Pino
-**Frontend**: Custom structured logger compatible with backend
-**Shared**: Common interfaces and configurations
-**No more mixed logging systems**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Benefits of Centralization**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- 🚀 **Performance**: Pino is 5x faster than winston
- 🔒 **Security**: Automatic sensitive data sanitization
- 📊 **Structured**: JSON logging for better parsing
- 🌐 **Correlation**: Request tracking across services
- 📈 **Monitoring**: Easy integration with log aggregation'
- this implemetnatin requires more type safety faeteur
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 🏗️ **Implementation**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Backend (BFF) - NestJS + Pino**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// ✅ CORRECT: Use nestjs-pino Logger
import { Logger } from "nestjs-pino";
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
@Injectable()
export class UserService {
constructor(@Inject(Logger) private readonly logger: Logger) {}
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
async findUser(id: string) {
this.logger.info(`Finding user ${id}`);
// ... implementation
}
}
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Frontend - Structured Logger**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// ✅ CORRECT: Use shared logger interface
import { logger } from "@/lib/logger";
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
export function handleApiCall() {
logger.logApiCall("/api/users", "GET", 200, 150);
logger.logUserAction("user123", "login");
}
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
## 🚫 **What NOT to Do**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **❌ Don't Use Multiple Logging Systems**
2025-08-21 15:24:40 +09:00
```typescript
2025-08-22 17:02:49 +09:00
// ❌ WRONG: Mixing logging systems
import { Logger } from "@nestjs/common"; // Don't use this - REMOVED
import { Logger } from "nestjs-pino"; // ✅ Use this - CENTRALIZED
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
// ❌ WRONG: Console logging in production
console.log("User logged in"); // Don't use console.log
logger.info("User logged in"); // Use structured logger
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **✅ Current Status: FULLY CENTRALIZED**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- **All BFF services** now use `nestjs-pino` Logger
- **No more** `@nestjs/common` Logger imports
- **No more** `new Logger()` instantiations
- **Single logging system** throughout the entire backend
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **❌ Don't Use Console Methods**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// ❌ WRONG: Direct console usage
console.log("Debug info");
console.error("Error occurred");
console.warn("Warning message");
// ✅ CORRECT: Structured logging
logger.debug("Debug info");
logger.error("Error occurred");
logger.warn("Warning message");
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
## 🔧 **Configuration**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Environment Variables**
2025-08-21 15:24:40 +09:00
```bash
2025-08-22 17:02:49 +09:00
# Logging configuration
LOG_LEVEL=info # error, warn, info, debug, trace
APP_NAME=customer-portal-bff # Service identifier
NODE_ENV=development # Environment context
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Log Levels**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
| Level | Numeric | Description |
| ------- | ------- | ------------------------------------ |
| `error` | 0 | Errors that need immediate attention |
| `warn` | 1 | Warnings that should be monitored |
| `info` | 2 | General information about operations |
| `debug` | 3 | Detailed debugging information |
| `trace` | 4 | Very detailed tracing information |
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 📝 **Usage Examples**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Basic Logging**
2025-08-21 15:24:40 +09:00
```typescript
2025-08-22 17:02:49 +09:00
// Simple messages
logger.info("User authentication successful");
logger.warn("Rate limit approaching");
logger.error("Database connection failed");
// With structured data
logger.info("Invoice created", {
invoiceId: "INV-001",
amount: 99.99,
userId: "user123",
});
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **API Call Logging**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// Automatic API call logging
logger.logApiCall("/api/invoices", "POST", 201, 250, {
userId: "user123",
invoiceId: "INV-001",
});
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **User Action Logging**
```typescript
// User activity tracking
logger.logUserAction("user123", "password_change", {
ipAddress: "192.168.1.1",
userAgent: "Mozilla/5.0...",
});
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **Error Logging**
```typescript
// Comprehensive error logging
try {
// ... operation
} catch (error) {
logger.logError(error, "user_creation", {
userId: "user123",
email: "user@example.com",
});
2025-08-21 15:24:40 +09:00
}
```
2025-08-22 17:02:49 +09:00
## 🔍 **Request Correlation**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Automatic Correlation IDs**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// Every request gets a unique correlation ID
// Headers: x-correlation-id: 1703123456789-abc123def
logger.info("Processing request", {
correlationId: req.headers["x-correlation-id"],
endpoint: req.url,
method: req.method,
});
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Manual Correlation**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// Set correlation context
logger.setCorrelationId("req-123");
logger.setUserId("user-456");
logger.setRequestId("req-789");
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
// All subsequent logs include this context
logger.info("User action completed");
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 📊 **Production Logging**
### **File Logging**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// Automatic log rotation
// - Combined logs: logs/customer-portal-bff-combined.log
// - Error logs: logs/customer-portal-bff-error.log
// - Console output: stdout (for container logs)
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Log Aggregation**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// Structured JSON output for easy parsing
{
"timestamp": "2025-01-22T10:30:00.000Z",
"level": "info",
"service": "customer-portal-bff",
"environment": "production",
"message": "User authentication successful",
"correlationId": "req-123",
"userId": "user-456",
"data": {
"ipAddress": "192.168.1.1",
"userAgent": "Mozilla/5.0..."
}
}
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
## 🚀 **Performance Benefits**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Benchmarks (Pino vs Winston)**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
| Operation | Pino | Winston | Improvement |
| -------------------- | ---- | ------- | ------------- |
| JSON serialization | 1x | 5x | **5x faster** |
| Object serialization | 1x | 3x | **3x faster** |
| String interpolation | 1x | 2x | **2x faster** |
| Overall performance | 1x | 5x | **5x faster** |
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Memory Usage**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- **Pino**: Minimal memory footprint
- **Winston**: Higher memory usage due to object retention
- **Console**: No memory overhead but unstructured
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 🔒 **Security Features**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Automatic Data Sanitization**
2025-08-21 15:24:40 +09:00
```typescript
2025-08-22 17:02:49 +09:00
// Sensitive data is automatically redacted
logger.info("User login", {
email: "user@example.com",
password: "[REDACTED]", // Automatically sanitized
token: "[REDACTED]", // Automatically sanitized
ipAddress: "192.168.1.1", // Safe to log
});
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **Sanitized Headers**
2025-08-21 15:24:40 +09:00
```typescript
2025-08-22 17:02:49 +09:00
// Request headers are automatically cleaned
{
"authorization": "[REDACTED]",
"cookie": "[REDACTED]",
"x-api-key": "[REDACTED]",
"user-agent": "Mozilla/5.0...", // Safe to log
"accept": "application/json" // Safe to log
}
```
## 🔄 **Migration Guide**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **From @nestjs/common Logger**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// ❌ OLD: @nestjs/common Logger
import { Logger } from "@nestjs/common";
private readonly logger = new Logger(ServiceName.name);
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
// ✅ NEW: nestjs-pino Logger
import { Logger } from "nestjs-pino";
constructor(@Inject(Logger) private readonly logger: Logger) {}
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **From Console Logging**
2025-08-21 15:24:40 +09:00
```typescript
2025-08-22 17:02:49 +09:00
// ❌ OLD: Console methods
console.log("Debug info");
console.error("Error occurred");
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
// ✅ NEW: Structured logger
logger.debug("Debug info");
logger.error("Error occurred");
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
### **From Winston**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```typescript
// ❌ OLD: Winston logger
import * as winston from 'winston';
const logger = winston.createLogger({...});
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
// ✅ NEW: Pino logger
import { Logger } from "nestjs-pino";
constructor(@Inject(Logger) private readonly logger: Logger) {}
2025-08-21 15:24:40 +09:00
```
2025-08-22 17:02:49 +09:00
## 📋 **Best Practices**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **✅ Do's**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- Use structured logging with context
- Include correlation IDs in all logs
- Log at appropriate levels
- Sanitize sensitive data
- Use consistent message formats
### **❌ Don'ts**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- Don't mix logging systems
- Don't use console methods in production
- Don't log sensitive information
- Don't log large objects unnecessarily
- Don't use string interpolation for logging
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 🛠️ **Troubleshooting**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Common Issues**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
1. **Multiple Logger Instances**: Ensure single logger per service
2. **Missing Correlation IDs**: Check middleware configuration
3. **Performance Issues**: Verify log level settings
4. **Missing Logs**: Check file permissions and disk space
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
### **Debug Mode**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
```bash
# Enable debug logging
LOG_LEVEL=debug pnpm dev
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
# Check logger configuration
LOG_LEVEL=trace pnpm dev
```
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
## 📚 **Additional Resources**
2025-08-21 15:24:40 +09:00
2025-08-22 17:02:49 +09:00
- [Pino Documentation](https://getpino.io/)
- [NestJS Pino Module](https://github.com/iamolegga/nestjs-pino)
- [Structured Logging Best Practices](https://12factor.net/logs)
- [Log Correlation Patterns](https://microservices.io/patterns/observability/distributed-tracing.html)