Incompatibility with bluebird long stack traces - thoughts on workarounds?

[Druotic]

When enabling bluebird's long stack traces, the appended Caused By... gets removed and a confusing/misleading stacktrace is created. The resulting stacktrace is the first part of the nested error stacktrace plus the first few lines of the Caused By: stacktrace appended with no indication of start/stop of stacktraces (plus the From previous event: trace after). Likewise, if the error has been nested multiple times, all of the nested (Caused By:) stacks get chopped/appending to the first stack.

https://github.com/petkaantonov/bluebird/blob/fdd44ee3af6d4fc2570a0f877ca82805a477c6b8/src/debuggability.js#L554 is to blame. I was considering adding a bluebird option to opt out of it, but was curious if this was something you had encountered and worked around previously. The regex being used is /^\s*at\s*/, so prepending at i.e. at Caused by: ... is another possible workaround.

let Promise = require('bluebird')
const NestedError = require('nested-error-stacks')

const throwError = () => { return Promise.reject(new Error('some error')) }

;(async function () {

  await throwError()
  .catch(err => {
    throw new NestedError('nested', err)
  }).catch (err => console.log(`BLUEBIRD_DEBUG not set: ${err.stack}\n`))

  process.env.BLUEBIRD_DEBUG = 1
  delete require.cache[require.resolve('bluebird')]
  Promise = require('bluebird')

  await throwError()
  .catch(err => {
    throw new NestedError('nested', err)
  }).catch(err => console.log(`BLUEBIRD_DEBUG=1: ${err.stack}\n`))

})()

/*
BLUEBIRD_DEBUG not set: NestedError: nested
    at throwError.catch.err (/Users/james.beavers/repos/test/bluebirdStacks.js:10:11)
    at tryCatcher (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromiseCtx (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:606:10)
    at Async._drainQueue (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:138:12)
    at Async._drainQueues (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
Caused By: Error: some error
    at throwError (/Users/james.beavers/repos/test/bluebirdStacks.js:4:50)
    at /Users/james.beavers/repos/test/bluebirdStacks.js:8:9
    at Object.<anonymous> (/Users/james.beavers/repos/test/bluebirdStacks.js:22:3)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3

BLUEBIRD_DEBUG=1: NestedError: nested
    at throwError.catch.err (/Users/james.beavers/repos/test/bluebirdStacks.js:19:11)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
    at throwError (/Users/james.beavers/repos/test/bluebirdStacks.js:4:50)
    at /Users/james.beavers/repos/test/bluebirdStacks.js:17:9
From previous event:
    at /Users/james.beavers/repos/test/bluebirdStacks.js:18:9
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:169:7)
*/

After changing how stacks are combined: stack += '\nat Caused By: ' + nested.stack;, the result is:

BLUEBIRD_DEBUG not set: NestedError: nested
    at throwError.catch.err (/Users/james.beavers/repos/test/bluebirdStacks.js:10:11)
    at tryCatcher (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromiseCtx (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/promise.js:606:10)
    at Async._drainQueue (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:138:12)
    at Async._drainQueues (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/Users/james.beavers/repos/test/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
at Caused By: Error: some error
    at throwError (/Users/james.beavers/repos/test/bluebirdStacks.js:4:50)
    at /Users/james.beavers/repos/test/bluebirdStacks.js:8:9
    at Object.<anonymous> (/Users/james.beavers/repos/test/bluebirdStacks.js:22:3)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3

BLUEBIRD_DEBUG=1: NestedError: nested
    at throwError.catch.err (/Users/james.beavers/repos/test/bluebirdStacks.js:19:11)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
at Caused By: Error: some error
    at throwError (/Users/james.beavers/repos/test/bluebirdStacks.js:4:50)
    at /Users/james.beavers/repos/test/bluebirdStacks.js:17:9
From previous event:
    at /Users/james.beavers/repos/test/bluebirdStacks.js:18:9
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:169:7)

note: the shorter stacks are due to bluebird automatically trimming common ancestors, internal trace lines, etc, but those lines aren't very useful anyway.

FWIW, this isn't a problem with Q's longStackSupport.

I can open a PR to prepend at, but I assume that would lead to a major version bump and might not be the preferred approach. Getting an opt-out merged into bluebird and released would probably take a while. Do you have a preference @mdlavin, or any other alternative ideas?

[mdlavin]

What about appending the 'at ' only when BLUEBIRD_DEBUG is set? That would leave the behavior untouched for most people but would still work better when bluebird is used?

I haven't seen this problem, but I also have stopped using Bluebird/Q since the newer versions of node have async/await support.

[Druotic]

That'd work for me. Sorry for the spam - forgot to rebase first. Regarding async/await - it still seems like some people might continue to use bluebird along with async/await for the convenience functions that native promises don't support - e.g. timeouts, tap, etc.

Just realized I didn't add any documentation to point out this new behavior if either of the environment variables are set. I'll add a commit in a sec.

[zommerfelds]

I just hit the same issue. I haven't looked into how either library is implemented, but if you say that Bluebird removes parts of the stack trace, would it be better to fix it on their end? Regarding the BLUEBIRD_DEBUG variable: we don't set it, but because NODE_ENV is set to development we get the Bluebird long stacktraces too. I just found the variable BLUEBIRD_LONG_STACK_TRACES as well.

[Druotic]

@zommerfelds Initially, I looked into fixing the issue on Bluebird's side, but I felt conflicted about what the right approach was. While Bluebird is making some strict assumptions about the stack and doing some manipulation around those assumptions, I don't feel like their assumptions are necessarily bad.

Appending newlines and strings to a stack is probably a bit unusual. Not bad in this case (as they are very helpful), but it certainly doesn't fit the shape of a normal stack that gets generated when an error is created.

I considered adding an option/env variable to bluebird, but then users of nested-error-stacks would have to know about the issue and would have to go out of their way to opt into the option. Not to mention - getting a change into bluebird and/or getting everyone on board with such an option might be difficult since it'd effectively be an option for just this library (or maybe a small handful of others).

I'm open to alternative ideas, though.