Building my own Stack Traces

Have you ever had an error in a javascript project?

TypeError: Cannot read property 'subdomain' of undefined
      at /Users/jstaab/my-project/src/server/db/core.js:568:35
      at Array.filter (<anonymous>)
      at /Users/jstaab/my-project/src/server/db/core.js:147:1
      at log (src/common/logger.js:75:14)
      at _callee16$ (src/server/db/core.js:768:28)
      at tryCatch (node_modules/regenerator-runtime/runtime.js:45:40)
      at Generator.invoke [as _invoke] (node_modules/regenerator-runtime/runtime.js:271:22)
      at Generator.prototype.(anonymous function) [as next] (node_modules/regenerator-runtime/runtime.js:97:21)
      at asyncGeneratorStep (src/server/db/core.js:22:103)
      at _next (src/server/db/core.js:24:194)
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:189:7)

Even with source maps, that stack would only point to where the error was thrown, but I have no idea where in the application that thing was called.

Today I decided to do something about it, by implementing my own stack traces. For example, for the above error, I got this extra information:

Intercepted in:
     server/db/core/getWhereColumns
     server/db/core/deleteRecords
     server/db/domain/MyModel.delete

This just gets appended to an error's built-in stack trace (which are just strings in the first place). This makes it orders of magnitude faster for me to isolate problems and fix them, whether I'm developing locally or diagnosing a problem in production.

This approach has drawbacks: there's some nasty boilerplate, and definitely some performance downsides, which I'll go into at the end of this post. But is it worth it? I think so.

Implementation

The basic concept is that you have a decorator that catches errors and rejected promises, annotates their stack, and re-throws them.

const IS_INSTRUMENTED = Symbol('isInstrumented')

const instrument = (name, f) => {
  if (f[IS_INSTRUMENTED]) {
    return f
  }

  function wrapper(...args) {
    let result
    try {
      result = f.call(this, ...args)
    } catch (error) {
      throw modifyStack(name, error)
    }

    if (result instanceof Promise) {
      result = result.catch(error => {
        throw modifyStack(name, error)
      })
    }

    return result
  }

  wrapper.name = name
  wrapper[IS_INSTRUMENTED] = true

  return wrapper
}

The reason I'm not using an async function here is that I want to be able to instrument synchronous functions without converting them to promise-returning functions (async functions always return promises). We're also using es5 function syntax and bind so we can pass this along.

This function takes a name and another function, and returns a function that passes the arguments along to the decorated function, catching any synchronous errors that it might throw and modifying their stack. It also checks if the return value is a promise, and modifies the stack of the return value.

Note that you should only ever throw/reject Errors, since this will add wonky stack properties to anything else.

Here's modifyStack:

const modifyStack = (name, error) => {
  if (!error.originalStack) {
    error.originalStack = error.stack
    error.stack += "\n\n    Intercepted in:"
  }

  error.stack += `\n\t ${name}`

  return error
}

A Basic Example

Here's how you'd use instrument:

const concat = instrument('utils.concat', (a, b) => a.concat(b))
const append = instrument('utils.append', (a, b) => concat(a, [b]))

Note that I don't recommend decorating utility functions, since they're likely to be leaf nodes in your call graph, and are usually called synchronously so you'll get a good stack trace for them. You also don't want to add the overhead of this decorator to something that's going to get called very often. This decorator is much better for controllers, hefty logic functions, etc, to give you a sense of what code path has gone wrong. With that in mind, what if you called the above function with weird arguments?

append(1, 2)

/*
Uncaught TypeError: a.concat is not a function
    at <anonymous>:1:55
    at wrapper (<anonymous>:7:18)
    at <anonymous>:2:53
    at wrapper (<anonymous>:7:18)
    at <anonymous>:1:1

    Intercepted in:
     utils.concat
     utils.append
*/

Not that helpful, but remember, this is just a small example. In complex application code, this sort of thing can be a lifesaver.

Class Methods

Class syntax can make this approach a pain. If you don't want to add a syntax transformer, you have another option: instrument an entire class. Here's what that looks like:

const instrumentClass = cls => {
  let obj = cls.prototype
  do {
    if (obj.constructor === Object) {
      break
    }

    Object.getOwnPropertyNames(obj).forEach(k => {
      if (typeof obj[k] === 'function' && k !== 'constructor') {
        obj[k] = instrument(`${obj.constructor.name}.${k}`, obj[k])
      }
    })
  } while (obj = Object.getPrototypeOf(obj))
}

class Libation {
  pourOn(target) {
    target.wet = true
  }
}

class Tea extends Libation {
  async pourOn(target) {
    await new Promise(() => super.pourOn(target))

    target.bland = true
  }
}

instrumentClass(Tea)

We're basically following this StackOverflow answer to traverse the chain of inheritance so we can enumerate all methods attached to our instance. We then instrument those methods, marking them with the class name and method name, skipping the constructor.

Here's how this would look in practice:

const tea = new Tea()
const ground = null

tea.pourOn(ground)

/*
Uncaught (in promise) TypeError: Cannot set property 'wet' of null
    at Tea.pourOn (<anonymous>:57:16)
    at Tea.wrapper (<anonymous>:5:18)
    at target.bland (<anonymous>:63:35)
    at new Promise (<anonymous>)
    at Tea.pourOn (<anonymous>:63:11)
    at Tea.wrapper (<anonymous>:5:18)
    at <anonymous>:74:5

    Intercepted in:
     Libation.pourOn
     Tea.pourOn
*/

Notice that the original stack trace is just plain wrong — and this is running in Chrome's devtools, with no build step. But now we have more information: the error happened in Libation.pourOn, which was called by Tea.pourOn! I don't know about you, but I find this very helpful.

Footguns and Performance

Obviously, any time you're changing the semantics of your host language, you need to be careful. This code is not perfect yet, but I've tried to address some of the possible issues:

• This code won't wrap synchronous functions in a Promise.
• This code will pass this down along with the arguments to the wrapped function.
• instrumentClass does create a new copy of each method, including a wrapping closure. What it doesn't do is create a new copy for each instance, which means we still have the general memory-conserving characteristics of object-oriented method dispatch.
• We're not unnecessarily wrapping every method of Object, and we can easily add code to whitelist which methods we wrap.

Performance is also not terrible. Here's a little bit of profiling code:

const profile = f => {
  now = new Date().valueOf()
  for (let i = 0; i < 10000000; i++) f(i, i)
  console.log(new Date().valueOf() - now)
}

profile((x, y) => x + y)
profile(instrument('hi there', (x, y) => x + y))

Without the wrapper, this comes out to ~200ms. With the wrapper, it comes out to ~450ms. This is 150% slower, but it's really a worst case scenario since the wrapper is doing more work than the inner function (which is why it's a bad idea to wrap frequently-used utility functions). If the inner function did more work, the cost of the wrapper would be negligible:

const profile = f => {
  now = new Date().valueOf()
  for (let i = 0; i < 1000; i++) f(i, i)
  console.log(new Date().valueOf() - now)
}

const f = (x, y) => {
  const r = []
  for (let i = 0; i < x; i++) {
    for (let j = 0; j < x; j++) {
      r.push(i + j)
    }
  }

  return r
}

profile(f)
profile(instrument('hi there', f))

This comes out to ~11200ms for both versions.

Conclusion

This code is available on github — please let me know in the comments what you think of this approach! Am I a generously mustached daredevil maverick, or am I going to end up like Rod Kimble, desperately shouting "Whiskey" on my way toward the side of a van?

Thanks for reading!