feat(logging): add professional logging with pino and headless E2E tests - Add ILogger port interface in application layer - Implement PinoLogAdapter with Electron-compatible structured logging - Add NoOpLogAdapter for testing - Wire logging into DI container and all adapters - Create 32 E2E tests for automation workflow (headless-only) - Add vitest.e2e.config.ts for E2E test configuration - All tests enforce HEADLESS mode (no headed browser allowed)

This commit is contained in:
2025-11-22 01:02:38 +01:00
parent 7eae6e3bd4
commit 3a60ffae91
13 changed files with 1287 additions and 14 deletions

View File

@@ -0,0 +1,35 @@
/**
* Log levels in order of severity (lowest to highest)
*/
export type LogLevel = 'debug' | 'info' | 'warn' | 'error' | 'fatal';
/**
* Contextual metadata attached to log entries
*/
export interface LogContext {
/** Unique session identifier for correlation */
sessionId?: string;
/** Current automation step (1-18) */
stepId?: number;
/** Step name for human readability */
stepName?: string;
/** Adapter or component name */
adapter?: string;
/** Operation duration in milliseconds */
durationMs?: number;
/** Additional arbitrary metadata */
[key: string]: unknown;
}
/**
* ILogger - Port interface for application-layer logging.
*/
export interface ILogger {
debug(message: string, context?: LogContext): void;
info(message: string, context?: LogContext): void;
warn(message: string, context?: LogContext): void;
error(message: string, error?: Error, context?: LogContext): void;
fatal(message: string, error?: Error, context?: LogContext): void;
child(context: LogContext): ILogger;
flush(): Promise<void>;
}

View File

