514 lines
15 KiB
TypeScript
514 lines
15 KiB
TypeScript
|
/**
|
||
|
|
* Adaptive SMTP Logging System
|
||
|
|
* Automatically switches between logging modes based on server load (active connections)
|
||
|
|
* to maintain performance during high-concurrency scenarios
|
||
|
|
*/
|
||
|
|
|
||
|
|
import * as plugins from '../../../../plugins.ts';
|
||
|
|
import { logger } from '../../../../logger.ts';
|
||
|
|
import { SecurityLogLevel, SecurityEventType } from '../constants.ts';
|
||
|
|
import type { ISmtpSession } from '../interfaces.ts';
|
||
|
|
import type { LogLevel, ISmtpLogOptions } from './logging.ts';
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log modes based on server load
|
||
|
|
*/
|
||
|
|
export enum LogMode {
|
||
|
|
VERBOSE = 'VERBOSE', // < 20 connections: Full detailed logging
|
||
|
|
REDUCED = 'REDUCED', // 20-40 connections: Limited command/response logging, full error logging
|
||
|
|
MINIMAL = 'MINIMAL' // 40+ connections: Aggregated logging only, critical errors only
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Configuration for adaptive logging thresholds
|
||
|
|
*/
|
||
|
|
export interface IAdaptiveLogConfig {
|
||
|
|
verboseThreshold: number; // Switch to REDUCED mode above this connection count
|
||
|
|
reducedThreshold: number; // Switch to MINIMAL mode above this connection count
|
||
|
|
aggregationInterval: number; // How often to flush aggregated logs (ms)
|
||
|
|
maxAggregatedEntries: number; // Max entries to hold before forced flush
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Aggregated log entry for batching similar events
|
||
|
|
*/
|
||
|
|
interface IAggregatedLogEntry {
|
||
|
|
type: 'connection' | 'command' | 'response' | 'error';
|
||
|
|
count: number;
|
||
|
|
firstSeen: number;
|
||
|
|
lastSeen: number;
|
||
|
|
sample: {
|
||
|
|
message: string;
|
||
|
|
level: LogLevel;
|
||
|
|
options?: ISmtpLogOptions;
|
||
|
|
};
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Connection metadata for aggregation tracking
|
||
|
|
*/
|
||
|
|
interface IConnectionTracker {
|
||
|
|
activeConnections: number;
|
||
|
|
peakConnections: number;
|
||
|
|
totalConnections: number;
|
||
|
|
connectionsPerSecond: number;
|
||
|
|
lastConnectionTime: number;
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Adaptive SMTP Logger that scales logging based on server load
|
||
|
|
*/
|
||
|
|
export class AdaptiveSmtpLogger {
|
||
|
|
private static instance: AdaptiveSmtpLogger;
|
||
|
|
private currentMode: LogMode = LogMode.VERBOSE;
|
||
|
|
private config: IAdaptiveLogConfig;
|
||
|
|
private aggregatedEntries: Map<string, IAggregatedLogEntry> = new Map();
|
||
|
|
private aggregationTimer: NodeJS.Timeout | null = null;
|
||
|
|
private connectionTracker: IConnectionTracker = {
|
||
|
|
activeConnections: 0,
|
||
|
|
peakConnections: 0,
|
||
|
|
totalConnections: 0,
|
||
|
|
connectionsPerSecond: 0,
|
||
|
|
lastConnectionTime: Date.now()
|
||
|
|
};
|
||
|
|
|
||
|
|
private constructor(config?: Partial<IAdaptiveLogConfig>) {
|
||
|
|
this.config = {
|
||
|
|
verboseThreshold: 20,
|
||
|
|
reducedThreshold: 40,
|
||
|
|
aggregationInterval: 30000, // 30 seconds
|
||
|
|
maxAggregatedEntries: 100,
|
||
|
|
...config
|
||
|
|
};
|
||
|
|
|
||
|
|
this.startAggregationTimer();
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Get singleton instance
|
||
|
|
*/
|
||
|
|
public static getInstance(config?: Partial<IAdaptiveLogConfig>): AdaptiveSmtpLogger {
|
||
|
|
if (!AdaptiveSmtpLogger.instance) {
|
||
|
|
AdaptiveSmtpLogger.instance = new AdaptiveSmtpLogger(config);
|
||
|
|
}
|
||
|
|
return AdaptiveSmtpLogger.instance;
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Update active connection count and adjust log mode if needed
|
||
|
|
*/
|
||
|
|
public updateConnectionCount(activeConnections: number): void {
|
||
|
|
this.connectionTracker.activeConnections = activeConnections;
|
||
|
|
this.connectionTracker.peakConnections = Math.max(
|
||
|
|
this.connectionTracker.peakConnections,
|
||
|
|
activeConnections
|
||
|
|
);
|
||
|
|
|
||
|
|
const newMode = this.determineLogMode(activeConnections);
|
||
|
|
if (newMode !== this.currentMode) {
|
||
|
|
this.switchLogMode(newMode);
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Track new connection for rate calculation
|
||
|
|
*/
|
||
|
|
public trackConnection(): void {
|
||
|
|
this.connectionTracker.totalConnections++;
|
||
|
|
const now = Date.now();
|
||
|
|
const timeDiff = (now - this.connectionTracker.lastConnectionTime) / 1000;
|
||
|
|
if (timeDiff > 0) {
|
||
|
|
this.connectionTracker.connectionsPerSecond = 1 / timeDiff;
|
||
|
|
}
|
||
|
|
this.connectionTracker.lastConnectionTime = now;
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Get current logging mode
|
||
|
|
*/
|
||
|
|
public getCurrentMode(): LogMode {
|
||
|
|
return this.currentMode;
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Get connection statistics
|
||
|
|
*/
|
||
|
|
public getConnectionStats(): IConnectionTracker {
|
||
|
|
return { ...this.connectionTracker };
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log a message with adaptive behavior
|
||
|
|
*/
|
||
|
|
public log(level: LogLevel, message: string, options: ISmtpLogOptions = {}): void {
|
||
|
|
// Always log structured data
|
||
|
|
const errorInfo = options.error ? {
|
||
|
|
errorMessage: options.error.message,
|
||
|
|
errorStack: options.error.stack,
|
||
|
|
errorName: options.error.name
|
||
|
|
} : {};
|
||
|
|
|
||
|
|
const logData = {
|
||
|
|
component: 'smtp-server',
|
||
|
|
logMode: this.currentMode,
|
||
|
|
activeConnections: this.connectionTracker.activeConnections,
|
||
|
|
...options,
|
||
|
|
...errorInfo
|
||
|
|
};
|
||
|
|
|
||
|
|
if (logData.error) {
|
||
|
|
delete logData.error;
|
||
|
|
}
|
||
|
|
|
||
|
|
logger.log(level, message, logData);
|
||
|
|
|
||
|
|
// Adaptive console logging based on mode
|
||
|
|
switch (this.currentMode) {
|
||
|
|
case LogMode.VERBOSE:
|
||
|
|
// Full console logging
|
||
|
|
if (level === 'error' || level === 'warn') {
|
||
|
|
console[level](`[SMTP] ${message}`, logData);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.REDUCED:
|
||
|
|
// Only errors and warnings to console
|
||
|
|
if (level === 'error' || level === 'warn') {
|
||
|
|
console[level](`[SMTP] ${message}`, logData);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.MINIMAL:
|
||
|
|
// Only critical errors to console
|
||
|
|
if (level === 'error' && (message.includes('critical') || message.includes('security') || message.includes('crash'))) {
|
||
|
|
console[level](`[SMTP] ${message}`, logData);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log command with adaptive behavior
|
||
|
|
*/
|
||
|
|
public logCommand(command: string, socket: plugins.net.Socket | plugins.tls.TLSSocket, session?: ISmtpSession): void {
|
||
|
|
const clientInfo = {
|
||
|
|
remoteAddress: socket.remoteAddress,
|
||
|
|
remotePort: socket.remotePort,
|
||
|
|
secure: socket instanceof plugins.tls.TLSSocket,
|
||
|
|
sessionId: session?.id,
|
||
|
|
sessionState: session?.state
|
||
|
|
};
|
||
|
|
|
||
|
|
switch (this.currentMode) {
|
||
|
|
case LogMode.VERBOSE:
|
||
|
|
this.log('info', `Command received: ${command}`, {
|
||
|
|
...clientInfo,
|
||
|
|
command: command.split(' ')[0]?.toUpperCase()
|
||
|
|
});
|
||
|
|
console.log(`← ${command}`);
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.REDUCED:
|
||
|
|
// Aggregate commands instead of logging each one
|
||
|
|
this.aggregateEntry('command', 'info', `Command: ${command.split(' ')[0]?.toUpperCase()}`, clientInfo);
|
||
|
|
// Only show error commands
|
||
|
|
if (command.toUpperCase().startsWith('QUIT') || command.includes('error')) {
|
||
|
|
console.log(`← ${command}`);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.MINIMAL:
|
||
|
|
// Only aggregate, no console output unless it's an error command
|
||
|
|
this.aggregateEntry('command', 'info', `Command: ${command.split(' ')[0]?.toUpperCase()}`, clientInfo);
|
||
|
|
break;
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log response with adaptive behavior
|
||
|
|
*/
|
||
|
|
public logResponse(response: string, socket: plugins.net.Socket | plugins.tls.TLSSocket): void {
|
||
|
|
const clientInfo = {
|
||
|
|
remoteAddress: socket.remoteAddress,
|
||
|
|
remotePort: socket.remotePort,
|
||
|
|
secure: socket instanceof plugins.tls.TLSSocket
|
||
|
|
};
|
||
|
|
|
||
|
|
const responseCode = response.substring(0, 3);
|
||
|
|
const isError = responseCode.startsWith('4') || responseCode.startsWith('5');
|
||
|
|
|
||
|
|
switch (this.currentMode) {
|
||
|
|
case LogMode.VERBOSE:
|
||
|
|
if (responseCode.startsWith('2') || responseCode.startsWith('3')) {
|
||
|
|
this.log('debug', `Response sent: ${response}`, clientInfo);
|
||
|
|
} else if (responseCode.startsWith('4')) {
|
||
|
|
this.log('warn', `Temporary error response: ${response}`, clientInfo);
|
||
|
|
} else if (responseCode.startsWith('5')) {
|
||
|
|
this.log('error', `Permanent error response: ${response}`, clientInfo);
|
||
|
|
}
|
||
|
|
console.log(`→ ${response}`);
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.REDUCED:
|
||
|
|
// Log errors normally, aggregate success responses
|
||
|
|
if (isError) {
|
||
|
|
if (responseCode.startsWith('4')) {
|
||
|
|
this.log('warn', `Temporary error response: ${response}`, clientInfo);
|
||
|
|
} else {
|
||
|
|
this.log('error', `Permanent error response: ${response}`, clientInfo);
|
||
|
|
}
|
||
|
|
console.log(`→ ${response}`);
|
||
|
|
} else {
|
||
|
|
this.aggregateEntry('response', 'debug', `Response: ${responseCode}xx`, clientInfo);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.MINIMAL:
|
||
|
|
// Only log critical errors
|
||
|
|
if (responseCode.startsWith('5')) {
|
||
|
|
this.log('error', `Permanent error response: ${response}`, clientInfo);
|
||
|
|
console.log(`→ ${response}`);
|
||
|
|
} else {
|
||
|
|
this.aggregateEntry('response', 'debug', `Response: ${responseCode}xx`, clientInfo);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log connection event with adaptive behavior
|
||
|
|
*/
|
||
|
|
public logConnection(
|
||
|
|
socket: plugins.net.Socket | plugins.tls.TLSSocket,
|
||
|
|
eventType: 'connect' | 'close' | 'error',
|
||
|
|
session?: ISmtpSession,
|
||
|
|
error?: Error
|
||
|
|
): void {
|
||
|
|
const clientInfo = {
|
||
|
|
remoteAddress: socket.remoteAddress,
|
||
|
|
remotePort: socket.remotePort,
|
||
|
|
secure: socket instanceof plugins.tls.TLSSocket,
|
||
|
|
sessionId: session?.id,
|
||
|
|
sessionState: session?.state
|
||
|
|
};
|
||
|
|
|
||
|
|
if (eventType === 'connect') {
|
||
|
|
this.trackConnection();
|
||
|
|
}
|
||
|
|
|
||
|
|
switch (this.currentMode) {
|
||
|
|
case LogMode.VERBOSE:
|
||
|
|
// Full connection logging
|
||
|
|
switch (eventType) {
|
||
|
|
case 'connect':
|
||
|
|
this.log('info', `New ${clientInfo.secure ? 'secure ' : ''}connection from ${clientInfo.remoteAddress}:${clientInfo.remotePort}`, clientInfo);
|
||
|
|
break;
|
||
|
|
case 'close':
|
||
|
|
this.log('info', `Connection closed from ${clientInfo.remoteAddress}:${clientInfo.remotePort}`, clientInfo);
|
||
|
|
break;
|
||
|
|
case 'error':
|
||
|
|
this.log('error', `Connection error from ${clientInfo.remoteAddress}:${clientInfo.remotePort}`, {
|
||
|
|
...clientInfo,
|
||
|
|
error
|
||
|
|
});
|
||
|
|
break;
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.REDUCED:
|
||
|
|
// Aggregate normal connections, log errors
|
||
|
|
if (eventType === 'error') {
|
||
|
|
this.log('error', `Connection error from ${clientInfo.remoteAddress}:${clientInfo.remotePort}`, {
|
||
|
|
...clientInfo,
|
||
|
|
error
|
||
|
|
});
|
||
|
|
} else {
|
||
|
|
this.aggregateEntry('connection', 'info', `Connection ${eventType}`, clientInfo);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
|
||
|
|
case LogMode.MINIMAL:
|
||
|
|
// Only aggregate, except for critical errors
|
||
|
|
if (eventType === 'error' && error && (error.message.includes('security') || error.message.includes('critical'))) {
|
||
|
|
this.log('error', `Critical connection error from ${clientInfo.remoteAddress}:${clientInfo.remotePort}`, {
|
||
|
|
...clientInfo,
|
||
|
|
error
|
||
|
|
});
|
||
|
|
} else {
|
||
|
|
this.aggregateEntry('connection', 'info', `Connection ${eventType}`, clientInfo);
|
||
|
|
}
|
||
|
|
break;
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Log security event (always logged regardless of mode)
|
||
|
|
*/
|
||
|
|
public logSecurityEvent(
|
||
|
|
level: SecurityLogLevel,
|
||
|
|
type: SecurityEventType,
|
||
|
|
message: string,
|
||
|
|
details: Record<string, any>,
|
||
|
|
ipAddress?: string,
|
||
|
|
domain?: string,
|
||
|
|
success?: boolean
|
||
|
|
): void {
|
||
|
|
const logLevel: LogLevel = level === SecurityLogLevel.DEBUG ? 'debug' :
|
||
|
|
level === SecurityLogLevel.INFO ? 'info' :
|
||
|
|
level === SecurityLogLevel.WARN ? 'warn' : 'error';
|
||
|
|
|
||
|
|
// Security events are always logged in full detail
|
||
|
|
this.log(logLevel, message, {
|
||
|
|
component: 'smtp-security',
|
||
|
|
eventType: type,
|
||
|
|
success,
|
||
|
|
ipAddress,
|
||
|
|
domain,
|
||
|
|
...details
|
||
|
|
});
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Determine appropriate log mode based on connection count
|
||
|
|
*/
|
||
|
|
private determineLogMode(activeConnections: number): LogMode {
|
||
|
|
if (activeConnections >= this.config.reducedThreshold) {
|
||
|
|
return LogMode.MINIMAL;
|
||
|
|
} else if (activeConnections >= this.config.verboseThreshold) {
|
||
|
|
return LogMode.REDUCED;
|
||
|
|
} else {
|
||
|
|
return LogMode.VERBOSE;
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Switch to a new log mode
|
||
|
|
*/
|
||
|
|
private switchLogMode(newMode: LogMode): void {
|
||
|
|
const oldMode = this.currentMode;
|
||
|
|
this.currentMode = newMode;
|
||
|
|
|
||
|
|
// Log the mode switch
|
||
|
|
console.log(`[SMTP] Adaptive logging switched from ${oldMode} to ${newMode} (${this.connectionTracker.activeConnections} active connections)`);
|
||
|
|
|
||
|
|
this.log('info', `Adaptive logging mode changed to ${newMode}`, {
|
||
|
|
oldMode,
|
||
|
|
newMode,
|
||
|
|
activeConnections: this.connectionTracker.activeConnections,
|
||
|
|
peakConnections: this.connectionTracker.peakConnections,
|
||
|
|
totalConnections: this.connectionTracker.totalConnections
|
||
|
|
});
|
||
|
|
|
||
|
|
// If switching to more verbose mode, flush aggregated entries
|
||
|
|
if ((oldMode === LogMode.MINIMAL && newMode !== LogMode.MINIMAL) ||
|
||
|
|
(oldMode === LogMode.REDUCED && newMode === LogMode.VERBOSE)) {
|
||
|
|
this.flushAggregatedEntries();
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Add entry to aggregation buffer
|
||
|
|
*/
|
||
|
|
private aggregateEntry(
|
||
|
|
type: 'connection' | 'command' | 'response' | 'error',
|
||
|
|
level: LogLevel,
|
||
|
|
message: string,
|
||
|
|
options?: ISmtpLogOptions
|
||
|
|
): void {
|
||
|
|
const key = `${type}:${message}`;
|
||
|
|
const now = Date.now();
|
||
|
|
|
||
|
|
if (this.aggregatedEntries.has(key)) {
|
||
|
|
const entry = this.aggregatedEntries.get(key)!;
|
||
|
|
entry.count++;
|
||
|
|
entry.lastSeen = now;
|
||
|
|
} else {
|
||
|
|
this.aggregatedEntries.set(key, {
|
||
|
|
type,
|
||
|
|
count: 1,
|
||
|
|
firstSeen: now,
|
||
|
|
lastSeen: now,
|
||
|
|
sample: { message, level, options }
|
||
|
|
});
|
||
|
|
}
|
||
|
|
|
||
|
|
// Force flush if we have too many entries
|
||
|
|
if (this.aggregatedEntries.size >= this.config.maxAggregatedEntries) {
|
||
|
|
this.flushAggregatedEntries();
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Start the aggregation timer
|
||
|
|
*/
|
||
|
|
private startAggregationTimer(): void {
|
||
|
|
if (this.aggregationTimer) {
|
||
|
|
clearInterval(this.aggregationTimer);
|
||
|
|
}
|
||
|
|
|
||
|
|
this.aggregationTimer = setInterval(() => {
|
||
|
|
this.flushAggregatedEntries();
|
||
|
|
}, this.config.aggregationInterval);
|
||
|
|
|
||
|
|
// Unref the timer so it doesn't keep the process alive
|
||
|
|
if (this.aggregationTimer && typeof this.aggregationTimer.unref === 'function') {
|
||
|
|
this.aggregationTimer.unref();
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Flush aggregated entries to logs
|
||
|
|
*/
|
||
|
|
private flushAggregatedEntries(): void {
|
||
|
|
if (this.aggregatedEntries.size === 0) {
|
||
|
|
return;
|
||
|
|
}
|
||
|
|
|
||
|
|
const summary: Record<string, number> = {};
|
||
|
|
let totalAggregated = 0;
|
||
|
|
|
||
|
|
for (const [key, entry] of this.aggregatedEntries.entries()) {
|
||
|
|
summary[entry.type] = (summary[entry.type] || 0) + entry.count;
|
||
|
|
totalAggregated += entry.count;
|
||
|
|
|
||
|
|
// Log a sample of high-frequency entries
|
||
|
|
if (entry.count >= 10) {
|
||
|
|
this.log(entry.sample.level, `${entry.sample.message} (aggregated: ${entry.count} occurrences)`, {
|
||
|
|
...entry.sample.options,
|
||
|
|
aggregated: true,
|
||
|
|
occurrences: entry.count,
|
||
|
|
timeSpan: entry.lastSeen - entry.firstSeen
|
||
|
|
});
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
// Log aggregation summary
|
||
|
|
console.log(`[SMTP] Aggregated ${totalAggregated} log entries: ${JSON.stringify(summary)}`);
|
||
|
|
|
||
|
|
this.log('info', 'Aggregated log summary', {
|
||
|
|
totalEntries: totalAggregated,
|
||
|
|
breakdown: summary,
|
||
|
|
logMode: this.currentMode,
|
||
|
|
activeConnections: this.connectionTracker.activeConnections
|
||
|
|
});
|
||
|
|
|
||
|
|
// Clear aggregated entries
|
||
|
|
this.aggregatedEntries.clear();
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Cleanup resources
|
||
|
|
*/
|
||
|
|
public destroy(): void {
|
||
|
|
if (this.aggregationTimer) {
|
||
|
|
clearInterval(this.aggregationTimer);
|
||
|
|
this.aggregationTimer = null;
|
||
|
|
}
|
||
|
|
this.flushAggregatedEntries();
|
||
|
|
}
|
||
|
|
}
|
||
|
|
|
||
|
|
/**
|
||
|
|
* Default instance for easy access
|
||
|
|
*/
|
||
|
|
export const adaptiveLogger = AdaptiveSmtpLogger.getInstance();
|