Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Difficulty debugging errors, stack traces missing and/or poor formatting #3296

Closed
trusktr opened this issue Apr 9, 2019 · 15 comments · Fixed by #3298 or karronoli/redpen#10 · May be fixed by Omrisnyk/npm-lockfiles#201
Closed

Difficulty debugging errors, stack traces missing and/or poor formatting #3296

trusktr opened this issue Apr 9, 2019 · 15 comments · Fixed by #3298 or karronoli/redpen#10 · May be fixed by Omrisnyk/npm-lockfiles#201

Comments

@trusktr
Copy link

trusktr commented Apr 9, 2019

Expected behaviour

I'm hoping to see full stack traces, to aid in debugging.

Actual behaviour

I see output like the following, which is making it difficult to debug:

output:
08 04 2019 20:37:40.725:INFO [karma]: Karma v2.0.5 server started at http://0.0.0.0:9876/
08 04 2019 20:37:40.728:INFO [launcher]: Launching browser CustomElectron with unlimited concurrency
08 04 2019 20:37:40.734:INFO [launcher]: Starting browser Electron
08 04 2019 20:37:41.312:INFO [Electron 2.0.18 (Node 8.9.3)]: Connected on socket UeP2147YwI328f5pAAAA with id 20256050
Electron 2.0.18 (Node 8.9.3) ERROR LOG: 'DEPRECATION:', 'Setting specFilter directly on Env is deprecated, please use the specFilter option in `configure`'
Electron 2.0.18 (Node 8.9.3) ERROR
  {
    "message": "Uncaught TypeError: Cannot read property 'default' of undefined\nat /Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:98:129\n\nundefined",
    "str": "Uncaught TypeError: Cannot read property 'default' of undefined\nat /Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:98:129\n\nundefined"
  }

Electron 2.0.18 (Node 8.9.3): Executed 0 of 0 ERROR (0.81 secs / 0 secs)

As you can see, the only hint is line 98, which doesn't match the original source because that line seems to be relative to transpiled code. Plus, without the stack trace it is hard to imagine what is happening.

My karma config looks like the following:

karma.config.js:
const CWD = process.cwd()
const glob = require('globby')
const fs = require('fs')
const mkdirp = require('mkdirp') // mkdir -p
const rmrf = require('rimraf') // rm -rf
const r = require('regexr').default

const testFiles = glob.sync([
    CWD+'/src/**/*.test.js',
    CWD+'/tests/**/*.js',
])

const config = fs.existsSync(CWD+'/builder.config.js') ? require(CWD+'/builder.config.js') : {}

rmrf.sync( CWD + '/.karma-test-build' )

testFiles.forEach(file => {
    const relativeFile = file.replace(CWD, '')
    const relativePath = dirname(relativeFile)

    mkdirp.sync( CWD + '/.karma-test-build' + relativePath )

    const nodeModulesToCompile = config.nodeModulesToCompile

    fs.writeFileSync( CWD + '/.karma-test-build' + relativeFile, `
        // NOTE, we don't use babel.config.js settings here, we can target a
        // more modern environment.
        require('@babel/register')({
            presets: [ ['@babel/preset-env', { targets: { node: 9 } }] ],
            plugins: [
                // We need to transpile the not-yet-official re-export syntax.
                '@babel/plugin-proposal-export-namespace-from',
                '@babel/plugin-proposal-export-default-from',
            ],
            sourceMap: 'inline',
            ${config.nodeModulesToCompile ? `
                ignore: [
                    // don't compile node_modules except for ones specified in the config
                    ${nodeModulesToCompile.map(moduleName => {
                        return r`/node_modules(?!\/${r.escape(moduleName)}\/)/`
                    })}
                ],
            ` : ''}
        })

        require( '${ file }' )
    ` )
})

const debugMode = false
// const debugMode = true

