feat: enhance logging with structured job tracking and processing timeline #18

Implemented comprehensive logging enhancements:

1. **Enhanced Logger (src/logger.js)**:
   - Added configurable log levels (DEBUG, INFO, WARN, ERROR)
   - Added new structured logging methods:
     * jobQueued() - Log when jobs are added to queue
     * jobSkipped() - Log when jobs are skipped (filtering, deduplication)
     * jobStarted() - Log when job execution begins
     * jobCompleted() - Log when jobs finish with duration
     * jobFailed() - Log when jobs fail with error details
     * duplicateDetected() - Log deduplication decisions
     * deduplicationCleanup() - Log cleanup operations
     * branchFiltered() - Log branch filtering decisions
     * variablesExtracted() - Log extracted variables (debug level)
     * queueStats() - Log queue health metrics
   - Added metrics tracking (jobs processed, failed, deduplicated, avg processing time)
   - Added duration formatting helper (_formatDuration)
   - Maintained backward compatibility with existing logging

2. **Enhanced JobQueue (src/jobQueue.js)**:
   - Integrated structured logging at all state transitions
   - Added job queued logging with issue number and command name
   - Added job started logging with issue context
   - Added job completed logging with duration tracking
   - Added job failed logging with error details
   - Extracts issue numbers from payloads for better traceability

3. **Enhanced CommandExecutor (src/commandExecutor.js)**:
   - Added debug-level logging for extracted variables
   - Added debug-level logging for branch filtering decisions
   - Improved filtering log messages with command context

4. **Configuration (.env.example)**:
   - Added LOG_LEVEL configuration option (DEBUG, INFO, WARN, ERROR)
   - Documented log level options

Benefits:
- Better visibility into job processing and queue health
- Clear audit trail with issue-specific timelines
- Performance monitoring with processing time metrics
- Debug capabilities with variable substitution visibility
- Easier troubleshooting and operational insights

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude <noreply@anthropic.com>

.env.example

@@ -4,6 +4,10 @@ PORT=3000
 WEBHOOK_PATH=/webhook
 WEBHOOK_SECRET=
 
+# Logging Configuration
+# Log level: DEBUG, INFO, WARN, ERROR (default: INFO)
+LOG_LEVEL=INFO
+
 # Webhook Event Configuration
 # Enable/disable webhook events (commands are configured in commands.json)
 # Set to 'true' to enable event handling, 'false' to disable

src/commandExecutor.js

@@ -139,6 +139,9 @@ export class CommandExecutor {
         break;
     }
 
+    // Log extracted variables at debug level
+    logger.variablesExtracted(eventType, variables);
+
     return variables;
   }
 
