feat: adds logging + better hashing

.github/ISSUE_TEMPLATE.md

@@ -7,9 +7,9 @@ https://github.com/kulshekhar/ts-jest/wiki/Troubleshooting -->
 ## Expected behavior <!-- describe the expected behavior below -->:
 
 
-## Output from 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**, paste it below -->:
+## Output from debug log <!-- You can activate the debug logger by setting the environment variable TS_JEST_DEBUG="true" before running tests. The output of the logger will be in **ts-jest-debug.log**, paste it below -->:
 ```bash
-# content of debug.txt :
+# content of ts-jest-debug.log :
 
 ```
 

e2e/__helpers__/test-case/RunResult.ts

@@ -1,6 +1,10 @@
 import { SpawnSyncReturns } from 'child_process'
 import ProcessedFileIo from './ProcessedFileIo'
-import { stripAnsiColors, normalizeJestOutput } from './utils'
+import { stripAnsiColors, normalizeJestOutput, escapeRegex } from './utils'
+import { resolve } from 'path'
+import { readFileSync, realpathSync } from 'fs'
+import { LOG_PREFIX } from '../../../src/util/debug'
+import { tmpdir } from 'os'
 
 // tslint:disable-next-line:no-default-export
 export default class RunResult {
@@ -14,6 +18,14 @@ export default class RunResult {
       env: { [key: string]: string },
     }>,
   ) { }
+  get logFilePath() { return resolve(this.cwd, 'ts-jest-debug.log') }
+  get logFileContent() { return readFileSync(this.logFilePath).toString('utf8') }
+  get normalizedLogFileContent() {
+    const prefix = ` ${LOG_PREFIX} `
+    return this.normalize(this.logFileContent.split(/\n/g).map(s => {
+      return s.split(prefix).slice(1).join(prefix)
+    }).join('\n'))
+  }
   get isPass() { return this.status === 0 }
   get isFail() { return !this.isPass }
   get status() { return this.result.status }
@@ -25,11 +37,27 @@ export default class RunResult {
   get cmdLine() {
     return [this.context.cmd, ...this.context.args].join(' ')
   }
+
   ioFor(relFilePath: string): ProcessedFileIo {
     if (!this.context.ioDir) {
       throw new Error('IO not written for test, you must configure the test with `writeIo: true`.')
     }
     const io = require(`${this.context.ioDir}/${relFilePath}.json`)
     return new ProcessedFileIo(this.cwd, relFilePath, io.in, io.out)
   }
+
+  normalize(str: string) {
+    // TODO: hmmm clean this!
+    return [
+      { from: this.cwd, to: '<cwd>' },
+      { from: realpathSync(this.cwd), to: '<cwd>' },
+      { from: tmpdir(), to: '<tmp>' },
+      { from: realpathSync(tmpdir()), to: '<tmp>' },
+      { from: /\b[a-f0-9]{40}\b/g, to: '<hex:40>' },
+    ]
+      .sort((a, b) => ((b.from as any).length || 0) - ((a.from as any).length || 0))
+      .reduce((str, { from, to }) => {
+        return str.replace(typeof from === 'string' ? new RegExp(`${escapeRegex(from)}`, 'g') : from, to)
+      }, str)
+  }
 }

e2e/__helpers__/test-case/utils.ts

@@ -52,3 +52,7 @@ export function normalizeJestOutput(output: string): string {
   }
   return out
 }
+
+export function escapeRegex(s: string) {
+  return s.replace(/[-\/\\^$*+?.()|[\]{}]/g, '\\$&')
+}

e2e/__tests__/logger.test.ts

