Always show stack trace on errors

[BluSyn]

Issue
Assertion errors are difficult to debug.
In bcoin it's common to see errors such as this in logs:
[error] (node) false == true or
[error] (node) Assertion failed.

Without a stack trace it is impossible to determine the cause of these errors.
We don't want a stack trace to show for every error thrown, but assertions
are an exception.

Solution
Using ERR_ASSERTION code to always show stack trace in this case.

Was hoping for a more general solution than relying on error code,
but I've decided it makes sense to consider assertions a special
exception case that we should handle specifically.

Example result after change:

[error] (node) Assertion failed.
    at parseEntry (bcoin/lib/wallet/client.js:87:3)
    at WalletClient.getEntry (bcoin/lib/wallet/client.js:63:12)
    at processTicksAndRejections (internal/process/task_queues.js:86:5)

Caveat:
This does result in duplicate stack traces showing in stream due to this line:

blgr/lib/logger.js

Lines 524 to 527 in f4de8ba

	if (level <= Logger.levels.WARNING) {
	if (this.stream)
	this.stream.write(err.stack + '\n');
	}

I'm not sure what the best solution is yet, short of adding a code !== 'ERR_ASSERTION' check,
but there could be some consequences here.

Related discussions:
bcoin-org/bcoin#762 (comment)
https://github.com/bcoin-org/bcoin/pull/605/files#r256155372

[braydonf]

Is there a reason not not display the stack trace on all cases for logger.error? I had originally though that it may be good to use NODE_ENV != production to show the stack, however that may also not be necessary.

[BluSyn]

Is there a reason not not display the stack trace on all cases for logger.error?

That could be noisy, as 'error' is a low level error, which would change logger.error into more like a console.trace. That seems like unintended behavior as traces are usually only for debugging. However for serious errors, such as assertion failures, you likely do want to see traces.

I had originally though that it may be good to use NODE_ENV != production to show the stack, however that may also not be necessary.

I considered the NODE_ENV idea, but that seems unhelpful since most of the random assertion failures that get reported are from production environments.

[tynes]

I considered the NODE_ENV idea, but that seems unhelpful since most of the random assertion failures that get reported are from production environments.

It would help a lot to be able to debug certain situations with the ability to turn on trace logging for errors. This problem - bcoin-org/bcoin#762 - is a good example because without the trace, its really hard to know what is wrong.

If not using with an environment variable, maybe a new log level is defined that is trace which is equivalent to error but instead logs the trace instead of just the error? Either way it would be really helpful if users could restart their process with a little configuration and see the stack trace

[braydonf]

The default behavior of console.error is to include the stack trace. Others that shouldn't display a trace should likely be warnings instead, then again the default behavior of console.warn is to include that stack too.

[braydonf]

There are also not that many places an error is logged in bcoin:

lib/node/node.js:        this.logger.error('Worker %d error: %s', child.id, err.message);
lib/node/node.js:    this.logger.error(err);
lib/blockchain/chain.js:        this.logger.error(e);
lib/mining/miner.js:          this.logger.error(e);
lib/mining/cpuminer.js:          this.logger.error(e);
lib/net/hostlist.js:      this.logger.error(e);
lib/net/hostlist.js:      this.logger.error(e);
lib/net/hostlist.js:      this.logger.error(e);

[braydonf]

I think the best option is to include the stack for all errors for logger.error, regardless of the NODE_ENV variable or the type of error.

[BluSyn]

I think the best option is to include the stack for all errors for logger.error, regardless of the NODE_ENV variable or the type of error.

Agreed. Updated PR to always show stack if present. Also removed existing logic for showing stack in streams only, since this is now redundant.

[braydonf]

nit: This comment is outdated.

[braydonf]

Looks good, tested with bcoin and handling node errors.

[BluSyn]

This does result in lots of this noise on my main-net fullnode:

[info] (net) Error: Verification failure: replace-by-fee (code=nonstandard score=0 hash=66524f0f1ec153105e470ff63458765ebc9eb1d489d9ff238c56dd38bdcdfebe)
    at Mempool.insertTX (/code/bcoin/lib/mempool/mempool.js:806:17)
    at Mempool._addTX (/code/bcoin/lib/mempool/mempool.js:726:28)
    at Mempool.addTX (/code/bcoin/lib/mempool/mempool.js:705:25)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:188:7)

This is one of the reasons I was checking by error code. Perhaps adding something to VerifyError in bcoin to prevent creation of stack in this case?

Thoughts @braydonf ?

[braydonf]

That is an info log not an error? I'll take a look at options.

[BluSyn]

My guess is it's because VerifyError extends Error class, so probably hits this:
https://github.com/bcoin-org/blgr/blob/master/lib/logger.js#L318-L321

I will have to test this more locally, I just noticed this on my production node.

[braydonf]

Okay, yeah. It would probably be better to either send the logger.info() just a message in that case, or switch to the log level to warn, debug or similar.

[braydonf]

Another case that is expected, and may not need the stack (though is a debug log):

[D:2019-05-15T20:28:35Z] (net) Error: Socket Error: ENETUNREACH ([2604:a880:400:d0::2004:f001]:8333)
    at Peer.error (bcoin/lib/net/peer.js:1218:13)
    at Peer.open (bcoin/lib/net/peer.js:358:12)
    at process._tickCallback (internal/process/next_tick.js:68:7)

[braydonf]

Yeah, the net/pool can use this instead for mempool verification errors:

diff --git a/lib/net/pool.js b/lib/net/pool.js
index 82d31c9c..a5bc478a 100644
--- a/lib/net/pool.js
+++ b/lib/net/pool.js
@@ -2441,7 +2441,7 @@ class Pool extends EventEmitter {
     } catch (err) {
       if (err.type === 'VerifyError') {
         peer.reject('tx', err);
-        this.logger.info(err);
+        this.logger.info(err.message);
         return;
       }
       throw err;

[braydonf]

Okay, all updates (including the above) are at bcoin-org/bcoin#771