ame-job-manager/ame-log-parser.js

/**
 * AME Log Parser Module
 *
 * Parses Adobe Media Encoder's AMEEncodingLog.txt and AMEEncodingErrorLog.txt
 * to extract encoding stats: completion status, encoding time, source/output files,
 * presets, codec info, and errors.
 *
 * macOS log path: /Users/<user>/Documents/Adobe/Adobe Media Encoder/<version>/
 * Windows log path: C:\Users\<user>\Documents\Adobe\Adobe Media Encoder\<version>\
 *
 * AME log format (typical entry):
 * ────────────────────────────────────
 * - Source File: /path/to/source.prproj
 * - Output File: /path/to/output.mp4
 * - Preset Used: Match Source - H.264
 * - Video: 1920x1080 (1.0), 29.97 fps, Progressive, 00:05:30:00, VBR, 1 pass, Target 10.00 Mbps
 * - Audio: AAC, 320 kbps, 48 kHz, Stereo
 * - Encoding Time: 00:02:15
 * - Status: Done
 * 3/30/2026 10:15:32 AM
 * ────────────────────────────────────
 *
 * Error log has similar format but with error messages.
 */

const fs = require('fs');
const path = require('path');

/**
 * Read a file and auto-detect encoding (UTF-16 LE/BE or UTF-8).
 * Windows AME writes logs as UTF-16 LE with BOM — Node's default
 * fs.readFileSync('utf-8') produces garbled output on these files.
 */
function readFileAutoEncoding(filePath) {
  const buf = fs.readFileSync(filePath);
  if (buf.length === 0) return '';

  // UTF-16 LE BOM: FF FE
  if (buf[0] === 0xFF && buf[1] === 0xFE) {
    return buf.slice(2).toString('utf16le');
  }
  // UTF-16 BE BOM: FE FF
  if (buf[0] === 0xFE && buf[1] === 0xFF) {
    // Swap bytes for Node's utf16le decoder
    const swapped = Buffer.alloc(buf.length - 2);
    for (let i = 2; i < buf.length - 1; i += 2) {
      swapped[i - 2] = buf[i + 1];
      swapped[i - 1] = buf[i];
    }
    return swapped.toString('utf16le');
  }
  // UTF-8 BOM: EF BB BF
  if (buf[0] === 0xEF && buf[1] === 0xBB && buf[2] === 0xBF) {
    return buf.slice(3).toString('utf-8');
  }
  // No BOM — check if it looks like UTF-16 LE (null bytes in even positions)
  if (buf.length >= 4 && buf[1] === 0x00 && buf[3] === 0x00) {
    return buf.toString('utf16le');
  }
  // Default: UTF-8
  return buf.toString('utf-8');
}

/**
 * Parse AME encoding log entries from a log file.
 * Handles multiple entry formats since AME versions vary.
 */
function parseAMELog(logContent) {
  const entries = [];

  if (!logContent || !logContent.trim()) return entries;

  // Split on common entry separators
  // AME uses blank lines or dashes between entries
  const lines = logContent.split('\n');

  let currentEntry = null;

  for (let i = 0; i < lines.length; i++) {
    const line = lines[i].trim();

    if (!line) {
      // Blank line might end an entry
      if (currentEntry && Object.keys(currentEntry).length > 1) {
        entries.push(currentEntry);
        currentEntry = null;
      }
      continue;
    }

    // Start a new entry on "Source File" or similar markers
    if (line.match(/^-?\s*Source\s*File\s*:/i)) {
      if (currentEntry && Object.keys(currentEntry).length > 1) {
        entries.push(currentEntry);
      }
      currentEntry = { raw: [] };
      currentEntry.sourceFile = extractValue(line);
      currentEntry.raw.push(line);
      continue;
    }

    if (!currentEntry) {
      // Check if this line starts an entry with a different format
      // Some AME versions start with the date/time
      const dateMatch = line.match(/^(\d{1,2}\/\d{1,2}\/\d{2,4})\s+(\d{1,2}:\d{2}:\d{2}\s*[AP]?M?)/i);
      if (dateMatch) {
        // Skip lines that are just queue start/stop/log header timestamps
        if (line.match(/Queue\s+(Started|Stopped)/i) || line.match(/Log\s+File\s+Created/i)) {
          continue;
        }
        if (currentEntry && Object.keys(currentEntry).length > 1) {
          entries.push(currentEntry);
        }
        currentEntry = { raw: [line] };
        currentEntry.timestamp = line;
        currentEntry.date = dateMatch[1];
        currentEntry.time = dateMatch[2];
        continue;
      }

      // Also handle "Encoding <filename>" as entry start
      if (line.match(/^Encoding\s+/i)) {
        if (currentEntry && Object.keys(currentEntry).length > 1) {
          entries.push(currentEntry);
        }
        currentEntry = { raw: [line] };
        currentEntry.sourceFile = line.replace(/^Encoding\s+/i, '').trim();
        continue;
      }

      continue;
    }

    currentEntry.raw.push(line);

    // Parse known fields
    if (line.match(/^-?\s*Output\s*File\s*:/i)) {
      currentEntry.outputFile = extractValue(line);
    } else if (line.match(/^-?\s*Preset\s*(Used)?\s*:/i)) {
      currentEntry.preset = extractValue(line);
    } else if (line.match(/^-?\s*Video\s*:/i)) {
      currentEntry.video = extractValue(line);
      parseVideoDetails(currentEntry);
    } else if (line.match(/^-?\s*Audio\s*:/i)) {
      currentEntry.audio = extractValue(line);
    } else if (line.match(/^-?\s*Encoding\s*Time\s*:/i)) {
      currentEntry.encodingTime = extractValue(line);
      currentEntry.encodingTimeMs = parseTimeToMs(currentEntry.encodingTime);
    } else if (line.match(/^-?\s*Status\s*:/i)) {
      currentEntry.status = extractValue(line).toLowerCase();
    } else if (line.match(/^-?\s*Error\s*:/i)) {
      currentEntry.error = extractValue(line);
      if (!currentEntry.status) currentEntry.status = 'error';
    } else if (line.match(/^-?\s*Warning\s*:/i)) {
      currentEntry.warning = extractValue(line);
    } else if (line.match(/^-?\s*Bitrate\s*:/i)) {
      const val = extractValue(line);
      if (val) currentEntry.bitrate = val;
    } else if (line.match(/File\s+Encoded/i)) {
      // AME Windows format: "03/31/2026 05:09:33 PM : File Encoded with warning"
      if (line.match(/with\s+warning/i)) {
        currentEntry.status = 'warning';
      } else {
        currentEntry.status = 'done';
      }
      currentEntry.type = 'success';
    } else if (line.match(/Queue\s+Started/i)) {
      // Skip queue start lines — not an entry
      if (currentEntry && Object.keys(currentEntry).length <= 2) {
        currentEntry = null;
      }
      continue;
    } else if (line.match(/Queue\s+Stopped/i)) {
      // Skip queue stop lines
      continue;
    } else if (line.match(/^Log\s+File\s+Created/i)) {
      // Skip header line
      continue;
    } else if (line.match(/^-+$/)) {
      // Separator line — might end an entry
      continue;
    } else if (line.match(/Offline\s+media/i) || line.match(/Missing\s+Asset/i)) {
      // Warning details from AME
      if (!currentEntry.warnings) currentEntry.warnings = [];
      currentEntry.warnings.push(line);
    } else if (line.match(/^\d{1,2}\/\d{1,2}\/\d{2,4}/)) {
      // Timestamp line at end of entry
      currentEntry.timestamp = line;
      const dateMatch = line.match(/^(\d{1,2}\/\d{1,2}\/\d{2,4})\s+(\d{1,2}:\d{2}:\d{2}\s*[AP]?M?)/i);
      if (dateMatch) {
        currentEntry.date = dateMatch[1];
        currentEntry.time = dateMatch[2];
      }
    } else if (line.match(/^-?\s*Format\s*:/i)) {
      currentEntry.format = extractValue(line);
    } else if (line.match(/^-?\s*Duration\s*:/i)) {
      currentEntry.duration = extractValue(line);
    }
  }

  // Don't forget the last entry
  if (currentEntry && Object.keys(currentEntry).length > 1) {
    entries.push(currentEntry);
  }

  return entries;
}

/**
 * Parse video details from the video line
 */
function parseVideoDetails(entry) {
  if (!entry.video) return;

  const v = entry.video;

  // Resolution: e.g., "1920x1080"
  const resMatch = v.match(/(\d{2,5})x(\d{2,5})/);
  if (resMatch) {
    entry.resolution = `${resMatch[1]}x${resMatch[2]}`;
  }

  // Frame rate: e.g., "29.97 fps"
  const fpsMatch = v.match(/([\d.]+)\s*fps/i);
  if (fpsMatch) {
    entry.frameRate = parseFloat(fpsMatch[1]);
  }

  // Bitrate: e.g., "Target 10.00 Mbps" or "10 Mbps"
  const brMatch = v.match(/([\d.]+)\s*[MKk]bps/i);
  if (brMatch) {
    entry.videoBitrate = brMatch[0];
  }
}

/**
 * Extract value from a "- Key: Value" or "Key: Value" line
 */
function extractValue(line) {
  return line.replace(/^-?\s*[^:]+:\s*/, '').trim();
}

/**
 * Parse "HH:MM:SS" or "HH:MM:SS.mmm" to milliseconds
 */
function parseTimeToMs(timeStr) {
  if (!timeStr) return null;
  const parts = timeStr.split(':');
  if (parts.length >= 3) {
    const hrs = parseInt(parts[0]) || 0;
    const mins = parseInt(parts[1]) || 0;
    const secs = parseFloat(parts[2]) || 0;
    return (hrs * 3600 + mins * 60 + secs) * 1000;
  }
  return null;
}

/**
 * Read and parse AME log files from a directory.
 * Returns combined results from both encoding and error logs.
 */
function readAMELogs(logDir) {
  const result = {
    encodingLog: { exists: false, entries: [], lastModified: null, path: null },
    errorLog: { exists: false, entries: [], lastModified: null, path: null },
    stats: {
      totalEncoded: 0,
      totalErrors: 0,
      totalEncodingTimeMs: 0,
      averageEncodingTimeMs: 0,
      lastEncoded: null,
      lastError: null,
      recentEntries: []
    }
  };

  if (!logDir || !fs.existsSync(logDir)) return result;

  // Find log files
  const encodingLogPath = path.join(logDir, 'AMEEncodingLog.txt');
  const errorLogPath = path.join(logDir, 'AMEEncodingErrorLog.txt');

  // Parse encoding log
  if (fs.existsSync(encodingLogPath)) {
    result.encodingLog.exists = true;
    result.encodingLog.path = encodingLogPath;
    try {
      const stat = fs.statSync(encodingLogPath);
      result.encodingLog.lastModified = stat.mtime.toISOString();
      const content = readFileAutoEncoding(encodingLogPath);
      result.encodingLog.entries = parseAMELog(content);
    } catch (e) {
      result.encodingLog.error = e.message;
    }
  }

  // Parse error log
  if (fs.existsSync(errorLogPath)) {
    result.errorLog.exists = true;
    result.errorLog.path = errorLogPath;
    try {
      const stat = fs.statSync(errorLogPath);
      result.errorLog.lastModified = stat.mtime.toISOString();
      const content = readFileAutoEncoding(errorLogPath);
      result.errorLog.entries = parseAMELog(content);
    } catch (e) {
      result.errorLog.error = e.message;
    }
  }

  // Compute stats
  const allSuccessEntries = result.encodingLog.entries.filter(e =>
    !e.status || e.status === 'done' || e.status === 'complete' || e.status === 'success' || e.status === 'warning'
  );
  const allErrorEntries = [
    ...result.errorLog.entries,
    ...result.encodingLog.entries.filter(e =>
      e.status === 'error' || e.status === 'failed' || e.status === 'stopped'
    )
  ];

  result.stats.totalEncoded = allSuccessEntries.length;
  result.stats.totalErrors = allErrorEntries.length;

  // Encoding time stats
  const timesMs = allSuccessEntries
    .filter(e => e.encodingTimeMs)
    .map(e => e.encodingTimeMs);

  if (timesMs.length > 0) {
    result.stats.totalEncodingTimeMs = timesMs.reduce((a, b) => a + b, 0);
    result.stats.averageEncodingTimeMs = Math.round(result.stats.totalEncodingTimeMs / timesMs.length);
  }

  // Last entries
  if (allSuccessEntries.length > 0) {
    result.stats.lastEncoded = allSuccessEntries[allSuccessEntries.length - 1];
  }
  if (allErrorEntries.length > 0) {
    result.stats.lastError = allErrorEntries[allErrorEntries.length - 1];
  }

  // Recent entries (last 20, combined and sorted newest first)
  const allEntries = [
    ...result.encodingLog.entries.map(e => ({ ...e, type: 'success' })),
    ...result.errorLog.entries.map(e => ({ ...e, type: 'error' }))
  ];

  // Take last 20 (entries are appended, so last = newest)
  result.stats.recentEntries = allEntries.slice(-20).reverse();

  return result;
}

/**
 * Watch an AME log file for changes and call a callback with new entries.
 * Returns a function to stop watching.
 */
function watchAMELog(logDir, callback, intervalMs = 3000) {
  let lastEncodingSize = 0;
  let lastErrorSize = 0;

  const encodingLogPath = path.join(logDir, 'AMEEncodingLog.txt');
  const errorLogPath = path.join(logDir, 'AMEEncodingErrorLog.txt');

  // Get initial sizes
  try {
    if (fs.existsSync(encodingLogPath)) lastEncodingSize = fs.statSync(encodingLogPath).size;
  } catch {}
  try {
    if (fs.existsSync(errorLogPath)) lastErrorSize = fs.statSync(errorLogPath).size;
  } catch {}

  const timer = setInterval(() => {
    let changed = false;

    // Check encoding log for new content
    try {
      if (fs.existsSync(encodingLogPath)) {
        const stat = fs.statSync(encodingLogPath);
        if (stat.size > lastEncodingSize) {
          // Read only new content
          const fd = fs.openSync(encodingLogPath, 'r');
          const newBytes = Buffer.alloc(stat.size - lastEncodingSize);
          fs.readSync(fd, newBytes, 0, newBytes.length, lastEncodingSize);
          fs.closeSync(fd);
          lastEncodingSize = stat.size;

          const newEntries = parseAMELog(newBytes.toString('utf-8'));
          if (newEntries.length > 0) {
            callback({ type: 'encoding', entries: newEntries });
            changed = true;
          }
        }
      }
    } catch {}

    // Check error log for new content
    try {
      if (fs.existsSync(errorLogPath)) {
        const stat = fs.statSync(errorLogPath);
        if (stat.size > lastErrorSize) {
          const fd = fs.openSync(errorLogPath, 'r');
          const newBytes = Buffer.alloc(stat.size - lastErrorSize);
          fs.readSync(fd, newBytes, 0, newBytes.length, lastErrorSize);
          fs.closeSync(fd);
          lastErrorSize = stat.size;

          const newEntries = parseAMELog(newBytes.toString('utf-8'));
          if (newEntries.length > 0) {
            callback({ type: 'error', entries: newEntries });
            changed = true;
          }
        }
      }
    } catch {}
  }, intervalMs);

  return () => clearInterval(timer);
}

/**
 * Format milliseconds as human-readable duration
 */
function formatDuration(ms) {
  if (!ms) return '–';
  const secs = Math.floor(ms / 1000);
  const hrs = Math.floor(secs / 3600);
  const mins = Math.floor((secs % 3600) / 60);
  const s = secs % 60;
  if (hrs > 0) return `${hrs}h ${mins}m ${s}s`;
  if (mins > 0) return `${mins}m ${s}s`;
  return `${s}s`;
}

module.exports = { parseAMELog, readAMELogs, watchAMELog, formatDuration };