module.exports = function(config) {

    config.set({

        frameworks: ['jasmine', 'stacktrace'],
        reporters: ['spec'],
        port: 9876,  // karma web server port
        colors: true,
        logLevel: config.LOG_INFO,
        autoWatch: false,
        singleRun: debugMode ? false : true,
        concurrency: Infinity,

        basePath: CWD,

        // Set up a "CustomElectron" launcher that extends karma-electron's
        // default "Electron" launcher, so that we can control options
        // (docs: // https://github.com/twolfson/karma-electron/tree/5.1.1#launcher-configuration)
        browsers: ['CustomElectron'],
        customLaunchers: {
            CustomElectron: {
                base: 'Electron',
                
                flags: debugMode ? [
                    // If in debug mode, this makes the electron window visible
                    // so that we can step through tests using devtools
                    '--show'
                    
                    // Alternatively to the --show option, we can use this
                    // option, then open chrome://inspect in Google Chrome and
                    // inspect from there.
                    // '--remote-debugging-port=9222',
                ] : [],
            }
        },
        
        files: [
            '.karma-test-build/**/*.js',
        ],
        preprocessors: {
            '.karma-test-build/**/*.js': ['electron'],
        },
        client: {
            // otherwise "require is not defined"
            useIframe: false,
            loadScriptsViaRequire: true,
        },

    })

}

function dirname(fullname) {
    if (typeof fullname !== 'string') throw new TypeError('expected a string')
    const parts = fullname.split('/')
    parts.pop()
    return parts.join('/')
}

Any ideas why the error output is so limited, or on how to make it show full stack traces? Maybe it isn't a karma problem, but a problem with a karma plugin? Thanks for any insight!

Environment Details

  • Karma version (output of karma --version): 2.0.5
  • Relevant part of your karma.config.js file: see above

Steps to reproduce the behaviour

git clone https://github.com/trusktr/infamous.git
cd infamous
npm install
npm test

Note, npm test ultimately runs the script in node_modules/builder-js-package/scripts/run-karma-tests.sh:

run-karma-tests.sh:
xvfb-maybe \
	karma start ./node_modules/builder-js-package/config/karma.config.js
RESULT=$?

# remove the temporary folder
rm -rf ./.karma-test-build

exit $RESULT

So, another way in which you can run the tests directly is:

./node_modules/.bin/karma start ./node_modules/builder-js-package/config/karma.config.js
@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

Oddly, I don't get this error when I run the code with the window visible. To run it in that mode,

  1. toggle the variable debugMode to true in karma.config.js,
  2. then run the tests again.

There doesn't seem to be any error in that case.

Why might this be?

@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

To see karma plugins and versions, look inside of node_modules/builder-js-package/package.json.

@johnjbarton
Copy link
Contributor

The reporter is suppose to format the errors, your reporter is 'spec' (IDK what it is).

@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

spec is karma-spec-reporter. I tried disabling that line, but I still see:

09 04 2019 14:29:56.492:INFO [karma]: Karma v2.0.5 server started at http://0.0.0.0:9876/
09 04 2019 14:29:56.497:INFO [launcher]: Launching browser CustomElectron with unlimited concurrency
09 04 2019 14:29:56.504:INFO [launcher]: Starting browser Electron
09 04 2019 14:29:57.452:INFO [Electron 2.0.18 (Node 8.9.3)]: Connected on socket _P6ZRmW3AEDvvwh2AAAA with id 77559288
Electron 2.0.18 (Node 8.9.3) ERROR: 'DEPRECATION:', 'Setting specFilter directly on Env is deprecated, please use the specFilter option in `configure`'

Electron 2.0.18 (Node 8.9.3) ERROR
  {
    "message": "Uncaught TypeError: Cannot read property 'default' of undefined\nat /Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:98:129\n\nundefined",
    "str": "Uncaught TypeError: Cannot read property 'default' of undefined\nat /Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:98:129\n\nundefined"
  }

@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

I updated to latest Karma, 4.0.1, and still see the same error (reporters option commented out). Hmmmmn 🤔

@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

Aha! Those errors are being thrown from the require() calls in the above @babel/register portion of my karma config. So I changed that part to use a try catch, and log the error, and I then can see the full stack trace:

testFiles.forEach(file => {
    const relativeFile = file.replace(CWD, '')
    const relativePath = dirname(relativeFile)

    mkdirp.sync( CWD + '/.karma-test-build' + relativePath )

    const nodeModulesToCompile = config.nodeModulesToCompile

    fs.writeFileSync( CWD + '/.karma-test-build' + relativeFile, `
        // NOTE, we don't use babel.config.js settings here, we can target a
        // more modern environment.
        require('@babel/register')({
            presets: [ ['@babel/preset-env', { targets: { node: 9 } }] ],
            plugins: [
                // We need to transpile the not-yet-official re-export syntax.
                '@babel/plugin-proposal-export-namespace-from',
                '@babel/plugin-proposal-export-default-from',
            ],
            sourceMap: 'inline',
            ${config.nodeModulesToCompile ? `
                ignore: [
                    // don't compile node_modules except for ones specified in the config
                    ${nodeModulesToCompile.map(moduleName => {
                        return r`/node_modules(?!\/${r.escape(moduleName)}\/)/`
                    })}
                ],
            ` : ''}
        })

        // RIGHT HERE, LOG THE ERROR ----------------------------
        try {
            require( '${ file }' )
        } catch(e) {
            console.error(e)
            throw e
        }
    ` )
})

Now I can see the following in terminal:

Electron 2.0.18 (Node 8.9.3) LOG: TypeError: Cannot read property 'default' of undefined
TypeError: Cannot read property 'default' of undefined
    at exports.default.Base (/Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:100:129)
    at /Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:54:36
    at /Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:64:17
    at /Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:132:17
    at /Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:44:12
    at ApplyDefault (/Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:119:22)
    at Mixin (/Users/trusktr/src/trusktr+infamous/node_modules/lowclass/Mixin.js:37:13)
    at initImperativeBase (/Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:100:58)
    at getImperativeBaseProtectedHelper (/Users/trusktr/src/trusktr+infamous/src/core/ImperativeBase.js:62:3)
    at Object.<anonymous> (/Users/trusktr/src/trusktr+infamous/src/core/Motor.js:15:86)

which is much more helpful.

So my question is, if I don't catch the error, then which part of the stack is deciding to output such limit ed information regarding the error?

@trusktr
Copy link
Author

trusktr commented Apr 9, 2019

Not sure if it's a karma problem, or a karma-electron problem, so I posted there too: twolfson/karma-electron#35 (cc @twolfson)

@johnjbarton
Copy link
Contributor

Electron 2.0.18 (Node 8.9.3) ERROR

As you can see the error is coming from inside of Electron.
Adding console.log() calls fails to result in log messages.
Adding syntax error at the top level of ImperativeBase.js results in an error like the one you see.

So the error is not happening during karma's config loading. Rather the config is creating some code that is executed in Electron and that code fails a the 'top' level.

The top level fail is calling the error handler here:
https://github.com/karma-runner/karma/blob/master/client/karma.js#L146
That is confirmed by the object with message and str properties.

This error handler conforms to
https://developer.mozilla.org/en-US/docs/Web/API/GlobalEventHandlers/onerror#window.onerror
My guess is that Electron is not passing the extended arguments, so the handler does not see error.stack. Since console logging does not work I can't be for sure, but I doubt there is any thing we can do from this side.

@trusktr
Copy link
Author

trusktr commented Apr 12, 2019

@johnjbarton Upon further investigation, it doesn't seem like a karma-electron issue:

I disabled karma-electron, and spec runner, and added karma-chrome-launcher and using progress reporter:

karma.config.js
const CWD = process.cwd()

module.exports = function(config) {

    config.set({

        frameworks: ['jasmine', 'stacktrace'],
        reporters: ['progress'],
        port: 9876,  // karma web server port
        colors: true,
        logLevel: config.LOG_INFO,
        autoWatch: false,
        singleRun: true,
        concurrency: Infinity,

        basePath: CWD,
        browsers: ['ChromeHeadless'],
        
        files: [
            'tests/**/*.js',
        ],

    })

}

For the following simple test file,

`test/test.js`
console.log( 'test.js' )

throw new Error('test error')

describe('Tests...', () => {
    it('needs to be implemented', () => {
        expect(true).toBe(true)
    })
})

the error output is in the same format, but they are now tagged with HeadlessChrome instead of Electron:

error output:
11 04 2019 18:46:11.820:INFO [karma-server]: Karma v4.0.1 server started at http://0.0.0.0:9876/
11 04 2019 18:46:11.823:INFO [launcher]: Launching browsers ChromeHeadless with concurrency unlimited
11 04 2019 18:46:11.827:INFO [launcher]: Starting browser ChromeHeadless
11 04 2019 18:46:12.241:INFO [HeadlessChrome 73.0.3683 (Mac OS X 10.14.3)]: Connected on socket VXtUqTsgs--lUMODAAAA with id 18081349
HeadlessChrome 73.0.3683 (Mac OS X 10.14.3) ERROR: 'DEPRECATION:', 'Setting specFilter directly on Env is deprecated, please use the specFilter opt
ion in `configure`'

HeadlessChrome 73.0.3683 (Mac OS X 10.14.3) LOG: 'test.js'

HeadlessChrome 73.0.3683 (Mac OS X 10.14.3) ERROR
  {
    "message": "An error was thrown in afterAll\nError: test error\n    at tests/test.js:3:7",
    "str": "An error was thrown in afterAll\nError: test error\n    at tests/test.js:3:7"
  }
HeadlessChrome 73.0.3683 (Mac OS X 10.14.3): Executed 0 of 0 ERROR (0.003 secs / 0 secs)

Longer errors can be even worse:

long error
HeadlessChrome 73.0.3683 (Mac OS X 10.14.3) ERROR
  {
    "message": "An error was thrown in afterAll\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\
nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError:
Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected iden
tifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntax
Error: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpec

ted identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier
\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxErro
r: Unexpected token {\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected
 identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSynt
axError: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexpected string\nSyntaxError: Unexpected strin
g\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexp
ected identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexpected string\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token export
\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxEr
ror: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpecte
d identifier\nSyntaxError: Unexpected token *\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token *\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token *",
    "str": "An error was thrown in afterAll\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyn
taxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unex
pected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifi
er\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxErro
r: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected
identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSy
ntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: U
nexpected token {\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected ide
ntifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxEr
ror: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexpected string\nSyntaxError: Unexpected string\nS
yntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token {\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexpecte
d identifier\nSyntaxError: Unexpected string\nSyntaxError: Unexpected string\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token export\nSy
ntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError:
 Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected identifier\nSyntaxError: Unexpected id
entifier\nSyntaxError: Unexpected token *\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token *\nSyntaxError: Unexpected token export\nSyntaxError: Unexpected token *"
  }

I made a reproduction:

git clone [email protected]:trusktr/infamous
cd infamous
git checkout karma-issue-3296
npm install
npm test
# or
./node_modules/.bin/karma start ./node_modules/builder-js-package/config/karma.config.js

I also tried it without karma-chrome-launcher, in which case I opened my browser to the localhost URL, and it gave me the same error formatting.

It seems like the errors are being formatted that way by Karma. Or could it be Jasmine or stacktrace? Let me try mocha/chai...

@trusktr
Copy link
Author

trusktr commented Apr 12, 2019

I disabled stacktrace and that had no effect. Then I replaced jasmine with mocha and chai, but still no luck; the errors are in the same format.

@trusktr
Copy link
Author

trusktr commented Apr 12, 2019

So, it seems in that small example the stack traces aren't missing, but as you see from my previous long error output, the stack traces were missing in that case. Is there something in Karma that isn't outputting regular-format errors?

Seems like whatever is handling the error should just log the error directly, or log e.stack.

@trusktr trusktr changed the title Difficulty debugging errors, stack traces missing. Difficulty debugging errors, stack traces missing and/or poor formatting Apr 12, 2019
@trusktr
Copy link
Author

trusktr commented Apr 12, 2019

Strange: I am able to pause on the uncaught exceptions in devtools, so it seems that nothing is catching the errors. However, despite the errors not being caught, they do not show up in the console.

@trusktr
Copy link
Author

trusktr commented Apr 13, 2019

I re-worded my previous comment; after reading it a second time, I couldn't even understand it myself.

Basically I was saying that I can't see these errors in devtools console like we normally do with uncaught errors. The only way to see them is by turning on the "Pause on exceptions" option.

@johnjbarton
Copy link
Contributor

My PR #3298 will make the error less mysterious but it may still have the line number of the transpile output, depending upon your sourcemap setup.

@johnjbarton
Copy link
Contributor

Please try the new release.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants