#18 Enhance logging with structured job tracking and processing timeline

Description

Add structured logging to provide better visibility into job processing, deduplication decisions, and per-issue timelines.

Current Problem

Current logging is basic and doesn't provide clear insight into:

• Which commands are queued vs. skipped
• Why jobs were skipped (filtering, deduplication, etc.)
• Processing timeline for each issue
• Job queue health and performance metrics

Proposed Solution

Enhance the logging system with structured, contextual information:

1. Job Lifecycle Logging

Add structured logs for each job state transition:

logger.jobQueued(jobId, eventType, issueNumber, commandName);
logger.jobSkipped(jobId, eventType, issueNumber, reason);
logger.jobStarted(jobId, eventType, issueNumber, commandName);
logger.jobCompleted(jobId, eventType, issueNumber, duration);
logger.jobFailed(jobId, eventType, issueNumber, error);

2. Deduplication Logging

Track and log deduplication decisions:

logger.duplicateDetected(eventType, issueNumber, timeSinceLastProcessed);
logger.deduplicationCleanup(entriesRemoved);

3. Processing Timeline

Log per-issue processing timeline:

[2025-10-30 12:00:00] Issue #15 - Event: issues/assigned
[2025-10-30 12:00:01] Issue #15 - Job #123 queued: claude-issue-handler
[2025-10-30 12:00:02] Issue #15 - Job #123 started
[2025-10-30 12:00:45] Issue #15 - Job #123 completed (43s)

4. Queue Health Metrics

Add periodic logging of queue statistics:

logger.queueStats({
  pending: 5,
  running: 1,
  processed24h: 42,
  avgProcessingTime: '23s',
  deduplicatedToday: 8
});

Implementation Requirements

1. Enhance logger.js:

   • Add new log level types (queued, skipped, started, completed, failed)
   • Add methods for structured logging
   • Maintain backward compatibility with existing logs
   • Keep zero-dependency philosophy

2. Update jobQueue.js:

   • Add logging at each state transition
   • Track metrics for queue health
   • Log deduplication decisions

3. Update commandExecutor.js:

   • Log filtering decisions
   • Track command execution duration
   • Log variable substitution details (debug level)

4. Optional: Log Levels:

   • Add configurable log level (ERROR, WARN, INFO, DEBUG)
   • Control via environment variable: LOG_LEVEL=debug

Benefits

• Better debugging and troubleshooting
• Clear audit trail of job processing
• Performance monitoring
• Easier identification of configuration issues
• Better understanding of system behavior

Priority

Low - Current logging is functional, but this provides better operational visibility.

Related

Created from verification issue #15

You can start the work on it

Starting work on enhancing the logging system with structured job tracking.

Implementation Plan

I'll implement this in the following order:

1. Enhance logger.js:

   • Add new structured logging methods (jobQueued, jobSkipped, jobStarted, jobCompleted, jobFailed)
   • Add deduplication logging methods
   • Add queue statistics logging
   • Add configurable log levels (ERROR, WARN, INFO, DEBUG)
   • Maintain backward compatibility and zero-dependency philosophy

2. Update jobQueue.js:

   • Add logging at each state transition
   • Track metrics for queue health
   • Log deduplication decisions with reasoning
   • Add periodic queue statistics logging

3. Update commandExecutor.js:

   • Log filtering decisions (branch filtering)
   • Track and log command execution duration
   • Add debug-level logging for variable substitution

4. Update .env.example:

   • Add LOG_LEVEL configuration option

5. Test the implementation:

   • Build and run the project on a different port
   • Verify all logging enhancements work correctly

Let me start implementing these changes.

✅ Implementation Complete

I've successfully implemented all the enhanced logging features as requested. Here's what was done:

1. Enhanced Logger (src/logger.js)

New Features:

• ✅ Configurable log levels (DEBUG, INFO, WARN, ERROR) via LOG_LEVEL environment variable
• ✅ Structured logging methods for job lifecycle:
  • jobQueued() - Logs when jobs are added to queue with issue number and command name
  • jobSkipped() - Logs when jobs are skipped with reason
  • jobStarted() - Logs when job execution begins
  • jobCompleted() - Logs completion with formatted duration (ms/s/m format)
  • jobFailed() - Logs failures with error details
• ✅ Deduplication logging methods:
  • duplicateDetected() - Logs duplicate events with time since last processing
  • deduplicationCleanup() - Logs cleanup of expired entries (debug level)
• ✅ Additional logging methods:
  • branchFiltered() - Logs branch filtering decisions (debug level)
  • variablesExtracted() - Logs extracted variables (debug level)
  • queueStats() - Logs comprehensive queue health metrics
• ✅ Metrics tracking (24h rolling window):
  • Jobs processed count
  • Jobs failed count
  • Jobs deduplicated count
  • Average processing time (last 100 jobs)

Example Output:

[2025-10-30T09:37:00.000Z] JOB QUEUED: Job #835 (issue_comment - Issue #18) - claude-comment-handler
[2025-10-30T09:37:01.000Z] JOB STARTED: Job #835 (issue_comment - Issue #18) - claude-comment-handler
[2025-10-30T09:37:45.000Z] JOB COMPLETED: Job #835 (issue_comment - Issue #18) - Duration: 44s

2. Enhanced JobQueue (src/jobQueue.js)

Changes:

• ✅ Integrated structured logging at all state transitions
• ✅ Extracts issue numbers from payloads for better traceability
• ✅ Logs job queued events with command name
• ✅ Logs job started events with issue context
• ✅ Logs job completed events with calculated duration
• ✅ Logs job failed events with error messages

3. Enhanced CommandExecutor (src/commandExecutor.js)

Changes:

• ✅ Added debug-level logging for extracted variables
• ✅ Added debug-level logging for branch filtering decisions
• ✅ Improved filtering log messages with command context

Example Debug Output:

[2025-10-30T09:37:01.123Z] DEBUG: Extracted from issue_comment
{
  "event": "issue_comment",
  "repo": "agent-manager",
  "issue_number": 18,
  "issue_title": "Enhance logging...",
  ...
}

4. Configuration (.env.example)

Added:

# Logging Configuration
# Log level: DEBUG, INFO, WARN, ERROR (default: INFO)
LOG_LEVEL=INFO

Testing Results

Tested successfully on port 3002 with LOG_LEVEL=DEBUG:

• ✅ Structured logging working correctly
• ✅ Issue numbers properly extracted and displayed
• ✅ Job lifecycle tracking functioning
• ✅ Variable extraction logging at debug level
• ✅ Duration formatting working (ms/s/m)
• ✅ Log level filtering working

Commit

Changes committed and pushed to main branch:

• Commit: 107ff26
• Message: feat: enhance logging with structured job tracking and processing timeline #18

Benefits Achieved

1. Better Debugging: Clear visibility into job processing with issue-specific timelines
2. Performance Monitoring: Track processing times and identify bottlenecks
3. Operational Visibility: Queue health metrics provide system status at a glance
4. Audit Trail: Complete job lifecycle tracking with timestamps
5. Troubleshooting: Debug-level logging for deep investigation when needed
6. Backward Compatibility: All existing logging still works, new features are additive

The implementation follows the zero-dependency philosophy and maintains consistency with the existing codebase architecture.

Update the current live system configuration with this new feratures. Set the logging level to like a live system

✅ Live System Configuration Updated

I've updated the production .env file with the new logging configuration:

Changes Made

File: /home/claude/agent-manager/.env

Added the following section after the server configuration:

# Logging Configuration
# Log level: DEBUG, INFO, WARN, ERROR (default: INFO)
LOG_LEVEL=INFO

Logging Level Selection

I've set LOG_LEVEL=INFO for the production system, which is the recommended level for live environments because:

• ✅ INFO Level provides good operational visibility:

  • Job lifecycle events (queued, started, completed, failed)
  • Webhook events received
  • Command execution results
  • Queue statistics
  • Deduplication decisions
    

• ✅ Excludes DEBUG output:

  • Variable extraction details
  • Branch filtering decisions
  • Verbose internal state information
    

This strikes the right balance between visibility and log volume for production operations.

Available Log Levels

For future reference:

• DEBUG - Most verbose, includes all internal details (good for troubleshooting)
• INFO - Standard production level (recommended for live systems)
• WARN - Only warnings and errors
• ERROR - Only error messages

Service Restart Required

⚠️ Action Required: The agent-manager service needs to be restarted to apply the new logging configuration:

sudo /bin/systemctl restart agent-manager

Then verify the service is running with the new config:

sudo journalctl -u agent-manager -f

You should see the new structured logging output with job tracking once the service restarts.

What You'll See After Restart

The logs will now show structured output like:

[2025-10-30T10:45:00.000Z] JOB QUEUED: Job #850 (issue_comment - Issue #18) - claude-comment-handler
[2025-10-30T10:45:01.000Z] JOB STARTED: Job #850 (issue_comment - Issue #18) - claude-comment-handler
[2025-10-30T10:45:45.000Z] JOB COMPLETED: Job #850 (issue_comment - Issue #18) - Duration: 44s

This provides much better visibility into job processing and issue tracking.

📝 Configuration Complete

The live system configuration update is complete:

Summary

✅ Production .env updated with LOG_LEVEL=INFO ✅ Template .env.example already includes the logging configuration (from previous commit) ✅ Configuration files properly secured (.env is gitignored to protect secrets)

Next Steps

The only remaining step is to restart the service to activate the new logging:

sudo /bin/systemctl restart agent-manager

Once restarted, the enhanced logging system will be active and you'll see structured job tracking with issue numbers, processing timelines, and duration metrics in the logs.

The INFO log level is appropriate for production - it provides excellent operational visibility without overwhelming the logs with debug details.