@@ -0,0 +1,28 @@
+import { configureTestCase } from '../__helpers__/test-case'
+import { PackageSets, allValidPackageSets } from '../__helpers__/templates'
+import { existsSync } from 'fs'
+
+describe('With unsupported version test', () => {
+  const testCase = configureTestCase('simple')
+
+  testCase.runWithTemplates([PackageSets.unsupportedVersion], 0, (runTest, { testLabel }) => {
+    it(testLabel, () => {
+      const result = runTest()
+      expect(result.status).toBe(0)
+      expect(result).toMatchSnapshot()
+    })
+  })
+})
+
+describe('TS_JEST_DEBUG', () => {
+  const testCase = configureTestCase('simple', { env: { TS_JEST_DEBUG: 'true' } })
+
+  testCase.runWithTemplates(allValidPackageSets, 0, (runTest, { templateName }) => {
+    it(`should pass and create log file when using tempalte "${templateName}"`, () => {
+      const result = runTest()
+      expect(result.status).toBe(0)
+      expect(existsSync(result.logFilePath))
+      expect(result.normalizedLogFileContent).toMatchSnapshot()
+    })
+  })
+})

package.json

@@ -81,7 +81,6 @@
     "lodash.merge": "^4.6.1",
     "lodash.set": "^4.3.2",
     "npm-run-all": "^4.1.3",
-    "outdent": "^0.5.0",
     "prettier": "^1.14.2",
     "reflect-metadata": "^0.1.12",
     "source-map": "^0.7.3",

src/compiler.spec.ts

@@ -81,13 +81,12 @@ describe('cache', () => {
 
   it('should use the cache', () => {
     const compiled1 = compiler.compile(source, __filename)
-    expect(logger).toHaveBeenCalledTimes(1)
-    expect(logger).toHaveBeenCalledWith(
-      'log',
-      'ts-jest:',
+    expect(logger.mock.calls.map(callArgs => callArgs[2])).toEqual([
       'readThrough:cache-miss',
-      __filename,
-    )
+      'compiler#getOutput',
+      'customTranformer#hoisting',
+      'readThrough:write-caches',
+    ])
 
     logger.mockClear()
     const compiled2 = compiler.compile(source, __filename)

src/compiler.ts

@@ -41,10 +41,18 @@ import { TsCompiler, MemoryCache, TypeInfo } from './types'
 import { Errors, interpolate } from './util/messages'
 import { factory as customTransformersFactory } from './transformers'
 
+const hasOwn = Object.prototype.hasOwnProperty
+
 /**
  * Register TypeScript compiler.
  */
 export function createCompiler(configs: ConfigSet): TsCompiler {
+  debug(
+    'createCompiler',
+    configs.tsJest.typeCheck ? 'with' : 'without',
+    'type-checking, config:',
+    configs.toJSON(),
+  )
   const cachedir = configs.tsCacheDir
 
   const memoryCache: MemoryCache = {
@@ -90,6 +98,7 @@ export function createCompiler(configs: ConfigSet): TsCompiler {
     fileName: string,
     lineOffset = 0,
   ): SourceOutput => {
+    debug(`compiler#getOutput`, 'compiling as isolated module')
     const result = ts.transpileModule(code, {
       fileName,
       transformers,
@@ -120,6 +129,7 @@ export function createCompiler(configs: ConfigSet): TsCompiler {
   if (configs.tsJest.typeCheck) {
     // Set the file contents into cache.
     const updateMemoryCache = (code: string, fileName: string) => {
+      debug(`compiler#updateMemoryCache`, fileName)
       if (memoryCache.contents[fileName] !== code) {
         memoryCache.contents[fileName] = code
         memoryCache.versions[fileName] =
@@ -143,10 +153,10 @@ export function createCompiler(configs: ConfigSet): TsCompiler {
           : String(version)
       },
       getScriptSnapshot(fileName: string) {
-        // Read contents into TypeScript memory cache.
-        if (
-          !Object.prototype.hasOwnProperty.call(memoryCache.contents, fileName)
-        ) {
+        const hit = hasOwn.call(memoryCache.contents, fileName)
+        debug(`compiler#getScriptSnapshot`, 'cache', hit ? 'hit' : 'miss')
+        // Read contents from TypeScript memory cache.
+        if (!hit) {
           memoryCache.contents[fileName] = ts.sys.readFile(fileName)
         }
 
@@ -168,15 +178,18 @@ export function createCompiler(configs: ConfigSet): TsCompiler {
       getCustomTransformers: () => transformers,
     }
 
+    debug(`createCompiler`, 'creating language service')
     const service = ts.createLanguageService(serviceHost)
 
     getOutput = (code: string, fileName: string, lineOffset: number = 0) => {
+      debug(`compiler#getOutput`, 'compiling using language service', fileName)
       // Must set memory cache before attempting to read file.
       updateMemoryCache(code, fileName)
 
       const output = service.getEmitOutput(fileName)
 
       if (configs.shouldReportDiagnostic(fileName)) {
+        debug(`compiler#getOutput`, 'computing diagnostics', fileName)
         // Get the relevant diagnostics - this is 3x faster than `getPreEmitDiagnostics`.
         const diagnostics = service
           .getCompilerOptionsDiagnostics()
@@ -280,6 +293,7 @@ function readThrough(
     const [value, sourceMap] = compile(code, fileName, lineOffset)
     const output = updateOutput(value, fileName, sourceMap, getExtension, cwd)
 
+    debug('readThrough:write-caches', fileName, 'cache file', outputPath)
     memoryCache.outputs[fileName] = output
     writeFileSync(outputPath, output)
 

src/config/config-set.ts

@@ -414,6 +414,10 @@ export class ConfigSet {
     return this.jest.cwd || process.cwd()
   }
 
+  get isDoctoring() {
+    return !!process.env.TS_JEST_DOCTOR
+  }
+
   readTsConfig(
     compilerOptions?: object,
     project?: string | null,
@@ -503,9 +507,18 @@ export class ConfigSet {
 
   @Memoize()
   get jsonValue() {
+    const jest = { ...this.jest }
+    const globals = (jest.globals = { ...jest.globals } as any)
+    // we need to remove some stuff from jest config
+    // this which does not depend on config
+    delete jest.name
+    delete jest.cacheDirectory
+    // we do not need this since its normalized version is in tsJest
+    delete globals['ts-jest']
+
     return new JsonableValue({
       version: myVersion,
-      jest: this.jest,
+      jest,
       tsJest: this.tsJest,
       babel: this.babel,
       tsconfig: this.tsconfig,
@@ -515,4 +528,8 @@ export class ConfigSet {
   get cacheKey(): string {
     return this.jsonValue.serialized
   }
+
+  toJSON() {
+    return this.jsonValue.value
+  }
 }

src/transformers/hoisting.ts

@@ -11,6 +11,7 @@ import {
   Transformer,
 } from 'typescript'
 import { ConfigSet } from '../config/config-set'
+import { wrapWithDebug } from '../util/debug'
 
 /**
  * What methods of `jest` should we hoist
@@ -121,6 +122,9 @@ export function factory(cs: ConfigSet) {
 
   // returns the transformer factory
   return (ctx: TransformationContext): Transformer<SourceFile> => {
-    return (sf: SourceFile) => ts.visitNode(sf, createVisitor(ctx, sf))
+    return wrapWithDebug(
+      (sf: SourceFile) => ['customTranformer#hoisting', sf.fileName],
+      (sf: SourceFile) => ts.visitNode(sf, createVisitor(ctx, sf)),
+    )
   }
 }

src/ts-jest-transformer.ts

@@ -4,6 +4,7 @@ import { JsonableValue } from './util/jsonable-value'
 import { ConfigSet } from './config/config-set'
 import { stringify, parse } from './util/json'
 import { inspect } from 'util'
+import { debug } from './util/debug'
 
 /**
  * @internal
@@ -32,6 +33,7 @@ export class TsJestTransformer implements jest.Transformer {
   constructor(baseOptions: TsJestGlobalOptions = {}) {
     this.options = { ...baseOptions }
     this.id = TsJestTransformer._nextTransformerId
+    debug('created new transformer', this)
   }
 
   [INSPECT_CUSTOM]() {