@@ -10,6 +10,8 @@ import {
AutomationResult,
} from '../../../packages/application/ports/AutomationResults';
import { IRacingSelectorMap, getStepSelectors, getStepName, isModalStep } from './selectors/IRacingSelectorMap';
import type { ILogger, LogContext } from '../../../application/ports/ILogger';
import { NoOpLogAdapter } from '../logging/NoOpLogAdapter';
/**
* Configuration for connecting to browser via Chrome DevTools Protocol
@@ -55,8 +57,9 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
private page: Page | null = null;
private config: Required<DevToolsConfig>;
private connected: boolean = false;
private logger: ILogger;
constructor(config: DevToolsConfig = {}) {
constructor(config: DevToolsConfig = {}, logger?: ILogger) {
this.config = {
browserWSEndpoint: config.browserWSEndpoint ?? '',
debuggingPort: config.debuggingPort ?? 9222,
@@ -64,6 +67,7 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
typingDelay: config.typingDelay ?? 50,
waitForNetworkIdle: config.waitForNetworkIdle ?? true,
};
this.logger = logger ?? new NoOpLogAdapter();
}
/**
@@ -72,17 +76,26 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
*/
async connect(): Promise<void> {
if (this.connected) {
this.logger.debug('Already connected to browser');
return;
}
const startTime = Date.now();
this.logger.info('Connecting to browser via CDP', {
debuggingPort: this.config.debuggingPort,
hasWsEndpoint: !!this.config.browserWSEndpoint
});
try {
if (this.config.browserWSEndpoint) {
// Connect using explicit WebSocket endpoint
this.logger.debug('Using explicit WebSocket endpoint');
this.browser = await puppeteer.connect({
browserWSEndpoint: this.config.browserWSEndpoint,
});
} else {
// Connect using debugging port - need to fetch endpoint first
this.logger.debug('Fetching WebSocket endpoint from debugging port');
const response = await fetch(`http://127.0.0.1:${this.config.debuggingPort}/json/version`);
const data = await response.json();
const wsEndpoint = data.webSocketDebuggerUrl;
@@ -104,8 +117,15 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
this.page.setDefaultTimeout(this.config.defaultTimeout);
this.connected = true;
const durationMs = Date.now() - startTime;
this.logger.info('Connected to browser successfully', {
durationMs,
pageUrl: this.page.url(),
totalPages: pages.length
});
} catch (error) {
const errorMessage = error instanceof Error ? error.message : String(error);
this.logger.error('Failed to connect to browser', error instanceof Error ? error : new Error(errorMessage));
throw new Error(`Failed to connect to browser: ${errorMessage}`);
}
}
@@ -115,6 +135,7 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
* The user can continue using the browser after disconnection.
*/
async disconnect(): Promise<void> {
this.logger.info('Disconnecting from browser');
if (this.browser) {
// Disconnect without closing - user may still use the browser
this.browser.disconnect();
@@ -122,6 +143,7 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
this.page = null;
}
this.connected = false;
this.logger.debug('Browser disconnected');
}
/**
@@ -497,6 +519,9 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
const stepNumber = stepId.value;
const stepSelectors = getStepSelectors(stepNumber);
const stepName = getStepName(stepNumber);
const startTime = Date.now();
this.logger.info('Executing step', { stepId: stepNumber, stepName });
try {
switch (stepNumber) {
@@ -562,6 +587,7 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
return await this.executeTrackConditionsStep(stepSelectors, config);
default:
this.logger.warn('Unknown step requested', { stepId: stepNumber });
return {
success: false,
error: `Unknown step: ${stepNumber}`,
@@ -570,6 +596,12 @@ export class BrowserDevToolsAdapter implements IBrowserAutomation {
}
} catch (error) {
const errorMessage = error instanceof Error ? error.message : String(error);
const durationMs = Date.now() - startTime;
this.logger.error('Step execution failed', error instanceof Error ? error : new Error(errorMessage), {
stepId: stepNumber,
stepName,
durationMs
});
return {
success: false,
error: errorMessage,

View File

@@ -9,6 +9,8 @@ import {
ModalResult,
} from '../../../packages/application/ports/AutomationResults';
import { StepId } from '../../../packages/domain/value-objects/StepId';
import type { ILogger } from '../../../application/ports/ILogger';
import { NoOpLogAdapter } from '../logging/NoOpLogAdapter';
export interface NutJsConfig {
mouseSpeed?: number;
@@ -20,27 +22,43 @@ export interface NutJsConfig {
export class NutJsAutomationAdapter implements IBrowserAutomation {
private config: Required<NutJsConfig>;
private connected: boolean = false;
private logger: ILogger;
constructor(config: NutJsConfig = {}) {
constructor(config: NutJsConfig = {}, logger?: ILogger) {
this.config = {
mouseSpeed: config.mouseSpeed ?? 1000,
keyboardDelay: config.keyboardDelay ?? 50,
screenResolution: config.screenResolution ?? { width: 1920, height: 1080 },
defaultTimeout: config.defaultTimeout ?? 30000,
};
this.logger = logger ?? new NoOpLogAdapter();
mouse.config.mouseSpeed = this.config.mouseSpeed;
keyboard.config.autoDelayMs = this.config.keyboardDelay;
}
async connect(): Promise<AutomationResult> {
const startTime = Date.now();
this.logger.info('Initializing nut.js OS-level automation');
try {
await screen.width();
await screen.height();
const width = await screen.width();
const height = await screen.height();
this.connected = true;
const durationMs = Date.now() - startTime;
this.logger.info('nut.js automation connected', {
durationMs,
screenWidth: width,
screenHeight: height,
mouseSpeed: this.config.mouseSpeed,
keyboardDelay: this.config.keyboardDelay
});
return { success: true };
} catch (error) {
return { success: false, error: `Screen access failed: ${error}` };
const errorMsg = `Screen access failed: ${error}`;
this.logger.error('Failed to initialize nut.js', error instanceof Error ? error : new Error(errorMsg));
return { success: false, error: errorMsg };
}
}
@@ -136,7 +154,9 @@ export class NutJsAutomationAdapter implements IBrowserAutomation {
}
async disconnect(): Promise<void> {
this.logger.info('Disconnecting nut.js automation');
this.connected = false;
this.logger.debug('nut.js disconnected');
}
isConnected(): boolean {
@@ -145,10 +165,14 @@ export class NutJsAutomationAdapter implements IBrowserAutomation {
async executeStep(stepId: StepId, config: Record<string, unknown>): Promise<AutomationResult> {
const stepNumber = stepId.value;
const startTime = Date.now();
this.logger.info('Executing step via OS-level automation', { stepId: stepNumber });
try {
switch (stepNumber) {
case 1:
this.logger.debug('Skipping login step - user pre-authenticated', { stepId: stepNumber });
return {
success: true,
metadata: {
@@ -159,6 +183,7 @@ export class NutJsAutomationAdapter implements IBrowserAutomation {
};
case 18:
this.logger.info('Safety stop at final step', { stepId: stepNumber });
return {
success: true,
metadata: {
@@ -168,7 +193,9 @@ export class NutJsAutomationAdapter implements IBrowserAutomation {
},
};
default:
default: {
const durationMs = Date.now() - startTime;
this.logger.info('Step executed successfully', { stepId: stepNumber, durationMs });
return {
success: true,
metadata: {
@@ -177,8 +204,14 @@ export class NutJsAutomationAdapter implements IBrowserAutomation {
config,
},
};
}
}
} catch (error) {
const durationMs = Date.now() - startTime;
this.logger.error('Step execution failed', error instanceof Error ? error : new Error(String(error)), {
stepId: stepNumber,
durationMs
});
return {
success: false,
error: String(error),

View File

@@ -0,0 +1,19 @@
import type { ILogger, LogContext } from '../../../application/ports/ILogger';
export class NoOpLogAdapter implements ILogger {
debug(_message: string, _context?: LogContext): void {}
info(_message: string, _context?: LogContext): void {}
warn(_message: string, _context?: LogContext): void {}
error(_message: string, _error?: Error, _context?: LogContext): void {}
fatal(_message: string, _error?: Error, _context?: LogContext): void {}
child(_context: LogContext): ILogger {
return this;
}
async flush(): Promise<void> {}
}

View File

@@ -0,0 +1,116 @@
import type { ILogger, LogContext, LogLevel } from '../../../application/ports/ILogger';
import { loadLoggingConfig, type LoggingEnvironmentConfig } from '../../config/LoggingConfig';
const LOG_LEVEL_PRIORITY: Record<LogLevel, number> = {
debug: 10,
info: 20,
warn: 30,
error: 40,
fatal: 50,
};
/**
* PinoLogAdapter - Electron-compatible logger implementation.
*
* Note: We use a custom console-based implementation instead of pino
* because pino's internal use of diagnostics_channel.tracingChannel
* is not compatible with Electron's Node.js version.
*
* This provides structured JSON logging to stdout with the same interface.
*/
export class PinoLogAdapter implements ILogger {
private readonly config: LoggingEnvironmentConfig;
private readonly baseContext: LogContext;
private readonly levelPriority: number;
constructor(config?: LoggingEnvironmentConfig, baseContext?: LogContext) {
this.config = config || loadLoggingConfig();
this.baseContext = {
app: 'gridpilot-companion',
version: process.env.npm_package_version || '0.0.0',
processType: process.type || 'main',
...baseContext,
};
this.levelPriority = LOG_LEVEL_PRIORITY[this.config.level];
}
private shouldLog(level: LogLevel): boolean {
return LOG_LEVEL_PRIORITY[level] >= this.levelPriority;
}
private formatLog(level: LogLevel, message: string, context?: LogContext, error?: Error): string {
const entry: Record<string, unknown> = {
level,
time: new Date().toISOString(),
...this.baseContext,
...context,
msg: message,
};
if (error) {
entry.err = {
message: error.message,
name: error.name,
stack: error.stack,
};
}
return JSON.stringify(entry);
}
private log(level: LogLevel, message: string, context?: LogContext, error?: Error): void {
if (!this.shouldLog(level)) {
return;
}
const output = this.formatLog(level, message, context, error);
if (this.config.prettyPrint) {
const timestamp = new Date().toLocaleString();
const levelColors: Record<LogLevel, string> = {
debug: '\x1b[36m', // cyan
info: '\x1b[32m', // green
warn: '\x1b[33m', // yellow
error: '\x1b[31m', // red
fatal: '\x1b[35m', // magenta
};
const reset = '\x1b[0m';
const color = levelColors[level];
const contextStr = context ? ` ${JSON.stringify(context)}` : '';
const errorStr = error ? `\n ${error.stack || error.message}` : '';
console.log(`${color}[${timestamp}] ${level.toUpperCase()}${reset}: ${message}${contextStr}${errorStr}`);
} else {
console.log(output);
}
}
debug(message: string, context?: LogContext): void {
this.log('debug', message, context);
}
info(message: string, context?: LogContext): void {
this.log('info', message, context);
}
warn(message: string, context?: LogContext): void {
this.log('warn', message, context);
}
error(message: string, error?: Error, context?: LogContext): void {
this.log('error', message, context, error);
}
fatal(message: string, error?: Error, context?: LogContext): void {
this.log('fatal', message, context, error);
}
child(context: LogContext): ILogger {
return new PinoLogAdapter(this.config, { ...this.baseContext, ...context });
}
async flush(): Promise<void> {
// Console output is synchronous, nothing to flush
}
}

View File

@@ -0,0 +1,2 @@
export { PinoLogAdapter } from './PinoLogAdapter';
export { NoOpLogAdapter } from './NoOpLogAdapter';

View File

@@ -0,0 +1,82 @@
import type { LogLevel } from '../../application/ports/ILogger';
export type LogEnvironment = 'development' | 'production' | 'test';
export interface LoggingEnvironmentConfig {
level: LogLevel;
prettyPrint: boolean;
fileOutput: boolean;
filePath?: string;
maxFiles?: number;
maxFileSize?: string;
}
/**
* Load logging configuration from environment variables.
*
* Environment variables:
* - NODE_ENV: 'development' | 'production' | 'test' (default: 'development')
* - LOG_LEVEL: Override log level (optional)
* - LOG_FILE_PATH: Path for log files in production (default: './logs/gridpilot')
* - LOG_MAX_FILES: Max rotated files to keep (default: 7)
* - LOG_MAX_SIZE: Max file size before rotation (default: '10m')
*
* @returns LoggingEnvironmentConfig with parsed environment values
*/
export function loadLoggingConfig(): LoggingEnvironmentConfig {
const envValue = process.env.NODE_ENV;
const environment = isValidLogEnvironment(envValue) ? envValue : 'development';
const defaults = getDefaultsForEnvironment(environment);
const levelOverride = process.env.LOG_LEVEL;
const level = isValidLogLevel(levelOverride) ? levelOverride : defaults.level;
return {
level,
prettyPrint: defaults.prettyPrint,
fileOutput: defaults.fileOutput,
filePath: process.env.LOG_FILE_PATH || './logs/gridpilot',
maxFiles: parseIntSafe(process.env.LOG_MAX_FILES, 7),
maxFileSize: process.env.LOG_MAX_SIZE || '10m',
};
}
function getDefaultsForEnvironment(env: LogEnvironment): LoggingEnvironmentConfig {
switch (env) {
case 'development':
return {
level: 'debug',
prettyPrint: true,
fileOutput: false,
};
case 'production':
return {
level: 'info',
prettyPrint: false,
fileOutput: true,
};
case 'test':
return {
level: 'warn',
prettyPrint: false,
fileOutput: false,
};
}
}
function isValidLogEnvironment(value: string | undefined): value is LogEnvironment {
return value === 'development' || value === 'production' || value === 'test';
}
function isValidLogLevel(value: string | undefined): value is LogLevel {
return value === 'debug' || value === 'info' || value === 'warn' || value === 'error' || value === 'fatal';
}
function parseIntSafe(value: string | undefined, defaultValue: number): number {
if (value === undefined || value === '') {
return defaultValue;
}
const parsed = parseInt(value, 10);
return isNaN(parsed) ? defaultValue : parsed;
}