Refactor logging by using log4js (#94)

* refactor(Stryker.ts) Use log4js in stryker

* refactor(TestRunnerOrchestrator.ts) Use log4js in the test runner orchestrator

* refactor(install-module) Fix for integration test

* refactor(IsolatedTestRunnerAdapter.ts) Use log4js in the isolated test runner adapter

* refactor(Stryker) Add logging for read config

* refactor(TestRunnerOrchestrator) Rename TestRunnerMetadata to TestRunnerSandbox

* refactor(IsolatedTestRunnerAdapter) Add a test before trace logging

* refactor(general) Replace last console.log statements with log4js log statements

* docs(readme) Remove notification about migration to log4js

.vscode/launch.json

@@ -6,7 +6,7 @@
             "type": "node",
             "request": "launch",
             "program": "${workspaceRoot}/node_modules/grunt-cli/bin/grunt",
-            // "preLaunchTask": "ts",
+            "preLaunchTask": "ts",
             "stopOnEntry": false,
             "args": [
                 "mochaTest:unit"
@@ -50,13 +50,15 @@
             "type": "node",
             "request": "launch",
             "program": "${workspaceRoot}/dist/src/Stryker.js",
-            // "preLaunchTask": "ts",
+            "preLaunchTask": "ts",
             "stopOnEntry": false,
             "args": [
                 "--mutate",
                 "test/sampleProject/src/+(Add|Circle).js",
                 "--files",
-                "test/sampleProject/src/Add.js,test/sampleProject/src/Circle.js,test/sampleProject/test/AddSpec.js,test/sampleProject/test/CircleSpec.js"
+                "test/sampleProject/src/Add.js,test/sampleProject/src/Circle.js,test/sampleProject/test/AddSpec.js,test/sampleProject/test/CircleSpec.js",
+                "--logLevel",
+                "debug"
             ],
             "cwd": "${workspaceRoot}/.",
             "runtimeExecutable": null,

README.md

@@ -83,7 +83,6 @@ The order of the files specified here will be the order used to load the file in
 **Config file key:** `logLevel`  
 **Description:**  
  Set the log4js loglevel. Possible values: fatal, error, warn, info, debug, trace, all and off. Default is "info"
- *Note: We are still migrating to using log4js. Some messages are not configurable*
 
 ### Config file
 **Short notation:** `-c`  

src/InputFileResolver.ts

@@ -1,6 +1,9 @@
 import {InputFile} from './api/core';
 import {glob, normalize} from './utils/fileUtils';
 import * as _ from 'lodash';
+import * as log4js from 'log4js';
+
+const log = log4js.getLogger('InputFileResolver');
 
 export default class InputFileResolver {
 
@@ -34,7 +37,7 @@ export default class InputFileResolver {
 
 
   private static reportEmptyGlobbingExpression(expression: string) {
-    console.log(`WARNING: Globbing expression "${expression}" did not result in any files.`)
+    log.warn(`Globbing expression "${expression}" did not result in any files.`);
   }
 
   private static resolveFileGlobs(sourceExpressions: string[]): Promise<string[]> {

src/Mutator.ts

@@ -6,6 +6,9 @@ import * as fileUtils from './utils/fileUtils';
 import Mutant from './Mutant';
 import MutationRegistry from './MutationRegistry';
 import * as parserUtils from './utils/parserUtils';
+import * as log4js from 'log4js';
+
+const log = log4js.getLogger('Mutator');
 
 /**
  * Class capable of finding spots to mutate in files.
@@ -40,7 +43,7 @@ export default class Mutator {
       } catch (err) {
         switch (err.code) {
           case 'ENOENT':
-            console.log(`Skipping file ${err.path} because it does not exist`);
+            log.info(`Skipping file ${err.path} because it does not exist`);
             break;
           default:
             throw err;

src/Stryker.ts

@@ -20,6 +20,8 @@ import PluginLoader from './PluginLoader';
 import {freezeRecursively} from './utils/objectUtils';
 import * as log4js from 'log4js';
 
+const log = log4js.getLogger('Stryker');
+
 export default class Stryker {
 
   reporter: BaseReporter;
@@ -39,7 +41,7 @@ export default class Stryker {
     this.loadPlugins();
     this.applyConfigWriters();
     this.setGlobalLogLevel(); // loglevel could be changed
-    freezeRecursively(this.config);
+    this.freezeConfig();
     var reporterFactory = new ReporterFactory();
     this.reporter = reporterFactory.getReporter('console');
   }
@@ -54,20 +56,20 @@ export default class Stryker {
 
       new InputFileResolver(this.config.mutate, this.config.files)
         .resolve().then(inputFiles => {
-          console.log('INFO: Running initial test run');
+          log.info('Running initial test run');
           let testRunnerOrchestrator = new TestRunnerOrchestrator(this.config, inputFiles)
           testRunnerOrchestrator.recordCoverage().then((runResults) => {
             let unsuccessfulTests = runResults.filter((runResult: RunResult) => {
               return !(runResult.failed === 0 && runResult.result === TestResult.Complete);
             });
             if (unsuccessfulTests.length === 0) {
-              console.log(`INFO: Initial test run succeeded. Ran ${runResults.length} tests.`);
+              log.info(`Initial test run succeeded. Ran ${runResults.length} tests.`);
 
               let mutator = new Mutator();
               let mutants = mutator.mutate(inputFiles
                 .filter(inputFile => inputFile.shouldMutate)
                 .map(file => file.path));
-              console.log('INFO: ' + mutants.length + ' Mutants generated');
+              log.info(`${mutants.length} Mutant(s) generated`);
 
               let mutantRunResultMatcher = new MutantRunResultMatcher(mutants, runResults);
               mutantRunResultMatcher.matchWithMutants();
@@ -84,7 +86,7 @@ export default class Stryker {
             strykerReject(errors);
           });
         }, (errors: string[]) => {
-          errors.forEach(error => console.log(`ERROR: ${error}`));
+          errors.forEach(error => log.error(error));
           strykerReject();
         });
     });
@@ -102,6 +104,13 @@ export default class Stryker {
     });
   }
 
+  private freezeConfig() {
+    freezeRecursively(this.config);
+    if (log.isDebugEnabled()) {
+      log.debug(`Using config: ${JSON.stringify(this.config)}`);
+    }
+  }
+
   private setGlobalLogLevel() {
     log4js.setGlobalLogLevel(this.config.logLevel);
   }
@@ -121,8 +130,9 @@ export default class Stryker {
         ))
         .sort();
     if (failedSpecNames.length > 0) {
-      console.log('ERROR: One or more tests failed in the inial test run:');
-      failedSpecNames.forEach(filename => console.log('\t', filename));
+      let message = 'One or more tests failed in the inial test run:';
+      failedSpecNames.forEach(filename => message += `\n\t${filename}`);
+      log.error(message);
     }
 
     let errors =
@@ -132,8 +142,9 @@ export default class Stryker {
         .sort();
 
     if (errors.length > 0) {
-      console.log('ERROR: One or more tests errored in the initial test run:')
-      errors.forEach(error => console.log('\t', error));
+      let message = 'One or more tests errored in the initial test run:';
+      errors.forEach(error => message += `\n\t${error}`);
+      log.error(message);
     }
   }
 }
@@ -156,5 +167,16 @@ export default class Stryker {
 
   log4js.setGlobalLogLevel(program['logLevel'] || 'info')
 
+  // Cleanup commander state
+  delete program.options;
+  delete program.rawArgs;
+  delete program.args;
+  delete program.commands;
+  for (let i in program) {
+    if (i.charAt(0) === '_') {
+      delete program[i];
+    }
+  }
+
   new Stryker(program).runMutationTest();
 })();

src/TestRunnerOrchestrator.ts

@@ -9,13 +9,17 @@ import * as os from 'os';
 import * as _ from 'lodash';
 import Mutant, {MutantStatus} from './Mutant';
 import BaseReporter from './reporters/BaseReporter';
+import * as log4js from 'log4js';
 const PromisePool = require('es6-promise-pool')
 
+const log = log4js.getLogger('TestRunnerOrchestrator');
+
 interface FileMap {
   [sourceFile: string]: string
 }
 
-interface TestRunnerMetadata {
+interface TestRunnerSandbox {
+  index: number;
   runnerAdapter: IsolatedTestRunnerAdapter;
   selector: TestSelector;
   sourceFileMap: FileMap;
@@ -28,7 +32,7 @@ export default class TestRunnerOrchestrator {
 
   recordCoverage(): Promise<RunResult[]> {
     let testSelector = TestSelectorFactory.instance().create(this.options.testFramework, { options: this.options });
-    let testRunner = IsolatedTestRunnerAdapterFactory.create(this.createTestRunSettings(this.files, testSelector, this.options.port, true));
+    let testRunner = IsolatedTestRunnerAdapterFactory.create(this.createTestRunSettings(this.files, testSelector, 0, true));
     return this.runSingleTestsRecursive(testSelector, testRunner, [], 0).then((testResults) => {
       testRunner.dispose();
       return testResults;
@@ -37,13 +41,12 @@ export default class TestRunnerOrchestrator {
 
   runMutations(mutants: Mutant[], reporter: BaseReporter): Promise<void> {
     mutants = _.clone(mutants); // work with a copy because we're changing state (pop'ing values)
-    return this.createTestRunners().then(testRunners => {
+    return this.createTestRunnerSandboxes().then(testRunners => {
       let promiseProducer: () => Promise<number> | Promise<void> = () => {
         if (mutants.length === 0) {
           return null; // we're done
         } else {
           var mutant = mutants.pop(); 
-
           if (mutant.scopedTestIds.length > 0) {
             let nextRunner = testRunners.pop();
             let sourceFileCopy = nextRunner.sourceFileMap[mutant.filename];
@@ -107,21 +110,21 @@ export default class TestRunnerOrchestrator {
     })
   }
 
-  private createTestRunners(): Promise<TestRunnerMetadata[]> {
+  private createTestRunnerSandboxes(): Promise<TestRunnerSandbox[]> {
 
-    return new Promise<TestRunnerMetadata[]>((resolve, reject) => {
+    return new Promise<TestRunnerSandbox[]>((resolve, reject) => {
       let cpuCount = os.cpus().length;
-      let testRunnerMetadatas: TestRunnerMetadata[] = [];
+      let testRunnerSandboxes: TestRunnerSandbox[] = [];
       let allPromises: Promise<any>[] = [];
-      console.log(`INFO: Creating ${cpuCount} test runners (based on cpu count)`);
+      log.info(`Creating ${cpuCount} test runners (based on cpu count)`);
       for (let i = 0; i < cpuCount; i++) {
-        allPromises.push(this.createTestRunner(i).then(testRunnerMetadata => testRunnerMetadatas.push(testRunnerMetadata)));
+        allPromises.push(this.createSandbox(i).then(sandbox => testRunnerSandboxes.push(sandbox)));
       }
-      Promise.all(allPromises).then(() => resolve(testRunnerMetadatas));
+      Promise.all(allPromises).then(() => resolve(testRunnerSandboxes));
     });
   }
 
-  private createTestRunner(portOffset: number): Promise<TestRunnerMetadata> {
+  private createSandbox(index: number): Promise<TestRunnerSandbox> {
     return this.copyAllSourceFilesToTempFolder().then(sourceFileMap => {
       let selector = TestSelectorFactory.instance().create(this.options.testFramework, { options: this.options });
       let runnerFiles: InputFile[] = [];
@@ -133,8 +136,9 @@ export default class TestRunnerOrchestrator {
         }
       });
       return {
+        index,
         sourceFileMap,
-        runnerAdapter: IsolatedTestRunnerAdapterFactory.create(this.createTestRunSettings(runnerFiles, selector, this.options.port + portOffset, false)),
+        runnerAdapter: IsolatedTestRunnerAdapterFactory.create(this.createTestRunSettings(runnerFiles, selector, index, false)),
         selector
       };
     });
@@ -144,6 +148,7 @@ export default class TestRunnerOrchestrator {
     return new Promise<FileMap>((resolve, reject) => {
       let fileMap: FileMap = Object.create(null);
       var tempFolder = StrykerTempFolder.createRandomFolder('test-runner-source-files');
+      log.debug('Making a sandbox for source files in %s', tempFolder);
       let copyPromises: Promise<any>[] = this.files.map(file => {
         if (file.shouldMutate) {
           let targetFile = tempFolder + path.sep + path.basename(file.path);
@@ -157,12 +162,14 @@ export default class TestRunnerOrchestrator {
     });
   }
 
-  private createTestRunSettings(files: InputFile[], selector: TestSelector, port: number, coverageEnabled: boolean): RunnerOptions {
-    return {
+  private createTestRunSettings(files: InputFile[], selector: TestSelector, index: number, coverageEnabled: boolean): RunnerOptions {
+    let settings = {
       coverageEnabled,
       files: selector.files().map(f => { return { path: f, shouldMutate: false }; }).concat(files),
       strykerOptions: this.options,
-      port: port
+      port: this.options.port + index
     };
+    log.debug(`Creating test runner %s using settings {port: %s, coverageEnabled: %s}`, index, settings.port, settings.coverageEnabled);
+    return settings;
   }
 }

src/isolated-runner/IsolatedTestRunnerAdapter.ts

@@ -6,6 +6,9 @@ import StartMessageBody from './StartMessageBody';
 import RunMessageBody from './RunMessageBody';
 import ResultMessageBody from './ResultMessageBody';
 import * as _ from 'lodash';
+import * as log4js from 'log4js';
+
+const log = log4js.getLogger('IsolatedTestRunnerAdapter');
 
 /**
  * Runs the given test runner in a child process and forwards reports about test results
@@ -37,11 +40,16 @@ export default class TestRunnerChildProcessAdapter extends TestRunner {
   private listenToWorkerProcess() {
 
     if (this.workerProcess.stdout) {
-      this.workerProcess.stdout.on('data', (data: any) => { /* do nothing */ });
+      let traceEnabled = log.isTraceEnabled();
+      this.workerProcess.stdout.on('data', (data: Buffer) => {
+        if (traceEnabled) {
+          log.trace(data.toString());
+        }
+      });
     }
     if (this.workerProcess.stderr) {
       this.workerProcess.stderr.on('data', (data: any) => {
-        console.log('ERROR: ' + data);
+        log.error(data.toString());
       });
     }
 
@@ -52,7 +60,7 @@ export default class TestRunnerChildProcessAdapter extends TestRunner {
           this.handleResultMessage(message);
           break;
         default:
-          console.error(`Retrieved unrecognized message from child process: ${JSON.stringify(message)}`)
+          log.error(`Retrieved unrecognized message from child process: ${JSON.stringify(message)}`)
           break;
       }
     });

src/karma-runner/KarmaTestRunner.ts

@@ -4,6 +4,9 @@ import * as _ from 'lodash';
 import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
+import * as log4js from 'log4js';
+
+const log = log4js.getLogger('KarmaTestRunner');
 
 interface ConfigOptions extends karma.ConfigOptions {
   coverageReporter?: { type: string, dir?: string, subdir?: string }
@@ -38,7 +41,7 @@ export default class KarmaTestRunner extends TestRunner {
     let karmaConfig = this.configureTestRunner(runnerOptions.strykerOptions['karma']);
     karmaConfig = this.configureCoverageIfEnabled(karmaConfig);
 
-    console.log(`using config ${JSON.stringify(karmaConfig)}`);
+    log.info(`using config ${JSON.stringify(karmaConfig)}`);
     this.server = new karma.Server(karmaConfig, function(exitCode) {
       process.exit(1);
     });
@@ -142,7 +145,7 @@ export default class KarmaTestRunner extends TestRunner {
     return new Promise<void>((resolve) => {
       let p = this.options.port;
       karma.runner.run({ port: p }, (exitCode) => {
-        console.log('karma run done with ', exitCode);
+        log.info('karma run done with ', exitCode);
         resolve();
       });
     });

test/helpers/log4jsMock.ts

@@ -1,12 +1,19 @@
 import * as log4js from 'log4js';
 import * as sinon from 'sinon';
 
+const l = log4js.getLogger();
 let logger = {
+  isTraceEnabled: sinon.stub(),
   trace: sinon.stub(),
+  isDebugEnabled: sinon.stub(),
   debug: sinon.stub(),
+  isInfoEnabled: sinon.stub(),
   info: sinon.stub(),
+  isWarnEnabled: sinon.stub(),
   warn: sinon.stub(),
+  isErrorEnabled: sinon.stub(),
   error: sinon.stub(),
+  isFatalEnabled: sinon.stub(),
   fatal: sinon.stub()
 };
 

test/integration/config-reader/ConfigReaderSpec.ts

@@ -36,7 +36,6 @@ describe('ConfigReader', () => {
     describe('with config file', () => {
 
       beforeEach(() => {
-        console.log(process.cwd());
         sut = new ConfigReader({ configFile: 'test/integration/config-reader/valid.conf.js' });
         result = sut.readConfig();
       });

test/integration/install-module/install-module.ts

@@ -29,7 +29,7 @@ describe('we have a module using stryker', function () {
       });
 
       it('should have ran stryker', () => {
-        expect(resultOutput).to.have.string('INFO: Initial test run succeeded. Ran 6 tests.');
+        expect(resultOutput).to.have.string('Initial test run succeeded. Ran 6 tests.');
         expect(resultOutput).to.have.string('Mutation score based on code coverage');
         expect(resultOutput).to.have.string('Mutation score based on codebase');
       });