Merge pull request #393 from kulshekhar/logging

Logging

.github/ISSUE_TEMPLATE

@@ -8,6 +8,9 @@
 
 [describe the expected behavior here]
 
+- Output from your debug log
+[ You can activate the debug logger by setting the environment variable TS_JEST_DEBUG="true" before running yarn test. The output of the logger
+will be in **<your_project_dir>/node_modules/ts-jest/debug.txt** ]
 
 
 - Link to a minimal repo that reproduces this issue

package.json

@@ -1,13 +1,13 @@
 {
   "name": "ts-jest",
-  "version": "22.0.1",
+  "version": "22.0.2",
   "main": "index.js",
   "types": "./dist/index.d.ts",
   "description": "A preprocessor with sourcemap support to help use Typescript with Jest",
   "scripts": {
     "build": "cpx index.d.ts dist/ && tsc -p .",
     "build:watch": "cpx index.d.ts dist/ && tsc -p . -w",
-    "clean": "rimraf dist/**/* && rimraf tests/simple/coverage && rimraf tests/simple-async/coverage",
+    "clean": "rimraf dist/**/* && rimraf tests/simple/coverage && rimraf tests/simple-async/coverage && rimraf tests/**/*/debug.txt",
     "clean-build": "npm run clean && npm run build",
     "pretest": "npm run tslint && npm run clean-build",
     "test": "node scripts/tests.js",

scripts/tests.js

@@ -67,14 +67,6 @@ createIntegrationMock();
 
 const argv = process.argv.slice(2);
 argv.push('--no-cache');
-// Watch unless on CI
-if (!process.env.CI) {
-  // argv.push('--watch');
-}
-// omit tests for watch cases if it runned on AppVeyor due to this issues:
-// https://github.com/kulshekhar/ts-jest/issues/53
-// http://help.appveyor.com/discussions/problems/5500-nodejs-child-process-with-watch-and-stderr-problem
-
 argv.push('--testPathPattern', '^(?!(.*watch.spec.ts$)).*');
 
 jest.run(argv);

src/logger.ts

@@ -0,0 +1,49 @@
+import * as fs from 'fs';
+import * as path from 'path';
+
+/**
+ * Logger file that enables logging things just once. Does this by traversing the array of previously recorded
+ * logs to see if the exact same message has already been logged
+ * @type {any[]}
+ */
+
+const logs: any[] = [];
+let logsFlushed: boolean = false;
+
+function shouldLog(): boolean {
+  // If the env variable is set and the logs have not already been flushed, log the line
+  return process.env.TS_JEST_DEBUG && !logsFlushed;
+}
+
+// Log function. Only logs prior to calls to flushLogs.
+export function logOnce(...thingsToLog: any[]) {
+  if (!shouldLog()) {
+    return;
+  }
+  logs.push(thingsToLog);
+}
+
+// This function JSONifies logs and flushes them to disk.
+export function flushLogs() {
+  if (!shouldLog()) {
+    return; // only output stuff for the first invocation and if logging is enabled.
+  }
+  logsFlushed = true;
+  const rootPath = path.resolve(__dirname, '../');
+  const JSONifiedLogs = logs.map(convertToJSONIfPossible);
+  const logString = JSONifiedLogs.join('\n');
+  const filePath = path.resolve(rootPath, 'debug.txt');
+  fs.writeFileSync(filePath, logString);
+}
+
+function includes<T>(array: T[], subject: T) {
+  return array.indexOf(subject) !== -1;
+}
+
+function convertToJSONIfPossible(object: any): string {
+  try {
+    return JSON.stringify(object, null, 2);
+  } catch {
+    return object.toString(); // if unable to parse, simply return the string variant
+  }
+}

src/postprocess.ts

@@ -14,6 +14,7 @@ import {
   TransformOptions,
   TsJestConfig,
 } from './jest-types';
+import { logOnce } from './logger';
 
 function createBabelTransformer(options: BabelTransformOptions) {
   options = {
@@ -62,19 +63,26 @@ export const getPostProcessHook = (
   tsJestConfig: TsJestConfig,
 ): PostProcessHook => {
   if (tsJestConfig.skipBabel) {
+    logOnce('Not using any postprocess hook.');
     return src => src; // Identity function
   }
 
-  const plugins = Array.from(tsJestConfig.babelConfig && tsJestConfig.babelConfig.plugins || []);
+  const plugins = Array.from(
+    (tsJestConfig.babelConfig && tsJestConfig.babelConfig.plugins) || [],
+  );
   // If we're not skipping babel
   if (tsCompilerOptions.allowSyntheticDefaultImports) {
     plugins.push('transform-es2015-modules-commonjs');
   }
 
-  return createBabelTransformer({
+  const babelOptions = {
     ...tsJestConfig.babelConfig,
     babelrc: tsJestConfig.useBabelrc || false,
     plugins,
     presets: tsJestConfig.babelConfig ? tsJestConfig.babelConfig.presets : [],
-  });
+  };
+
+  logOnce('Using babel with options:', babelOptions);
+
+  return createBabelTransformer(babelOptions);
 };

src/preprocessor.ts

@@ -1,6 +1,7 @@
 import * as crypto from 'crypto';
 import * as tsc from 'typescript';
 import { JestConfig, Path, TransformOptions } from './jest-types';
+import { flushLogs, logOnce } from './logger';
 import { getPostProcessHook } from './postprocess';
 import {
   cacheFile,
@@ -22,6 +23,8 @@ export function process(
     transformOptions.instrument,
   );
 
+  logOnce('final compilerOptions:', compilerOptions);
+
   const isTsFile = /\.tsx?$/.test(filePath);
   const isJsFile = /\.jsx?$/.test(filePath);
   const isHtmlFile = /\.html$/.test(filePath);
@@ -44,6 +47,7 @@ export function process(
   });
 
   const tsJestConfig = getTSJestConfig(jestConfig.globals);
+  logOnce('tsJestConfig: ', tsJestConfig);
 
   const postHook = getPostProcessHook(
     compilerOptions,
@@ -63,7 +67,7 @@ export function process(
     tsTranspiled.outputText,
     outputText,
   );
-
+  flushLogs();
   return modified;
 }
 

src/utils.ts

@@ -4,6 +4,7 @@ import * as fsExtra from 'fs-extra';
 import * as path from 'path';
 import * as tsc from 'typescript';
 import { JestConfig, TsJestConfig } from './jest-types';
+import { logOnce } from './logger';
 
 export function getTSJestConfig(globals: any): TsJestConfig {
   return globals && globals['ts-jest'] ? globals['ts-jest'] : {};
@@ -119,6 +120,7 @@ const tsConfigCache: { [key: string]: any } = {};
 // https://github.com/facebook/jest/issues/3524
 export function getTSConfig(globals, collectCoverage: boolean = false) {
   let configPath = getTSConfigPathFromConfig(globals);
+  logOnce(`Reading tsconfig file from path ${configPath}`);
   const skipBabel = getTSJestConfig(globals).skipBabel;
 
   // check cache before resolving configuration
@@ -134,6 +136,7 @@ export function getTSConfig(globals, collectCoverage: boolean = false) {
   }
 
   const config = readCompilerOptions(configPath);
+  logOnce('Original typescript config before modifications: ', config);
 
   // ts-jest will map lines numbers properly if inlineSourceMap and
   // inlineSources are set to true. For testing, we don't need the

tests/__helpers__/runJest.ts

@@ -11,7 +11,7 @@ const JEST_PATH = 'jest';
 // return the result of the spawned proccess:
 //  [ 'status', 'signal', 'output', 'pid', 'stdout', 'stderr',
 //    'envPairs', 'options', 'args', 'file' ]
-export default function runJest(dir: string, args: string[]) {
+export default function runJest(dir: string, args: string[], env = {}): Result {
   const isRelative = dir[0] !== '/';
 
   if (isRelative) {
@@ -30,10 +30,28 @@ export default function runJest(dir: string, args: string[]) {
 
   const result = spawnSync(JEST_PATH, args || [], {
     cwd: dir,
+    env: { ...process.env, ...env }, // Add both process.env which is the standard and custom env variables
   });
 
-  result.stdout = result.stdout && result.stdout.toString();
-  result.stderr = result.stderr && result.stderr.toString();
+  // Call to string on byte arrays and strip ansi color codes for more accurate string comparison.
+  result.stdout = result.stdout && stripAnsiColors(result.stdout.toString());
+  result.stderr = result.stderr && stripAnsiColors(result.stderr.toString());
+  result.output = result.output && stripAnsiColors(result.output.toString());
 
   return result;
 }
+
+// from https://stackoverflow.com/questions/25245716/remove-all-ansi-colors-styles-from-strings
+function stripAnsiColors(stringToStrip: String): String {
+  return stringToStrip.replace(
+    /[\u001b\u009b][[()#;?]*(?:[0-9]{1,4}(?:;[0-9]{0,4})*)?[0-9A-ORZcf-nqry=><]/g,
+    '',
+  );
+}
+
+export interface Result {
+  stdout: string;
+  stderr: string;
+  status: number;
+  output: string;
+}

tests/__helpers__/utils.ts

@@ -31,7 +31,7 @@ export function linkJestPackage(packageName, cwd) {
 }
 
 export function fileExists(filePath) {
-  const F_OK = (fs.constants && fs.constants.F_OK) || (<number>fs['F_OK']);
+  const F_OK = (fs.constants && fs.constants.F_OK) || <number>fs['F_OK'];
   try {
     fs.accessSync(filePath, F_OK);
     return true;

tests/__tests__/babel-config.spec.ts

@@ -8,7 +8,7 @@ describe('babelConfig flag', () => {
 
   it('should fail for invalid babel configs', () => {
     const result = runJest('../babel-config-invalid', ['--no-cache', '-u']);
-    const stderr = result.stderr.toString();
+    const stderr = result.stderr;
     expect(result.status).toBe(1);
     expect(stderr).toContain('ReferenceError: [BABEL]');
     expect(stderr).toContain(
@@ -29,7 +29,7 @@ describe('babelConfig flag', () => {
       '--no-cache',
       '-u',
     ]);
-    const stderr = result.stderr.toString();
+    const stderr = result.stderr;
     expect(result.status).toBe(1);
     expect(stderr).toContain(`Couldn't find preset "nonexistent"`);
   });

tests/__tests__/babelrc.spec.ts

@@ -3,7 +3,7 @@ import runJest from '../__helpers__/runJest';
 describe('babelrc flag', () => {
   it('should crash on invalid babelrc', () => {
     const result = runJest('../use-babelrc', ['--no-cache', '-u']);
-    const stderr = result.stderr.toString();
+    const stderr = result.stderr;
     expect(result.status).toBe(1);
     expect(stderr).toContain('ReferenceError: [BABEL]');
     expect(stderr).toContain(

tests/__tests__/debug.spec.ts

@@ -0,0 +1,29 @@
+import * as fs from 'fs-extra';
+import * as path from 'path';
+import runJest from '../__helpers__/runJest';
+
+const debugFilePath = path.resolve(
+  __dirname,
+  '../simple/node_modules/ts-jest/debug.txt',
+);
+
+describe('Debug output', () => {
+  beforeEach(async () => {
+    return fs.remove(debugFilePath);
+  });
+
+  it('should create a debug file with the correct output if the flag is set', async () => {
+    runJest('../simple', ['--no-cache', '-u'], {
+      TS_JEST_DEBUG: 'true',
+    });
+    const logFile = await fs.readFile(debugFilePath, 'utf-8');
+
+    expect(logFile).not.toBeNull();
+  });
+
+  it('Should not create a file if the debug flag is not set', async () => {
+    runJest('../simple', ['--no-cache', '-u']);
+    expect.assertions(1); // To make sure we actually do assert the promise on the line below
+    await expect(fs.readFile(debugFilePath, 'utf-8')).rejects.toThrow();
+  });
+});

tests/__tests__/import.spec.ts

@@ -4,11 +4,10 @@ describe('import with relative and absolute paths', () => {
   it('should run successfully', () => {
     const result = runJest('../imports-test', ['--no-cache']);
 
-    const stderr = result.stderr.toString();
-    const output = result.output.toString();
+    const stderr = result.stderr;
 
     expect(result.status).toBe(1);
-    expect(output).toContain('4 failed, 4 total');
+    expect(stderr).toContain('4 failed, 4 total');
 
     expect(stderr).toContain('Hello.ts:11:11)');
 

tests/__tests__/jest-hoist.spec.ts

@@ -3,7 +3,7 @@ import runJest from '../__helpers__/runJest';
 describe('Jest.mock() calls', () => {
   it('Should run all tests using jest.mock() underneath the imports succesfully.', () => {
     const result = runJest('../hoist-test', ['--no-cache']);
-    const output = result.output.toString();
+    const output = result.output;
 
     expect(output).toContain('4 passed, 4 total');
     expect(result.status).toBe(0);
@@ -12,7 +12,7 @@ describe('Jest.mock() calls', () => {
   it('Should retain proper line endings while hoisting', () => {
     const result = runJest('../hoist-errors', ['--no-cache']);
 
-    const stderr = result.stderr.toString();
+    const stderr = result.stderr;
 
     expect(result.status).toBe(1);
     expect(stderr).toContain('Hello.ts:22:11');