Not getting stack trace past async boundary in node.js server

[dobesv]

Hi,

When I look at a span in APM I only see the stack trace up to the current event loop handler. I was hoping to see the stack trace go further back so I could tell the actual API call being made. e.g. the trace looks like this:

node_modules/mongodb-core/lib/cursor.js in nextFunction at line 607
node_modules/mongodb-core/lib/cursor.js in cursor.topology.selectServer at line 820
node_modules/mongodb-core/lib/topologies/replset.js in ReplSet.selectServer at line 1149
node_modules/mongodb/lib/topologies/topology_base.js in selectServer at line 362
node_modules/mongodb-core/lib/cursor.js in initializeCursor at line 779
node_modules/mongodb-core/lib/cursor.js in nextFunction at line 591
node_modules/mongodb-core/lib/cursor.js in Cursor.next at line 833
node_modules/mongodb/lib/cursor.js in Cursor._next at line 211
node_modules/mongodb/lib/operations/cursor_ops.js in fetchDocs at line 209
node_modules/mongodb/lib/operations/cursor_ops.js in toArray at line 239
node_modules/mongodb/lib/utils.js in <anonymous> at line 437
in Promise at line 0
node_modules/mongodb/lib/utils.js in executeOperation at line 432
node_modules/mongodb/lib/cursor.js in Cursor.toArray at line 824
src/api/users/loaders/users.js in batchFn at line 6
node_modules/dataloader/index.js in dispatchQueueBatch at line 246
node_modules/dataloader/index.js in dispatchQueue at line 233
node_modules/dataloader/index.js in global.<anonymous> at line 70
internal/process/next_tick.js in internalTickCallback at line 70

Is it possible facebook's DataLoader is doing one of those things that prevents APM from tracing back past an async boundary?

[dobesv]

I'm guessing it has something to do with this stuff in dataloader:

// Private: Enqueue a Job to be executed after all "PromiseJobs" Jobs.
//
// ES6 JavaScript uses the concepts Job and JobQueue to schedule work to occur
// after the current execution context has completed:
// http://www.ecma-international.org/ecma-262/6.0/#sec-jobs-and-job-queues
//
// Node.js uses the `process.nextTick` mechanism to implement the concept of a
// Job, maintaining a global FIFO JobQueue for all Jobs, which is flushed after
// the current call stack ends.
//
// When calling `then` on a Promise, it enqueues a Job on a specific
// "PromiseJobs" JobQueue which is flushed in Node as a single Job on the
// global JobQueue.
//
// DataLoader batches all loads which occur in a single frame of execution, but
// should include in the batch all loads which occur during the flushing of the
// "PromiseJobs" JobQueue after that same execution frame.
//
// In order to avoid the DataLoader dispatch Job occuring before "PromiseJobs",
// A Promise Job is created with the sole purpose of enqueuing a global Job,
// ensuring that it always occurs after "PromiseJobs" ends.
//
// Node.js's job queue is unique. Browsers do not have an equivalent mechanism
// for enqueuing a job to be performed after promise microtasks and before the
// next macrotask. For browser environments, a macrotask is used (via
// setImmediate or setTimeout) at a potential performance penalty.
var enqueuePostPromiseJob =
  typeof process === 'object' && typeof process.nextTick === 'function' ?
    function (fn) {
      if (!resolvedPromise) {
        resolvedPromise = Promise.resolve();
      }
      resolvedPromise.then(() => process.nextTick(fn));
    } :
    setImmediate || setTimeout;

Is there a way I can monkeypatch this myself?

[stephenbelanger]

That's a limitation of Node.js itself. You can try installing a long stack trace module to improve that, though they do tend to have a significant performance impact. If you are on Node.js 8+, you can try https://www.npmjs.com/package/trace

[dobesv]

Hmm I thought the elastic APM module had a bunch of code to work around this itself.