@@ -269,6 +272,8 @@ export class CommandExecutor {
 
     // Apply branch filter if configured
     if (config.filterBranch && variables.branch !== config.filterBranch) {
+      const commandName = config.name || config.command || 'unknown';
+      logger.branchFiltered(variables.branch, config.filterBranch, commandName);
       logger.info(`Skipping command execution - branch '${variables.branch}' does not match filter '${config.filterBranch}'`);
       return null;
     }

src/jobQueue.js

@@ -95,6 +95,13 @@ export class JobQueue {
     this.queue.push(job);
     this.saveQueue();
 
+    // Extract issue number for logging if this is an issue-related event
+    const issueNumber = payload.issue?.number || payload.number || null;
+    const commandName = config.name || config.command || 'unknown';
+
+    // Use structured logging
+    logger.jobQueued(job.id, eventType, issueNumber, commandName);
+
     logger.info(`Job ${job.id} added to queue (${eventType})`, {
       queueLength: this.queue.length,
       jobId: job.id
@@ -126,6 +133,13 @@ export class JobQueue {
     job.startedAt = new Date().toISOString();
     this.saveQueue();
 
+    // Extract issue number and command name for logging
+    const issueNumber = job.payload.issue?.number || job.payload.number || null;
+    const commandName = job.config.name || job.config.command || 'unknown';
+
+    // Use structured logging
+    logger.jobStarted(job.id, job.eventType, issueNumber, commandName);
+
     logger.info(`Starting job ${job.id} (${job.eventType})`, {
       queueLength: this.queue.length,
       jobId: job.id
@@ -145,9 +159,14 @@ export class JobQueue {
       job.completedAt = new Date().toISOString();
       job.result = result;
 
+      const durationMs = new Date(job.completedAt) - new Date(job.startedAt);
+
+      // Use structured logging
+      logger.jobCompleted(job.id, job.eventType, issueNumber, durationMs);
+
       logger.info(`Job ${job.id} completed successfully`, {
         jobId: job.id,
-        duration: new Date(job.completedAt) - new Date(job.startedAt)
+        duration: durationMs
       });
     } catch (error) {
       // Update job with error
@@ -158,6 +177,9 @@ export class JobQueue {
         error: error.message
       };
 
+      // Use structured logging
+      logger.jobFailed(job.id, job.eventType, issueNumber, error.message);
+
       logger.error(`Job ${job.id} failed`, error);
     }
 

src/logger.js

@@ -2,6 +2,14 @@
  * Logger module for webhook events
  */
 
+// Log levels
+const LOG_LEVELS = {
+  DEBUG: 0,
+  INFO: 1,
+  WARN: 2,
+  ERROR: 3
+};
+
 export class Logger {
   constructor(options = {}) {
     // Auto-detect systemd/journald environment
@@ -12,6 +20,36 @@ export class Logger {
     // (journald already adds timestamps and doesn't render colors well)
     this.enableTimestamps = options.enableTimestamps ?? (isSystemd ? false : true);
     this.enableColors = options.enableColors ?? (isSystemd ? false : true);
+
+    // Set log level from environment or default to INFO
+    const levelStr = (options.logLevel || process.env.LOG_LEVEL || 'INFO').toUpperCase();
+    this.logLevel = LOG_LEVELS[levelStr] ?? LOG_LEVELS.INFO;
+
+    // Track metrics for queue health reporting
+    this.metrics = {
+      jobsProcessed24h: 0,
+      jobsFailed24h: 0,
+      jobsDuplicated24h: 0,
+      processingTimes: [], // Array of processing times in ms
+      lastResetTime: Date.now()
+    };
+
+    // Reset metrics every 24 hours
+    this._startMetricsReset();
+  }
+
+  _startMetricsReset() {
+    // Reset metrics every 24 hours
+    setInterval(() => {
+      this.metrics = {
+        jobsProcessed24h: 0,
+        jobsFailed24h: 0,
+        jobsDuplicated24h: 0,
+        processingTimes: [],
+        lastResetTime: Date.now()
+      };
+      this.debug('Metrics reset (24h cycle)');
+    }, 24 * 60 * 60 * 1000);
   }
 
   _getTimestamp() {
@@ -22,7 +60,27 @@ export class Logger {
     return this.enableColors ? `\x1b[${colorCode}m${text}\x1b[0m` : text;
   }
 
+  _formatDuration(ms) {
+    if (ms < 1000) return `${ms}ms`;
+    if (ms < 60000) return `${(ms / 1000).toFixed(1)}s`;
+    return `${Math.floor(ms / 60000)}m ${Math.floor((ms % 60000) / 1000)}s`;
+  }
+
+  _shouldLog(level) {
+    return LOG_LEVELS[level] >= this.logLevel;
+  }
+
+  debug(message, data = null) {
+    if (!this._shouldLog('DEBUG')) return;
+    const timestamp = this._getTimestamp();
+    console.log(`${timestamp} ${this._colorize('DEBUG', '90')}:`, message);
+    if (data) {
+      console.log(JSON.stringify(data, null, 2));
+    }
+  }
+
   info(message, data = null) {
+    if (!this._shouldLog('INFO')) return;
     const timestamp = this._getTimestamp();
     console.log(`${timestamp} ${this._colorize('INFO', '36')}:`, message);
     if (data) {
@@ -30,7 +88,17 @@ export class Logger {
     }
   }
 
+  warn(message, data = null) {
+    if (!this._shouldLog('WARN')) return;
+    const timestamp = this._getTimestamp();
+    console.warn(`${timestamp} ${this._colorize('WARN', '33')}:`, message);
+    if (data) {
+      console.warn(JSON.stringify(data, null, 2));
+    }
+  }
+
   error(message, error = null) {
+    if (!this._shouldLog('ERROR')) return;
     const timestamp = this._getTimestamp();
     console.error(`${timestamp} ${this._colorize('ERROR', '31')}:`, message);
     if (error) {
@@ -39,6 +107,7 @@ export class Logger {
   }
 
   webhook(event, payload) {
+    if (!this._shouldLog('INFO')) return;
     const timestamp = this._getTimestamp();
     console.log(`\n${this._colorize('='.repeat(80), '33')}`);
     console.log(`${timestamp} ${this._colorize('WEBHOOK', '32')} - Event: ${this._colorize(event, '35')}`);
@@ -46,6 +115,113 @@ export class Logger {
     console.log(JSON.stringify(payload, null, 2));
     console.log(`${this._colorize('='.repeat(80), '33')}\n`);
   }
+
+  // Job lifecycle logging methods
+  jobQueued(jobId, eventType, issueNumber, commandName) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+    const issueInfo = issueNumber ? ` - Issue #${issueNumber}` : '';
+    console.log(`${timestamp} ${this._colorize('JOB QUEUED', '36')}: Job #${jobId} (${eventType}${issueInfo}) - ${commandName}`);
+  }
+
+  jobSkipped(jobId, eventType, issueNumber, reason) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+    const issueInfo = issueNumber ? ` - Issue #${issueNumber}` : '';
+    console.log(`${timestamp} ${this._colorize('JOB SKIPPED', '33')}: Job #${jobId} (${eventType}${issueInfo}) - Reason: ${reason}`);
+  }
+
+  jobStarted(jobId, eventType, issueNumber, commandName) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+    const issueInfo = issueNumber ? ` - Issue #${issueNumber}` : '';
+    console.log(`${timestamp} ${this._colorize('JOB STARTED', '32')}: Job #${jobId} (${eventType}${issueInfo}) - ${commandName}`);
+  }
+
+  jobCompleted(jobId, eventType, issueNumber, durationMs) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+    const issueInfo = issueNumber ? ` - Issue #${issueNumber}` : '';
+    const duration = this._formatDuration(durationMs);
+    console.log(`${timestamp} ${this._colorize('JOB COMPLETED', '32')}: Job #${jobId} (${eventType}${issueInfo}) - Duration: ${duration}`);
+
+    // Track metrics
+    this.metrics.jobsProcessed24h++;
+    this.metrics.processingTimes.push(durationMs);
+    // Keep only last 100 processing times to calculate averages
+    if (this.metrics.processingTimes.length > 100) {
+      this.metrics.processingTimes.shift();
+    }
+  }
+
+  jobFailed(jobId, eventType, issueNumber, error) {
+    if (!this._shouldLog('ERROR')) return;
+    const timestamp = this._getTimestamp();
+    const issueInfo = issueNumber ? ` - Issue #${issueNumber}` : '';
+    console.error(`${timestamp} ${this._colorize('JOB FAILED', '31')}: Job #${jobId} (${eventType}${issueInfo}) - Error: ${error}`);
+
+    // Track metrics
+    this.metrics.jobsFailed24h++;
+  }
+
+  // Deduplication logging
+  duplicateDetected(eventType, issueNumber, timeSinceLastMs) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+    const timeSince = this._formatDuration(timeSinceLastMs);
+    console.log(`${timestamp} ${this._colorize('DUPLICATE', '33')}: ${eventType} for Issue #${issueNumber} (last processed ${timeSince} ago)`);
+
+    // Track metrics
+    this.metrics.jobsDuplicated24h++;
+  }
+
+  deduplicationCleanup(entriesRemoved) {
+    if (!this._shouldLog('DEBUG')) return;
+    const timestamp = this._getTimestamp();
+    console.log(`${timestamp} ${this._colorize('CLEANUP', '90')}: Removed ${entriesRemoved} expired deduplication entries`);
+  }
+
+  // Branch filtering logging
+  branchFiltered(branch, filterBranch, commandName) {
+    if (!this._shouldLog('DEBUG')) return;
+    const timestamp = this._getTimestamp();
+    console.log(`${timestamp} ${this._colorize('FILTERED', '90')}: Command '${commandName}' skipped - branch '${branch}' != '${filterBranch}'`);
+  }
+
+  // Variable substitution logging (debug level)
+  variablesExtracted(eventType, variables) {
+    if (!this._shouldLog('DEBUG')) return;
+    const timestamp = this._getTimestamp();
+    console.log(`${timestamp} ${this._colorize('VARIABLES', '90')}: Extracted from ${eventType}`);
+    console.log(JSON.stringify(variables, null, 2));
+  }
+
+  // Queue health metrics
+  queueStats(stats) {
+    if (!this._shouldLog('INFO')) return;
+    const timestamp = this._getTimestamp();
+
+    // Calculate average processing time
+    let avgProcessingTime = 0;
+    if (this.metrics.processingTimes.length > 0) {
+      const sum = this.metrics.processingTimes.reduce((a, b) => a + b, 0);
+      avgProcessingTime = sum / this.metrics.processingTimes.length;
+    }
+
+    console.log(`\n${this._colorize('='.repeat(80), '36')}`);
+    console.log(`${timestamp} ${this._colorize('QUEUE STATS', '36')}`);
+    console.log(`${this._colorize('-'.repeat(80), '36')}`);
+    console.log(`  Pending jobs:        ${stats.pending}`);
+    console.log(`  Running jobs:        ${stats.running}`);
+    console.log(`  Processed (24h):     ${this.metrics.jobsProcessed24h}`);
+    console.log(`  Failed (24h):        ${this.metrics.jobsFailed24h}`);
+    console.log(`  Deduplicated (24h):  ${this.metrics.jobsDuplicated24h}`);
+    console.log(`  Avg processing time: ${this._formatDuration(avgProcessingTime)}`);
+    if (stats.currentJob) {
+      console.log(`  Current job:         #${stats.currentJob.id} (${stats.currentJob.eventType})`);
+    }
+    console.log(`${this._colorize('='.repeat(80), '36')}\n`);
+  }
 }
 
 export default new Logger();