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

could not capture stack trace for span #588

Closed
Davidiusdadi opened this issue Sep 21, 2018 · 6 comments
Closed

could not capture stack trace for span #588

Davidiusdadi opened this issue Sep 21, 2018 · 6 comments

Comments

@Davidiusdadi
Copy link

This is likely not a bug - rather i am probbably missing something:

APM is working except that my spans don't have any stacktraces.
In my node app i get messages like this for every single span:

could not capture stack trace for span { id: 'ff6000a5-eea6-4025-9ee4-5d0367d55ed2',
  name: 'HGET',
  type: 'cache.redis',
  err: 'Could not process callsites' }

So far i stopped using import 'source-map-support/register' to not alter prepareStackTrace as reccomended in https://discuss.elastic.co/t/node-agent-could-not-capture-stack-trace-for-span/130775. Doing this however did not help.

My node app uses typescript and webpack.
node: v8.9.4
webpack: 3.11.0
typscript: 3.0.1 and emits es2018 code.
babel is not used and i boostrap viaconst apm = require('elastic-apm-node').start() with env vars

Webpack emits my server.js along with server.js.map and the server.js correctly references the source map like //# sourceMappingURL=server.js.map like it said it needs to in https://www.elastic.co/guide/en/apm/agent/nodejs/current/source-maps.html and i never had issues with source maps during debugging.

Can you help me to get rid of the error messages and get the spans to work correctly?

@watson
Copy link
Member

watson commented Sep 21, 2018

Thanks for reporting.

Can I get you to search through all your dependencies (and sub-dependencies etc) for where prepareStackTrace is overridden? My best guess is that some other module is also overwriting this function besides Babel.

@Davidiusdadi
Copy link
Author

Thanks for the quick response.
I digged a little and found multiple places where prepareStackTrace is set:
I used the the following instumentation to find all places where prepareStackTrace is set.

const orginal = Error.prepareStackTrace
const overwrites = []
Object.defineProperty(Error, 'prepareStackTrace', {
    set: (v) => {
        overwrites.push(v)
        console.error()
        console.error('prepareStackTrace set at')
        console.trace()
        console.error()

    },
    get() {
        return overwrites[0] // igonre all but the first  assignment of prepareStackTrace
    }
})
const apm = require('elastic-apm-node').start()

With all that instumentation and environment variable DEBUG=stackman my app prints out:

env $(cat .env) node --inspect dist/server.js
Debugger listening on ws://127.0.0.1:9229/58335564-b548-42c8-8bd9-bc42281575d9
For help see https://nodejs.org/en/docs/inspector

prepareStackTrace set at
[object Object]
   at Function.set (/home/user/app/dist/server.js:14361:17)
   at Object.<anonymous> (/home/user/app/node_modules/error-callsites/index.js:6:25)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/stackman/index.js:7:22)


prepareStackTrace set at
[object Object]
   at Function.set (/home/user/app/dist/server.js:14361:17)
   at callSiteToString (/home/user/app/node_modules/depd/lib/compat/index.js:30:27)
   at Object.get [as callSiteToString] (/home/user/app/node_modules/depd/lib/compat/index.js:55:15)
   at Object.<anonymous> (/home/user/app/node_modules/depd/index.js:11:47)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/body-parser/index.js:14:17)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/lib/express.js:15:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/index.js:11:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/dist/server.js:1897:18)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at Object.<anonymous> (/home/user/app/dist/server.js:14369:35)
   at Object.mod.default (/home/user/app/dist/server.js:14533:30)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at /home/user/app/dist/server.js:63:18
   at Object.<anonymous> (/home/user/app/dist/server.js:66:10)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)


prepareStackTrace set at
[object Object]
   at Function.set (/home/user/app/dist/server.js:14361:17)
   at callSiteToString (/home/user/app/node_modules/depd/lib/compat/index.js:39:27)


prepareStackTrace set at
[object Object]
   at Function.set (/home/user/app/dist/server.js:14361:17)
   at getStack (/home/user/app/node_modules/depd/index.js:368:27)
   at depd (/home/user/app/node_modules/depd/index.js:111:15)
   at Object.<anonymous> (/home/user/app/node_modules/body-parser/index.js:14:32)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/lib/express.js:15:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/index.js:11:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/dist/server.js:1897:18)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at Object.<anonymous> (/home/user/app/dist/server.js:14369:35)
   at Object.mod.default (/home/user/app/dist/server.js:14533:30)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at /home/user/app/dist/server.js:63:18
   at Object.<anonymous> (/home/user/app/dist/server.js:66:10)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Function.Module.runMain (module.js:684:10)
   at startup (bootstrap_node.js:187:16)
   at bootstrap_node.js:608:3


