Skip to content

Instantly share code, notes, and snippets.

@ugultopu

ugultopu/How to preserve the original stack trace in callbacks?.md

Last active December 22, 2020 17:22
Show Gist options
  • Save ugultopu/83ebf605495b734247d287725ddb13df to your computer and use it in GitHub Desktop.
Save ugultopu/83ebf605495b734247d287725ddb13df to your computer and use it in GitHub Desktop.
Download ZIP
A description of the problem of and potential solutions for understanding the location where a callback is used at
Raw
How to preserve the original stack trace in callbacks?.md

Summary

Use the following pattern in your callbacks:

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  err => throwIfError(err),
);

// NOTE: This works only if it is used with an inline helper callback like `err
// => throwIfError(err)`, which is a function _expression_ that's passed to a
// function invocation which expects a callback. If the following function is
// used by itself, like `throwIfError`, it won't work!
function throwIfError(err) {
  if (!err) return;

  // https://nodejs.org/api/errors.html#errors_error_capturestacktrace_targetobject_constructoropt
  const stackContainer = {
    name: 'Info',
    message: 'First line below shows where this callback was used'
  };
  Error.captureStackTrace(stackContainer, throwIfError);

  err.stack = stackContainer.stack + '\n' + err.stack;
  // Following is so that the stack will be formatted properly when it is
  // printed. The `formatError` function in 'lib/internal/util/inspect.js'
  // ignores everything in the `stack` property until the end of the value of
  // the `message` property in the `stack` property. That is, the `err.message`
  // is present in `err.stack` by default, because when creating an error with
  // an argument, the argument becomes the `message` property, and the value of
  // the `stack` property is generated using the:
  //
  // - Name of the error type
  // - Error message
  // - Stack trace at the time that the error is created
  //
  // Since the `message` property is present in the `stack` property by default,
  // and since the `formatError` function in 'lib/internal/util/inspect.js'
  // ignores everything until the end of the value of the `message` in the
  // `stack` property, we remove the `message` property so that the part of the
  // stack before the value of the `message` property will not be ignored (that
  // is, it will be formatted properly for printing).
  //
  // The lines in the `formatError` function in 'lib/internal/util/inspect.js'
  // that cause this are as follows:
  //
  //     // Ignore the error message if it's contained in the stack.
  //     let pos = (err.message && stack.indexOf(err.message)) || -1;
  //     if (pos !== -1)
  //       pos += err.message.length;
  delete err.message;

  throw err;
}
$ node script.js
/path/to/the/script.js:50
  throw err;
  ^

Info: First line below shows where this callback was used
    at /path/to/the/script.js:4:10
    at fs.js:1448:7
    at FSReqCallback.oncomplete (fs.js:171:23)
Error: ENOENT: no such file or directory, open 'some_non_existent_directory/some_file' {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/some_file'
}
$

Description

I'm writing a script in Node.js and I want the script to fail fast. Hence, I've written the following function to be used as a callback in multiple places:

function throwIfError(err) {
  if(err) throw err;
}

However, when I use it in, say fs.writeFile, I'm not getting a helpful stack trace:

function throwIfError(err) {
  if(err) throw err;
}

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  throwIfError,
);
$ node script.js
/path/to/script.js:2
  if(err) throw err;
          ^

[Error: ENOENT: no such file or directory, open 'some_non_existent_directory/some_file'] {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/some_file'
}
$

Nothing here tells me that the source of the error is the call to writeFile on line 5. The script could have multiple writeFile calls and I wouldn't know where the error originated from.

Using console.trace() does not help either:

function throwIfError(err) {
  console.trace();
}

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  throwIfError,
);
$ node script.js
Trace
    at throwIfError (/path/to/script.js:2:11)
    at fs.js:1448:7
    at FSReqCallback.oncomplete (fs.js:171:23)
$

Instead of defining the callback function in one place and using it in multiple places, defining the callback inline at each function call fixes it:

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  err => {if(err) throw err},
);
$ node script.js
/path/to/script.js:4
  err => {if(err) throw err},
                  ^

[Error: ENOENT: no such file or directory, open 'some_non_existent_directory/some_file'] {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/some_file'
}
$

Since the callback is inline now, the place where the error is thrown is the same place where the "problematic" function call is made. Since the runtime tells me the location where the error is thrown, this means I implicitly know in which function call the error occurred.

However, the problem with this is code duplication. Doing this means defining the same function (the callback) over and over again in many places. If I want to change the callback, all needs to be changed since all are actually duplicates of each other. Another issue is the increased load on the garbage collector. In the previous way, there is only one callback and just references to it. However, in this way, there are as many callbacks as they are used.

The first problem (duplicating callback definition and the need to change every one of them when you need to change one) can be fixed with the following "helper callback" pattern:

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  err => throwIfError(err),
);

function throwIfError(err) {
  if(err) {
    console.log('Callback is located at:');
    console.trace();
    throw err;
  }
}
$ node script.js
Callback is located at:
Trace
    at throwIfError (/path/to/the/script.js:10:13)
    at /path/to/the/script.js:4:10
    at fs.js:1448:7
    at FSReqCallback.oncomplete (fs.js:171:23)
