Feature: verbose logging updates (#165)

src/console/logLevel.ts

@@ -1,4 +1,5 @@
 enum LogLevel {
+  TRACE,
   DEBUG,
   INFO,
   WARN,

src/console/logger.ts

@@ -3,16 +3,24 @@ import figlet from 'figlet';
 
 import Constants from '../constants.js';
 import LogLevel from './logLevel.js';
+import { Symbols } from './progressBar.js';
 import ProgressBarCLI from './progressBarCLI.js';
 
 export default class Logger {
   private logLevel: LogLevel;
 
   private readonly stream: NodeJS.WritableStream;
 
-  constructor(logLevel: LogLevel = LogLevel.WARN, stream: NodeJS.WritableStream = process.stdout) {
+  private readonly loggerPrefix?: string;
+
+  constructor(
+    logLevel: LogLevel = LogLevel.WARN,
+    stream: NodeJS.WritableStream = process.stdout,
+    loggerPrefix?: string,
+  ) {
     this.logLevel = logLevel;
     this.stream = stream;
+    this.loggerPrefix = loggerPrefix;
   }
 
   getLogLevel(): LogLevel {
@@ -29,34 +37,39 @@ export default class Logger {
 
   private readonly print = (logLevel: LogLevel, message: unknown = ''): void => {
     if (this.logLevel <= logLevel) {
-      this.stream.write(`${Logger.formatMessage(logLevel, String(message).toString())}\n`);
+      this.stream.write(`${this.formatMessage(logLevel, String(message).toString())}\n`);
     }
   };
 
   newLine(): void {
     this.print(LogLevel.ALWAYS);
   }
 
-  static formatMessage(logLevel: LogLevel, message: string): string {
+  formatMessage(logLevel: LogLevel, message: string): string {
     // Don't format "ALWAYS" or "NEVER"
     if (logLevel >= LogLevel.ALWAYS) {
       return message;
     }
 
     const chalkFuncs: { [key: number]: (message: string) => string } = {
+      [LogLevel.TRACE]: chalk.grey,
       [LogLevel.DEBUG]: chalk.magenta,
       [LogLevel.INFO]: chalk.cyan,
       [LogLevel.WARN]: chalk.yellow,
       [LogLevel.ERROR]: chalk.red,
     };
     const chalkFunc = chalkFuncs[logLevel];
 
+    const loggerPrefix = this.logLevel <= LogLevel.INFO && this.loggerPrefix ? `${this.loggerPrefix}: ` : '';
+
     return message.trim()
       .split('\n')
-      .map((m) => chalkFunc(`${LogLevel[logLevel]}: `) + m)
+      .map((m) => chalkFunc(`${LogLevel[logLevel]}: `) + loggerPrefix + m)
       .join('\n');
   }
 
+  trace = (message: unknown = ''): void => this.print(LogLevel.TRACE, message);
+
   debug = (message: unknown = ''): void => this.print(LogLevel.DEBUG, message);
 
   info = (message: unknown = ''): void => this.print(LogLevel.INFO, message);
@@ -100,7 +113,15 @@ export default class Logger {
     );
   }
 
-  async addProgressBar(name: string, symbol: string, initialTotal = 0): Promise<ProgressBarCLI> {
+  async addProgressBar(
+    name: string,
+    symbol = Symbols.WAITING,
+    initialTotal = 0,
+  ): Promise<ProgressBarCLI> {
     return ProgressBarCLI.new(this, name, symbol, initialTotal);
   }
+
+  withLoggerPrefix(prefix: string): Logger {
+    return new Logger(this.logLevel, this.stream, prefix);
+  }
 }

src/console/progressBar.ts

@@ -37,8 +37,14 @@ export default abstract class ProgressBar {
     return this.done(`${count.toLocaleString()} ${noun.trim()}${count !== 1 ? pluralSuffix : ''} ${verb}`);
   }
 
+  abstract withLoggerPrefix(prefix: string): ProgressBar;
+
   abstract log(logLevel: LogLevel, message: string): Promise<void>;
 
+  async logTrace(message: string): Promise<void> {
+    return this.log(LogLevel.TRACE, message);
+  }
+
   async logDebug(message: string): Promise<void> {
     return this.log(LogLevel.DEBUG, message);
   }

src/console/progressBarCLI.ts

@@ -135,9 +135,13 @@ export default class ProgressBarCLI extends ProgressBar {
     return ProgressBarCLI.render();
   }
 
+  withLoggerPrefix(prefix: string): ProgressBar {
+    return new ProgressBarCLI(this.logger.withLoggerPrefix(prefix), this.singleBarFormatted);
+  }
+
   async log(logLevel: LogLevel, message: string): Promise<void> {
     if (this.logger.getLogLevel() <= logLevel) {
-      ProgressBarCLI.multiBar?.log(`${Logger.formatMessage(logLevel, message)}\n`);
+      ProgressBarCLI.multiBar?.log(`${this.logger.formatMessage(logLevel, message)}\n`);
       await ProgressBarCLI.render();
     }
   }

src/igir.ts

@@ -39,16 +39,18 @@ export default class Igir {
     const rawRomFiles = await this.processROMScanner();
     const patches = await this.processPatchScanner();
     const processedRomFiles = await this.processHeaderProcessor(rawRomFiles);
-    if (!dats.length) {
-      dats = DATInferrer.infer(processedRomFiles);
-    }
 
     // Set up progress bar and input for DAT processing
     const datProcessProgressBar = await this.logger.addProgressBar('Processing DATs', Symbols.PROCESSING, dats.length);
+    if (!dats.length) {
+      dats = await new DATInferrer(datProcessProgressBar).infer(processedRomFiles);
+    }
+
     const datsToWrittenRoms = new Map<DAT, Map<Parent, File[]>>();
     const datsStatuses: DATStatus[] = [];
 
     // Process every DAT
+    await datProcessProgressBar.logInfo(`Processing ${dats.length.toLocaleString()} DAT${dats.length !== 1 ? 's' : ''}`);
     await async.eachLimit(dats, Constants.DAT_THREADS, async (dat, callback) => {
       const progressBar = await this.logger.addProgressBar(
         dat.getNameShort(),
@@ -93,6 +95,7 @@ export default class Igir {
 
       callback();
     });
+    await datProcessProgressBar.logInfo(`Done processing ${dats.length.toLocaleString()} DAT${dats.length !== 1 ? 's' : ''}`);
 
     await datProcessProgressBar.doneItems(dats.length, 'DAT', 'processed');
     datProcessProgressBar.delete();
@@ -111,7 +114,7 @@ export default class Igir {
       return [];
     }
 
-    const progressBar = await this.logger.addProgressBar('Scanning for DATs', Symbols.WAITING);
+    const progressBar = await this.logger.addProgressBar('Scanning for DATs');
     const dats = await new DATScanner(this.options, progressBar).scan();
     if (!dats.length) {
       progressBar.delete();
@@ -129,7 +132,7 @@ export default class Igir {
   }
 
   private async processROMScanner(): Promise<File[]> {
-    const progressBar = await this.logger.addProgressBar('Scanning for ROMs', Symbols.WAITING);
+    const progressBar = await this.logger.addProgressBar('Scanning for ROMs');
     const roms = await new ROMScanner(this.options, progressBar).scan();
     await progressBar.doneItems(roms.length, 'unique ROM', 'found');
     await progressBar.freeze();
@@ -141,15 +144,15 @@ export default class Igir {
       return [];
     }
 
-    const progressBar = await this.logger.addProgressBar('Scanning for patches', Symbols.WAITING);
+    const progressBar = await this.logger.addProgressBar('Scanning for patches');
     const patches = await new PatchScanner(this.options, progressBar).scan();
     await progressBar.doneItems(patches.length, 'unique patch', 'found');
     await progressBar.freeze();
     return patches;
   }
 
   private async processHeaderProcessor(romFiles: File[]): Promise<File[]> {
-    const progressBar = await this.logger.addProgressBar('Detecting ROM headers', Symbols.WAITING);
+    const progressBar = await this.logger.addProgressBar('Detecting ROM headers');
     const processedRomFiles = await new HeaderProcessor(this.options, progressBar)
       .process(romFiles);
     await progressBar.doneItems(processedRomFiles.length, 'ROM', 'processed');
@@ -164,7 +167,7 @@ export default class Igir {
       return;
     }
 
-    const progressBar = await this.logger.addProgressBar('Cleaning output directory', Symbols.WAITING);
+    const progressBar = await this.logger.addProgressBar('Cleaning output directory');
     const writtenFilesToExclude = [...datsToWrittenRoms.values()]
       .flatMap((parentsToFiles) => [...parentsToFiles.values()])
       .flatMap((files) => files);

src/modules/argumentsParser.ts

@@ -354,7 +354,7 @@ export default class ArgumentsParser {
       .option('verbose', {
         group: groupHelp,
         alias: 'v',
-        description: 'Enable verbose logging, can specify twice (-vv)',
+        description: 'Enable verbose logging, can specify up to three times (-vvv)',
         type: 'count',
       })
 

src/modules/candidateFilter.ts

@@ -3,21 +3,20 @@ import DAT from '../types/logiqx/dat.js';
 import Parent from '../types/logiqx/parent.js';
 import Options from '../types/options.js';
 import ReleaseCandidate from '../types/releaseCandidate.js';
+import Module from './module.js';
 
 /**
  * Apply any specified filter and preference options to the release candidates for each
  * {@link Parent}.
  *
  * This class may be run concurrently with other classes.
  */
-export default class CandidateFilter {
+export default class CandidateFilter extends Module {
   private readonly options: Options;
 
-  private readonly progressBar: ProgressBar;
-
   constructor(options: Options, progressBar: ProgressBar) {
+    super(progressBar, CandidateFilter.name);
     this.options = options;
-    this.progressBar = progressBar;
   }
 
   async filter(
@@ -47,19 +46,20 @@ export default class CandidateFilter {
     for (let i = 0; i < [...parentsToCandidates.entries()].length; i += 1) {
       const [parent, releaseCandidates] = [...parentsToCandidates.entries()][i];
       await this.progressBar.increment();
-      await this.progressBar.logDebug(`${dat.getName()}: Filtering ${parent.getName()}: ${releaseCandidates.length} candidates before`);
+      await this.progressBar.logTrace(`${dat.getName()}: ${parent.getName()}: ${releaseCandidates.length} candidates before filtering`);
 
       const filteredReleaseCandidates = releaseCandidates
         .filter((rc) => this.preFilter(rc))
         .sort((a, b) => this.sort(a, b))
         .filter((rc, idx) => this.postFilter(idx));
-      await this.progressBar.logDebug(`${dat.getName()}: Filtering ${parent.getName()}: ${filteredReleaseCandidates.length} candidates after`);
+      await this.progressBar.logTrace(`${dat.getName()}: ${parent.getName()}: ${filteredReleaseCandidates.length} candidates after filtering`);
       output.set(parent, filteredReleaseCandidates);
     }
 
     const filteredCandidates = [...output.values()].reduce((sum, rc) => sum + rc.length, 0);
-    await this.progressBar.logInfo(`${dat.getName()}: ${filteredCandidates} candidate${filteredCandidates !== 1 ? 's' : ''} after filtering`);
+    await this.progressBar.logDebug(`${dat.getName()}: ${filteredCandidates.toLocaleString()} candidate${filteredCandidates !== 1 ? 's' : ''} after filtering`);
 
+    await this.progressBar.logInfo(`${dat.getName()}: Done filtering candidates`);
     return output;
   }
 

src/modules/candidateGenerator.ts

@@ -12,21 +12,21 @@ import ROM from '../types/logiqx/rom.js';
 import Options from '../types/options.js';
 import ReleaseCandidate from '../types/releaseCandidate.js';
 import ROMWithFiles from '../types/romWithFiles.js';
+import CandidateFilter from './candidateFilter.js';
+import Module from './module.js';
 
 /**
  * For every {@link Parent} in the {@link DAT}, look for its {@link ROM}s in the scanned ROM list,
  * and return a set of candidate files.
  *
  * This class may be run concurrently with other classes.
  */
-export default class CandidateGenerator {
+export default class CandidateGenerator extends Module {
   private readonly options: Options;
 
-  private readonly progressBar: ProgressBar;
-
   constructor(options: Options, progressBar: ProgressBar) {
+    super(progressBar, CandidateFilter.name);
     this.options = options;
-    this.progressBar = progressBar;
   }
 
   async generate(
@@ -47,7 +47,7 @@ export default class CandidateGenerator {
     // TODO(cemmer): only do this once globally, not per DAT
     // TODO(cemmer): ability to index files by some other property such as name
     const hashCodeToInputFiles = CandidateGenerator.indexFilesByHashCode(inputRomFiles);
-    await this.progressBar.logInfo(`${dat.getName()}: ${hashCodeToInputFiles.size} unique ROMs found`);
+    await this.progressBar.logDebug(`${dat.getName()}: ${hashCodeToInputFiles.size.toLocaleString()} unique ROMs found`);
 
     // For each parent, try to generate a parent candidate
     /* eslint-disable no-await-in-loop */
@@ -78,13 +78,14 @@ export default class CandidateGenerator {
         }
       }
 
-      await this.progressBar.logDebug(`${dat.getName()}: Found ${releaseCandidates.length} candidates for ${parent.getName()}`);
+      await this.progressBar.logTrace(`${dat.getName()}: ${parent.getName()}: found ${releaseCandidates.length.toLocaleString()} candidates`);
       output.set(parent, releaseCandidates);
     }
 
     const totalCandidates = [...output.values()].reduce((sum, rc) => sum + rc.length, 0);
-    await this.progressBar.logInfo(`${dat.getName()}: ${totalCandidates} candidate${totalCandidates !== 1 ? 's' : ''} found`);
+    await this.progressBar.logDebug(`${dat.getName()}: ${totalCandidates.toLocaleString()} candidate${totalCandidates !== 1 ? 's' : ''} found`);
 
+    await this.progressBar.logInfo(`${dat.getName()}: Done generating candidates`);
     return output;
   }
 
@@ -127,7 +128,7 @@ export default class CandidateGenerator {
     // Ignore the Game if not every File is present
     if (missingRoms.length > 0) {
       if (foundRomsWithFiles.length > 0) {
-        await this.logMissingRomFiles(game, release, missingRoms);
+        await this.logMissingRomFiles(dat, game, release, missingRoms);
       }
       return undefined;
     }
@@ -176,11 +177,12 @@ export default class CandidateGenerator {
   }
 
   private async logMissingRomFiles(
+    dat: DAT,
     game: Game,
     release: Release | undefined,
     missingRoms: ROM[],
   ): Promise<void> {
-    let message = `Missing ${missingRoms.length.toLocaleString()} file${missingRoms.length !== 1 ? 's' : ''} for: ${game.getName()}`;
+    let message = `${dat.getName()}: Missing ${missingRoms.length.toLocaleString()} file${missingRoms.length !== 1 ? 's' : ''} for: ${game.getName()}`;
     if (release?.getRegion()) {
       message += ` (${release?.getRegion()})`;
     }

src/modules/datInferrer.ts

@@ -1,24 +1,36 @@
 import path from 'path';
 
+import ProgressBar from '../console/progressBar.js';
 import ArchiveEntry from '../types/files/archiveEntry.js';
 import File from '../types/files/file.js';
 import DAT from '../types/logiqx/dat.js';
 import Game from '../types/logiqx/game.js';
 import Header from '../types/logiqx/header.js';
 import ROM from '../types/logiqx/rom.js';
+import Module from './module.js';
+
+export default class DATInferrer extends Module {
+  constructor(progressBar: ProgressBar) {
+    super(progressBar, DATInferrer.name);
+  }
+
+  async infer(romFiles: File[]): Promise<DAT[]> {
+    await this.progressBar.logInfo(`Inferring DATs for ${romFiles.length} ROMs`);
 
-export default class DATInferrer {
-  static infer(romFiles: File[]): DAT[] {
     const datNamesToRomFiles = romFiles.reduce((map, file) => {
       const datName = DATInferrer.getDatName(file);
       const datRomFiles = map.get(datName) || [];
       datRomFiles.push(file);
       map.set(datName, datRomFiles);
       return map;
     }, new Map<string, File[]>());
+    await this.progressBar.logDebug(`Inferred ${datNamesToRomFiles.size.toLocaleString()} DAT${datNamesToRomFiles.size !== 1 ? 's' : ''}`);
 
-    return [...datNamesToRomFiles.entries()]
+    const dats = [...datNamesToRomFiles.entries()]
       .map(([datName, datRomFiles]) => DATInferrer.createDAT(datName, datRomFiles));
+
+    await this.progressBar.logInfo('Done inferring DATs');
+    return dats;
   }
 
   private static getDatName(file: File): string {