prepareStackTrace set at
[object Object]
   at Function.set (/home/user/app/dist/server.js:14361:17)
   at getStack (/home/user/app/node_modules/depd/index.js:377:27)
   at depd (/home/user/app/node_modules/depd/index.js:111:15)
   at Object.<anonymous> (/home/user/app/node_modules/body-parser/index.js:14:32)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/lib/express.js:15:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/node_modules/express/index.js:11:18)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Module.require (module.js:587:17)
   at Module.Hook._require.Module.require (/home/user/app/node_modules/require-in-the-middle/index.js:60:37)
   at require (internal/module.js:11:18)
   at Object.<anonymous> (/home/user/app/dist/server.js:1897:18)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at Object.<anonymous> (/home/user/app/dist/server.js:14369:35)
   at Object.mod.default (/home/user/app/dist/server.js:14533:30)
   at __webpack_require__ (/home/user/app/dist/server.js:20:30)
   at /home/user/app/dist/server.js:63:18
   at Object.<anonymous> (/home/user/app/dist/server.js:66:10)
   at Module._compile (module.js:643:30)
   at Object.Module._extensions..js (module.js:654:10)
   at Module.load (module.js:556:32)
   at tryModuleLoad (module.js:499:12)
   at Function.Module._load (module.js:491:3)
   at Function.Module.runMain (module.js:684:10)
   at startup (bootstrap_node.js:187:16)
   at bootstrap_node.js:608:3

 stackman loading source map for /home/user/app/node_modules/depd/index.js +0ms
 stackman loading source map for /home/user/app/node_modules/body-parser/index.js +1ms
 stackman loading source map for /home/user/app/node_modules/require-in-the-middle/index.js +0ms
 stackman loading source map for /home/user/app/node_modules/express/lib/express.js +0ms
 stackman loading source map for /home/user/app/node_modules/express/index.js +0ms
 stackman loading source map for /home/user/app/dist/server.js +0ms
 stackman reading /home/user/app/node_modules/depd/index.js +30ms
 stackman reading /home/user/app/node_modules/body-parser/index.js +0ms
 stackman reading /home/user/app/node_modules/require-in-the-middle/index.js +0ms
 stackman reading /home/user/app/node_modules/express/lib/express.js +1ms
 stackman reading /home/user/app/node_modules/express/index.js +0ms
 stackman reading /home/user/app/dist/webpack:/external "express" +221ms
 stackman reading /home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651 +1ms
 stackman reading /home/user/app/dist/webpack:/server.ts +0ms
 stackman reading /home/user/app/dist/server.js +1ms
 stackman error reading /home/user/app/dist/webpack:/external "express": ENOENT: no such file or directory, open '/home/user/app/dist/webpack:/external "express"' +10ms
 stackman error reading /home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651: ENOENT: no such file or directory, open '/home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651' +0ms
 stackman error reading /home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651: ENOENT: no such file or directory, open '/home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651' +0ms
 stackman error reading /home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651: ENOENT: no such file or directory, open '/home/user/app/dist/webpack:/webpack/bootstrap 9daa5dd531b848fb2651' +0ms
 stackman error reading /home/user/app/dist/webpack:/server.ts: ENOENT: no such file or directory, open '/home/user/app/dist/webpack:/server.ts' +0ms
logging error b88bd7b0-9d84-4f0c-b4f0-8cca0872e13f with Elastic APM

By using the defineProperty trick i prevent prepareStackTrace from being overwritten.
Strangely express and the body-parser seem to overwrite it...

Now that prepareStackTrace is set correctly however stackman failes and causes the app to exit.
For some reason stackman looks for the map files in the wrong place.

Do you have an idea if stackman works with webpack?
What do you think about all these prepareStackTrace overwrites?

@Davidiusdadi
Copy link
Author

The package depd seems to write prepareStackTrace a lot and i see no way of turning that off...
While my previous defined property would prevent further overwriting that would actually cause my app to terminate. Therefore i now define prepareStackTrace in such a way that it always does what seems to be essential for elastic-apm-node to work which seems to be setting __error_callsites

type prepTrace = (error, structuredStackTrace) => void
type Wrapper = prepTrace & { impl?: prepTrace }
let prepareStackTraceImpl = undefined
Object.defineProperty(Error, 'prepareStackTrace', {
    set: (v) => {
        if (v.impl) {
             prepareStackTraceImpl = v.impl
            return
        }
        prepareStackTraceImpl = v
    },
    get() {
        if (!prepareStackTraceImpl) {
            return
        }
        const wrapper: Wrapper = (err, callsites) => {
            // the following call is copied from error-callsites package
            Object.defineProperty(err, '__error_callsites', {
                enumerable: false,
                configurable: true,
                writable: false,
                value: callsites
            })

            return wrapper.impl.call(Error, err, callsites)
        }
        wrapper.impl = prepareStackTraceImpl

        return wrapper
    }
})

const apm = require('elastic-apm-node').start()

With that code i get the stacktraces in kibana apm:
image

In the stack trace can even see the real original file name and type along with the correct line number.
I however don't see any code context / surrounding lines

stackman prints out a bunch a of loading source map messages but no other messages like stackman reading like before. The stackman error are gone.

Do you have an idea why i don't see any surrounding lines for the stack taces?

@watson
Copy link
Member

watson commented Sep 24, 2018

Do you have an idea if stackman works with webpack?

It should - or at least it shouldn't crash - worst case it should just give up on collecting the stack trace and your app should continue as normal. But you might have discovered a bug. I'll see if I can reproduce it.

Do you happen to have a stack trace handy so I can see where it fails?

What do you think about all these prepareStackTrace overwrites?

It's not body-parser or express that are overwriting Error.prepareStackTrace, but they both use "dept" to mark certain API's as deprecated.

The dept module uses prepareStackTrace to ensure that it only outputs one deprecation warning per unique location in your source code where the deprecated API is called.

After I read the source code of dept, it seems like it's doing it in a way that's not in conflict with stackman. I.e. it's only overwriting Error.prepareStackTrace when it needs it, and then it's reapplying the original function after its done - so it shouldn't have any effect in the outside scope.

@Davidiusdadi
Copy link
Author

sorry for the delay - was on vacation
i'll provide a stacktrace in the next 3 days

@Davidiusdadi
Copy link
Author

I did not investigate further since we encountered #398 in production and disabled the capturing of stack traces altogether. (i'll post details on that issue)

I consider this issue solved since i could get the capturing of stack traces to work by ensuring prepareStackTrace is not overwritten by any other package.

Stackman failing to capture the surrounding lines is technically a different issue for which i'd open a separate issue in case in case #398 gets solved and the issue remains.

Thanks for the quick support.

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

No branches or pull requests

2 participants