diff --git a/.vscode/launch.json b/.vscode/launch.json index fb027ae43f..de022dc0f8 100644 --- a/.vscode/launch.json +++ b/.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, diff --git a/README.md b/README.md index 6ba1950170..a1539abd79 100644 --- a/README.md +++ b/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` diff --git a/src/InputFileResolver.ts b/src/InputFileResolver.ts index 5476751f81..bfa493b02b 100644 --- a/src/InputFileResolver.ts +++ b/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 { diff --git a/src/Mutator.ts b/src/Mutator.ts index e045f3e7b9..8dd787b942 100644 --- a/src/Mutator.ts +++ b/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; diff --git a/src/Stryker.ts b/src/Stryker.ts index a6492d90ec..d569250292 100644 --- a/src/Stryker.ts +++ b/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(); })(); diff --git a/src/TestRunnerOrchestrator.ts b/src/TestRunnerOrchestrator.ts index 78fa168fa8..d9c65f5897 100644 --- a/src/TestRunnerOrchestrator.ts +++ b/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 { 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 { 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 | Promise = () => { 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 { + private createTestRunnerSandboxes(): Promise { - return new Promise((resolve, reject) => { + return new Promise((resolve, reject) => { let cpuCount = os.cpus().length; - let testRunnerMetadatas: TestRunnerMetadata[] = []; + let testRunnerSandboxes: TestRunnerSandbox[] = []; let allPromises: Promise[] = []; - 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 { + private createSandbox(index: number): Promise { 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((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[] = 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; } } \ No newline at end of file diff --git a/src/isolated-runner/IsolatedTestRunnerAdapter.ts b/src/isolated-runner/IsolatedTestRunnerAdapter.ts index 551fbdb90d..ba7d02e558 100644 --- a/src/isolated-runner/IsolatedTestRunnerAdapter.ts +++ b/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; } }); diff --git a/src/karma-runner/KarmaTestRunner.ts b/src/karma-runner/KarmaTestRunner.ts index 0f5ec5d5db..658dda2483 100644 --- a/src/karma-runner/KarmaTestRunner.ts +++ b/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((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(); }); }); diff --git a/test/helpers/log4jsMock.ts b/test/helpers/log4jsMock.ts index 4b6d01b50f..0692d51315 100644 --- a/test/helpers/log4jsMock.ts +++ b/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() }; diff --git a/test/integration/config-reader/ConfigReaderSpec.ts b/test/integration/config-reader/ConfigReaderSpec.ts index 04344eabc9..4758028525 100644 --- a/test/integration/config-reader/ConfigReaderSpec.ts +++ b/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(); }); diff --git a/test/integration/install-module/install-module.ts b/test/integration/install-module/install-module.ts index 00b252b8af..eac4699916 100644 --- a/test/integration/install-module/install-module.ts +++ b/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'); }); diff --git a/test/unit/InputFileResolverSpec.ts b/test/unit/InputFileResolverSpec.ts index ef958379f5..77bfd3f8a5 100644 --- a/test/unit/InputFileResolverSpec.ts +++ b/test/unit/InputFileResolverSpec.ts @@ -4,6 +4,7 @@ import * as fileUtils from '../../src/utils/fileUtils'; import {InputFile} from '../../src/api/core'; import {expect} from 'chai'; import {normalize} from 'path'; +import log from '../helpers/log4jsMock'; describe('InputFileResolver', () => { let sandbox: sinon.SinonSandbox; @@ -92,7 +93,7 @@ describe('InputFileResolver', () => { }); it('should log a warning', () => { - expect(console.log).to.have.been.calledWith(`WARNING: Globbing expression "notExists" did not result in any files.`) + expect(log.warn).to.have.been.calledWith('Globbing expression "notExists" did not result in any files.'); }); }); diff --git a/test/unit/StrykerSpec.ts b/test/unit/StrykerSpec.ts index e29d0f1a66..b52fd76e0e 100644 --- a/test/unit/StrykerSpec.ts +++ b/test/unit/StrykerSpec.ts @@ -10,6 +10,7 @@ import * as inputFileResolver from '../../src/InputFileResolver'; import * as configReader from '../../src/ConfigReader'; import * as testRunnerOrchestrator from '../../src/TestRunnerOrchestrator'; import * as pluginLoader from '../../src/PluginLoader'; +import log from '../helpers/log4jsMock'; class FakeConfigWriter implements ConfigWriter { constructor() { } @@ -38,7 +39,6 @@ describe('Stryker', function () { }; sandbox.stub(configReader, 'default').returns(configReaderMock); sandbox.stub(pluginLoader, 'default').returns(pluginLoaderMock); - sandbox.stub(console, 'log'); }); function itShouldResultInARejection() { @@ -128,8 +128,7 @@ describe('Stryker', function () { }); it('should have logged the errors', () => { - expect(console.log).to.have.been.calledWith('ERROR: One or more tests errored in the initial test run:'); - expect(console.log).to.have.been.calledWith('\t', 'An error!'); + expect(log.error).to.have.been.calledWith('One or more tests errored in the initial test run:\n\tAn error!'); }); itShouldResultInARejection();