462 lines
14 KiB
TypeScript
462 lines
14 KiB
TypeScript
/**
|
|
* Comprehensive Hono middleware for request logging with Pino integration
|
|
*/
|
|
|
|
import type { Context, Next } from 'hono';
|
|
import { Logger } from './logger';
|
|
import { generateCorrelationId, createTimer, sanitizeMetadata, LogThrottle } from './utils';
|
|
|
|
export interface LoggingMiddlewareOptions {
|
|
logger?: Logger;
|
|
serviceName?: string;
|
|
skipPaths?: string[];
|
|
skipSuccessfulRequests?: boolean;
|
|
logRequestBody?: boolean;
|
|
logResponseBody?: boolean;
|
|
maxBodySize?: number;
|
|
enablePerformanceMetrics?: boolean;
|
|
enableThrottling?: boolean;
|
|
throttleConfig?: {
|
|
maxLogs?: number;
|
|
windowMs?: number;
|
|
};
|
|
sensitiveHeaders?: string[];
|
|
redactSensitiveData?: boolean;
|
|
}
|
|
|
|
/**
|
|
* Hono middleware for HTTP request/response logging with enhanced features
|
|
*/
|
|
export function loggingMiddleware(options: LoggingMiddlewareOptions = {}) {
|
|
const {
|
|
serviceName = 'unknown-service',
|
|
skipPaths = ['/health', '/metrics', '/favicon.ico'],
|
|
skipSuccessfulRequests = false,
|
|
logRequestBody = false,
|
|
logResponseBody = false,
|
|
maxBodySize = 1024,
|
|
enablePerformanceMetrics = true,
|
|
enableThrottling = false,
|
|
throttleConfig = { maxLogs: 100, windowMs: 60000 },
|
|
sensitiveHeaders = ['authorization', 'cookie', 'x-api-key', 'x-auth-token'],
|
|
redactSensitiveData = true
|
|
} = options;
|
|
|
|
// Create logger if not provided
|
|
const logger = options.logger || new Logger(serviceName);
|
|
|
|
// Create throttle instance if enabled
|
|
const throttle = enableThrottling ? new LogThrottle(throttleConfig.maxLogs, throttleConfig.windowMs) : null;
|
|
|
|
return async (c: Context, next: Next) => {
|
|
const url = new URL(c.req.url);
|
|
const path = url.pathname;
|
|
|
|
// Skip certain paths
|
|
if (skipPaths.some(skipPath => path.startsWith(skipPath))) {
|
|
return next();
|
|
}
|
|
|
|
// Check throttling
|
|
const throttleKey = `${c.req.method}-${path}`;
|
|
if (throttle && !throttle.shouldLog(throttleKey)) {
|
|
return next();
|
|
}
|
|
|
|
// Generate correlation ID
|
|
const correlationId = generateCorrelationId();
|
|
// Store correlation ID in context for later use
|
|
c.set('correlationId', correlationId);
|
|
// Set correlation ID as response header
|
|
c.header('x-correlation-id', correlationId);
|
|
|
|
// Start timer
|
|
const timer = createTimer(`${c.req.method} ${path}`);
|
|
|
|
// Extract request headers (sanitized)
|
|
const rawHeaders = Object.fromEntries(
|
|
Array.from(c.req.raw.headers.entries())
|
|
);
|
|
|
|
const headers = redactSensitiveData
|
|
? Object.fromEntries(
|
|
Object.entries(rawHeaders).map(([key, value]) => [
|
|
key,
|
|
sensitiveHeaders.some(sensitive => key.toLowerCase().includes(sensitive.toLowerCase()))
|
|
? '[REDACTED]'
|
|
: value
|
|
])
|
|
)
|
|
: rawHeaders; // Extract request metadata following LogMetadata.request structure
|
|
const requestMetadata: any = {
|
|
method: c.req.method,
|
|
url: c.req.url,
|
|
path: path,
|
|
userAgent: c.req.header('user-agent'),
|
|
contentType: c.req.header('content-type'),
|
|
contentLength: c.req.header('content-length'),
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown',
|
|
headers: headers
|
|
};
|
|
// Add request body if enabled
|
|
if (logRequestBody) {
|
|
try {
|
|
const body = await c.req.text();
|
|
if (body) {
|
|
requestMetadata.body = body.length > maxBodySize
|
|
? body.substring(0, maxBodySize) + '...[truncated]'
|
|
: body;
|
|
}
|
|
} catch (error) {
|
|
// Body might not be available or already consumed
|
|
requestMetadata.bodyError = 'Unable to read request body';
|
|
}
|
|
} // Log request start with structured data
|
|
logger.http('HTTP Request started', {
|
|
method: c.req.method,
|
|
url: c.req.url,
|
|
userAgent: c.req.header('user-agent'),
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown'
|
|
});
|
|
|
|
let error: Error | null = null;
|
|
let responseTime: number = 0;
|
|
|
|
try {
|
|
// Process request
|
|
await next();
|
|
} catch (err) {
|
|
error = err instanceof Error ? err : new Error(String(err));
|
|
throw error; // Re-throw to maintain error handling flow
|
|
} finally {
|
|
// Calculate response time
|
|
const timing = timer.end();
|
|
responseTime = timing.duration;
|
|
|
|
// Get response information
|
|
const response = c.res;
|
|
const status = response.status;
|
|
|
|
// Determine log level based on status code
|
|
const isError = status >= 400 || error !== null;
|
|
const isSuccess = status >= 200 && status < 300;
|
|
const isRedirect = status >= 300 && status < 400;
|
|
|
|
// Skip successful requests if configured
|
|
if (skipSuccessfulRequests && isSuccess && !error) {
|
|
return;
|
|
}
|
|
|
|
// Extract response headers (sanitized)
|
|
const rawResponseHeaders = Object.fromEntries(
|
|
Array.from(response.headers.entries())
|
|
);
|
|
|
|
const responseHeaders = redactSensitiveData
|
|
? Object.fromEntries(
|
|
Object.entries(rawResponseHeaders).map(([key, value]) => [
|
|
key,
|
|
sensitiveHeaders.some(sensitive => key.toLowerCase().includes(sensitive.toLowerCase()))
|
|
? '[REDACTED]'
|
|
: value
|
|
])
|
|
)
|
|
: rawResponseHeaders;
|
|
|
|
const responseMetadata: any = {
|
|
statusCode: status,
|
|
statusText: response.statusText,
|
|
headers: responseHeaders,
|
|
contentLength: response.headers.get('content-length'),
|
|
contentType: response.headers.get('content-type')
|
|
};
|
|
|
|
// Add response body if enabled and not an error
|
|
if (logResponseBody && !isError) {
|
|
try {
|
|
const responseBody = await response.clone().text();
|
|
if (responseBody) {
|
|
responseMetadata.body = responseBody.length > maxBodySize
|
|
? responseBody.substring(0, maxBodySize) + '...[truncated]'
|
|
: responseBody;
|
|
}
|
|
} catch (bodyError) {
|
|
responseMetadata.bodyError = 'Unable to read response body';
|
|
}
|
|
} // Performance metrics matching LogMetadata.performance structure
|
|
const performanceMetrics = {
|
|
operation: timing.operation,
|
|
duration: timing.duration,
|
|
startTime: enablePerformanceMetrics ? timing.startTime : undefined,
|
|
endTime: enablePerformanceMetrics ? timing.endTime : undefined
|
|
}; // Create comprehensive log entry
|
|
const logEntry: any = {
|
|
correlationId,
|
|
request: requestMetadata,
|
|
response: responseMetadata,
|
|
performance: performanceMetrics,
|
|
type: error ? 'custom' : isError ? 'custom' : 'http_request'
|
|
};
|
|
|
|
// Sanitize if needed
|
|
const finalLogEntry = redactSensitiveData ? sanitizeMetadata(logEntry) : logEntry; // Log based on status code and errors
|
|
if (error) {
|
|
logger.error('HTTP Request error', error, finalLogEntry);
|
|
} else if (isError) {
|
|
logger.warn('HTTP Request failed', finalLogEntry);
|
|
} else if (isRedirect) {
|
|
logger.info('HTTP Request redirected', finalLogEntry);
|
|
} else {
|
|
logger.http('HTTP Request completed', {
|
|
method: c.req.method,
|
|
url: c.req.url,
|
|
statusCode: status,
|
|
responseTime: timing.duration,
|
|
userAgent: c.req.header('user-agent'),
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown'
|
|
});
|
|
}
|
|
}
|
|
};
|
|
}
|
|
|
|
/**
|
|
* Error logging middleware for Hono
|
|
*/
|
|
export function errorLoggingMiddleware(logger?: Logger) {
|
|
return async (c: Context, next: Next) => {
|
|
const errorLogger = logger || new Logger('error-handler');
|
|
|
|
try {
|
|
await next();
|
|
} catch (err) {
|
|
const correlationId = c.get('correlationId') || c.req.header('x-correlation-id');
|
|
const url = new URL(c.req.url);
|
|
|
|
const requestMetadata = {
|
|
method: c.req.method,
|
|
url: c.req.url,
|
|
path: url.pathname,
|
|
userAgent: c.req.header('user-agent'),
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown'
|
|
};
|
|
|
|
errorLogger.error('Unhandled HTTP error', err instanceof Error ? err : new Error(String(err)), {
|
|
correlationId,
|
|
request: requestMetadata,
|
|
response: {
|
|
statusCode: c.res.status
|
|
}
|
|
});
|
|
|
|
// Re-throw the error so Hono can handle it
|
|
throw err;
|
|
}
|
|
};
|
|
}
|
|
|
|
/**
|
|
* Create a child logger with request context for Hono
|
|
*/
|
|
export function createRequestLogger(c: Context, baseLogger: Logger): Logger {
|
|
const correlationId = c.get('correlationId') || c.req.header('x-correlation-id');
|
|
const url = new URL(c.req.url);
|
|
|
|
return baseLogger.child({
|
|
correlationId,
|
|
requestId: correlationId,
|
|
method: c.req.method,
|
|
path: url.pathname,
|
|
userAgent: c.req.header('user-agent'),
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown'
|
|
});
|
|
}
|
|
|
|
/**
|
|
* Performance monitoring middleware for specific operations
|
|
*/
|
|
export function performanceMiddleware(operationName?: string, logger?: Logger) {
|
|
return async (c: Context, next: Next) => {
|
|
const perfLogger = logger || new Logger('performance');
|
|
const operation = operationName || `${c.req.method} ${new URL(c.req.url).pathname}`;
|
|
const timer = createTimer(operation);
|
|
|
|
try {
|
|
await next();
|
|
|
|
const timing = timer.end();
|
|
perfLogger.info('Operation completed', {
|
|
type: 'performance',
|
|
performance: timing,
|
|
correlationId: c.get('correlationId')
|
|
});
|
|
} catch (error) {
|
|
const timing = timer.end();
|
|
perfLogger.warn('Operation failed', {
|
|
type: 'performance',
|
|
performance: timing,
|
|
correlationId: c.get('correlationId'),
|
|
error: error instanceof Error ? {
|
|
name: error.name,
|
|
message: error.message,
|
|
stack: error.stack
|
|
} : { message: String(error) }
|
|
});
|
|
throw error;
|
|
}
|
|
};
|
|
}
|
|
|
|
/**
|
|
* Security event logging middleware
|
|
*/
|
|
export function securityMiddleware(logger?: Logger) {
|
|
return async (c: Context, next: Next) => {
|
|
const secLogger = logger || new Logger('security');
|
|
const url = new URL(c.req.url);
|
|
|
|
// Log authentication attempts
|
|
const authHeader = c.req.header('authorization');
|
|
if (authHeader) {
|
|
secLogger.info('Authentication attempt', {
|
|
type: 'security_event',
|
|
security: {
|
|
type: 'authentication',
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown',
|
|
resource: url.pathname,
|
|
action: 'access_attempt'
|
|
},
|
|
correlationId: c.get('correlationId')
|
|
});
|
|
}
|
|
|
|
await next();
|
|
|
|
// Log access control
|
|
const status = c.res.status;
|
|
if (status === 401 || status === 403) {
|
|
secLogger.warn('Access denied', {
|
|
type: 'security_event',
|
|
security: {
|
|
type: 'authorization',
|
|
result: 'failure',
|
|
ip: c.req.header('x-forwarded-for') || c.req.header('x-real-ip') || 'unknown',
|
|
resource: url.pathname,
|
|
action: c.req.method,
|
|
severity: status === 401 ? 'medium' : 'high'
|
|
},
|
|
correlationId: c.get('correlationId')
|
|
});
|
|
}
|
|
};
|
|
}
|
|
|
|
/**
|
|
* Business event logging middleware for trading operations
|
|
*/
|
|
export function businessEventMiddleware(logger?: Logger) {
|
|
return async (c: Context, next: Next) => {
|
|
const bizLogger = logger || new Logger('business');
|
|
const url = new URL(c.req.url);
|
|
const path = url.pathname;
|
|
|
|
// Check if this is a business-critical endpoint
|
|
const businessEndpoints = [
|
|
'/api/orders',
|
|
'/api/trades',
|
|
'/api/portfolio',
|
|
'/api/strategies',
|
|
'/api/signals'
|
|
];
|
|
|
|
const isBusinessEndpoint = businessEndpoints.some(endpoint => path.startsWith(endpoint));
|
|
|
|
if (isBusinessEndpoint) {
|
|
const timer = createTimer(`business_${c.req.method}_${path}`);
|
|
|
|
try {
|
|
await next();
|
|
|
|
const timing = timer.end();
|
|
const status = c.res.status;
|
|
|
|
bizLogger.info('Business operation completed', {
|
|
type: 'business_event',
|
|
business: {
|
|
type: 'trading_operation',
|
|
action: c.req.method,
|
|
result: status >= 200 && status < 300 ? 'success' : 'failure'
|
|
},
|
|
performance: timing,
|
|
correlationId: c.get('correlationId')
|
|
});
|
|
} catch (error) {
|
|
const timing = timer.end();
|
|
|
|
bizLogger.error('Business operation failed', error, {
|
|
type: 'business_event',
|
|
business: {
|
|
type: 'trading_operation',
|
|
action: c.req.method,
|
|
result: 'failure'
|
|
},
|
|
performance: timing,
|
|
correlationId: c.get('correlationId')
|
|
});
|
|
throw error;
|
|
}
|
|
} else {
|
|
await next();
|
|
}
|
|
};
|
|
}
|
|
|
|
/**
|
|
* Comprehensive logging middleware that combines all logging features
|
|
*/
|
|
export function comprehensiveLoggingMiddleware(options: LoggingMiddlewareOptions & {
|
|
enableSecurity?: boolean;
|
|
enableBusiness?: boolean;
|
|
enablePerformance?: boolean;
|
|
} = {}) {
|
|
const {
|
|
enableSecurity = true,
|
|
enableBusiness = true,
|
|
enablePerformance = true,
|
|
...loggingOptions
|
|
} = options;
|
|
return async (c: Context, next: Next) => {
|
|
const middlewares: Array<(c: Context, next: Next) => Promise<void>> = [];
|
|
|
|
// Add security middleware
|
|
if (enableSecurity) {
|
|
middlewares.push(securityMiddleware(options.logger));
|
|
}
|
|
|
|
// Add performance middleware
|
|
if (enablePerformance) {
|
|
middlewares.push(performanceMiddleware(undefined, options.logger));
|
|
}
|
|
|
|
// Add business event middleware
|
|
if (enableBusiness) {
|
|
middlewares.push(businessEventMiddleware(options.logger));
|
|
}
|
|
|
|
// Add main logging middleware
|
|
middlewares.push(loggingMiddleware(loggingOptions));
|
|
|
|
// Execute middleware chain
|
|
let index = 0;
|
|
async function dispatch(i: number): Promise<void> {
|
|
if (i >= middlewares.length) {
|
|
return next();
|
|
}
|
|
|
|
const middleware = middlewares[i];
|
|
return middleware(c, () => dispatch(i + 1));
|
|
}
|
|
|
|
return dispatch(0);
|
|
};
|
|
}
|