/path/to/the/script.js:11
    throw err;
    ^

[Error: ENOENT: no such file or directory, open 'some_non_existent_directory/some_file'] {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/some_file'
}
$

Here, the second line in the output of the console.trace lets me understand where the callback is used at. This way, I understand which function call caused this error.

An advantage of this pattern is, if the (real) callback needs to be changed, it can simply be changed just in one place, which is where it is defined. However, there is still the problem of increased load on the garbage collector because we are defining anonymous "helper" callbacks at each place that we need to use the throwIfError callback.

A fancier implementation of this same idea is as follows:

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  err => throwIfError(err),
);

// NOTE: This works only if it is used with an inline helper callback like `err
// => throwIfError(err)`, which is a function _expression_ that's passed to a
// function invocation which expects a callback. If the following function is
// used by itself, like `throwIfError`, it won't work!
function throwIfError(err) {
  if (!err) return;

  // https://nodejs.org/api/errors.html#errors_error_capturestacktrace_targetobject_constructoropt
  const stackContainer = {
    name: 'Info',
    message: 'First line below shows where this callback was used'
  };
  Error.captureStackTrace(stackContainer, throwIfError);

  err.stack = stackContainer.stack + '\n' + err.stack;
  // Following is so that the stack will be formatted properly when it is
  // printed. The `formatError` function in 'lib/internal/util/inspect.js'
  // ignores everything in the `stack` property until the end of the value of
  // the `message` property in the `stack` property. That is, the `err.message`
  // is present in `err.stack` by default, because when creating an error with
  // an argument, the argument becomes the `message` property, and the value of
  // the `stack` property is generated using the:
  //
  // - Name of the error type
  // - Error message
  // - Stack trace at the time that the error is created
  //
  // Since the `message` property is present in the `stack` property by default,
  // and since the `formatError` function in 'lib/internal/util/inspect.js'
  // ignores everything until the end of the value of the `message` in the
  // `stack` property, we remove the `message` property so that the part of the
  // stack before the value of the `message` property will not be ignored (that
  // is, it will be formatted properly for printing).
  //
  // The lines in the `formatError` function in 'lib/internal/util/inspect.js'
  // that cause this are as follows:
  //
  //     // Ignore the error message if it's contained in the stack.
  //     let pos = (err.message && stack.indexOf(err.message)) || -1;
  //     if (pos !== -1)
  //       pos += err.message.length;
  delete err.message;

  throw err;
}
$ node script.js
/path/to/the/script.js:50
  throw err;
  ^

Info: First line below shows where this callback was used
    at /path/to/the/script.js:4:10
    at fs.js:1448:7
    at FSReqCallback.oncomplete (fs.js:171:23)
Error: ENOENT: no such file or directory, open 'some_non_existent_directory/some_file' {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/some_file'
}
$

Although this does not solve the problem of increased load on the garbage collector due to anonymous "helper" callback function, this was the best that I was able to come up with.

A similar solution that I came up with before realizing that I can do the "helper" callback pattern (err => throwIfErr(err)) shown above was the following:

require('fs').writeFile(
  'some_non_existent_directory/test.txt',
  '',
  getThrowIfError(),
);

function getThrowIfError() {
  // https://nodejs.org/api/errors.html#errors_error_capturestacktrace_targetobject_constructoropt
  const stackContainer = {
    name: 'Info',
    message: 'First line below shows where this callback was used'
  };
  Error.captureStackTrace(stackContainer, getThrowIfError);

  // Not sure if this optimization is necessary. That is, not sure if
  // the performance would have been the same if we had just used:
  //
  //     err.stack = stackContainer.stack + '\n' + err.stack;
  //
  // in `throwIfError`.
  //
  // Or, maybe instead of this line, we could have just used:
  //
  //     Object.defineProperty(err, 'stack', {writable: false});
  //
  // This way, the runtime would know that the property is read-only and
  // hence, it could do the necessary optimizations.
  //
  // Or could it? That is, just because we have that `defineProperty`
  // call, could the runtime really understand that the property is
  // read-only and make the relevant optimizations?
  //
  // Maybe the best thing is to write the code as the original version
  // (that is as:)
  //
  //     err.stack = stackContainer.stack + '\n' + err.stack;
  //
  // and let the runtime (JavaScript compiler) do the optimizations.
  // Because it is obvious that `originalStack` object is not being used
  // anywhere else, hence it can be garbage collected (only one of its
  // properties named 'stack' is being used without being modified
  // anywhere. Hence, I think that property can be "extracted" and the
  // object can be garbage collected. Of course, this entirely depends
  // on the particular JavaScript engine implementation).
  const originalStack = stackContainer.stack;

  return throwIfError;

  function throwIfError(err) {
    if (!err) return;

    err.stack = originalStack + '\n' + err.stack;
    // Following is so that the stack will be formatted properly when it is
    // printed. The `formatError` function in 'lib/internal/util/inspect.js'
    // ignores everything in the `stack` property until the end of the value of
    // the `message` property in the `stack` property. That is, the `err.message`
    // is present in `err.stack` by default, because when creating an error with
    // an argument, the argument becomes the `message` property, and the value of
    // the `stack` property is generated using the:
    //
    // - Name of the error type
    // - Error message
    // - Stack trace at the time that the error is created
    //
    // Since the `message` property is present in the `stack` property by default,
    // and since the `formatError` function in 'lib/internal/util/inspect.js'
    // ignores everything until the end of the value of the `message` in the
    // `stack` property, we remove the `message` property so that the part of the
    // stack before the value of the `message` property will not be ignored (that
    // is, it will be formatted properly for printing).
    //
    // The lines in the `formatError` function in 'lib/internal/util/inspect.js'
    // that cause this are as follows:
    //
    //     // Ignore the error message if it's contained in the stack.
    //     let pos = (err.message && stack.indexOf(err.message)) || -1;
    //     if (pos !== -1)
    //       pos += err.message.length;
    delete err.message;

    throw err;
  }
}
$ node script.js
/path/to/the/script.js:81
    throw err;
    ^

Info: First line below shows where this callback was used
    at Object.<anonymous> (/path/to/the/script.js:4:3)
    at Module._compile (internal/modules/cjs/loader.js:1063:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10)
    at Module.load (internal/modules/cjs/loader.js:928:32)
    at Function.Module._load (internal/modules/cjs/loader.js:769:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:72:12)
    at internal/main/run_main_module.js:17:47
Error: ENOENT: no such file or directory, open 'some_non_existent_directory/test.txt' {
  errno: -2,
  code: 'ENOENT',
  syscall: 'open',
  path: 'some_non_existent_directory/test.txt'
}
$

This one works by creating a closure each time the callback is generated and storing the original stack trace ("original stack trace" is the stack trace at the time that the callback is generated in this closure. Initially I implemented it so that it would store the original stack trace on the function object itself, such as throwIfError.originalStack = originalStack (and then use it like err.stack = throwIfError.originalStack + '\n' + err.stack;), but then by mistake, I realized that the closure version works too.

Moreover, the current implementation of the closure version might be more efficient than the "helper callback" version in some ways. In the closure version, the JavaScript engine (in this case, V8) might be creating only one instance of throwIfError function and on every closure creation, simply returning the a reference to this same instance, along with the custom closure environment. So, on every closure creation, the only extra costs compared to the "helper callback" might be the:

  • Invocation of the callback generator function, getThrowIfError. That is, creation of a call stack frame, etc. But this might not be too relevant because the helper callback causes the creation of an extra call stack frame each time the helper callback is invoked as well. This makes the number of stack frames used equal between the "helper callback version" and "closure version".
  • Invocation of the Error.captureStackTrace in getThrowIfError function and operations related to it. This is definitely worse than than the "helper callback" one because in "helper callback" one, Error.captureStackTrace is being invoked in the callback (as opposed to in the callback generator) only when there is an error. So, while in the "helper callback" one Error.captureStackTrace is being invoked only when there is an error, in "callback generator one" (that is, this one), Error.captureStackTrace is being invoked always.

On the other hand, in the "helper callback" one, the code of the helper callbacks are always the same (err => throwIfError(err)) too, just like in the "closure version". (Also the code of the "real callback" is definitely the same in the "helper callback version", since the real callback does not change at all.) Since the code of the helper callbacks are always the same (only the context (execution context and scope) and meta information like the line number and file path that the helper function is located at are different), most likely the JavaScript runtime is optimizing the helper callbacks too. Hence, actually the helper callback pattern might be (and probably is) much more efficient than this one, but we can't really know for sure without performing some performance tests.

Another noteworthy difference of this from the "helper callback" is that the rest of the stack trace here includes the trace until the invocation of the callback generator, whereas the stack trace in the "helper callback" pattern includes the trace of the code that invoked the callback. This might be an important difference and either of them could be preferred depending on the requirements for debugging a particular callback.

Another idea that came to my mind is, if the program logic continued from the callback, we wouldn't need any of these because then the error check (and throw) would be in the callback and due to the structure of the code, we would understand what caused the error. That is, since the runtime tells us the location of the throw operator when an uncaught error is thrown, and since that throw operator would have been inside the place where the program would resume, then we could easily deduct what was the place before the callback. Explanation in code:

require('fs').writeFile(
  'some_non_existent_directory/some_file',
  '',
  function restOfYourProgram(err) {
    if (err) throw err;
    // Operations required in the rest of your program.
  },
);
// No code will go here. All the rest of the whole program will continue from
// the `restOfYourProgram` function.

But then again, this would defeat the purpose of using asynchronous programming. The whole point of asynchronous programming is being able to perform other things while a long operation (such as I/O) is being performed in the background. The role of callbacks here is to contain the code that depends on the asynchronous operation. If you place the things that does not depend on the asynchronous operation in the callback as well, then you are unnecessarily blocking the execution of the non-dependent code until the asynchronous operation finishes. That is, you are essentially making the whole code synchronous. This defeats the whole purpose of using asynchronous programming (and callbacks).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment