debug

debug copied to clipboard

Hello,

Small question of which I don't know it's a bug or expected behaviour:

In my express application I have the following app.use at the bottom:

app.use( (error, req, res, next) => {
    const status = error.statusCode || 500;
    const source = error.source || 'Unknown';
    const message = error.message;
    const info = error.info || '';
    console.log(error); // For logging on the server
    res.status(status).json({
        status: status,
        source: source,
        message: message,
        info: info
    })
});

This shows me the stack trace and the error object (with source and info properties).

When I change the console.log to debug, it only shows the stack trace and not the error object.

Why is that? And how can I show the error object with the debug command also?

And while this gives the undesired effect described above:

debug(error)

the following does work as desired.

debug({x: error})

Can you show the code with debug, and a minimal complete reproduction case?

Here it is:

package.json

{
  "name": "debug-issue711",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "start": "export DEBUG=d:* && node app.js"
  },
  "author": "",
  "license": "ISC",
  "dependencies": {
    "debug": "^4.1.1",
    "express": "^4.17.1"
  }
}

app.js

const express = require('express');
const debug = require('debug')('d:app');

const app = express();

app.use((req, res, next) => {
    res.setHeader('Access-Control-Allow-Origin', '*');
    res.setHeader('Access-Control-Allow-Methods', 'GET');
    res.setHeader('Access-Control-Allow-Headers', 'Content-Type, Authorization');
    next();
});

app.get('/', (req, res, next) => {
    // Generate an error
    const error = new Error('I see a red door and I want it painted black');
    error.source = 'Root-route';
    error.info = {
        "additional info": "No colors anymore I want them to turn black"
    };
    throw error;
});


app.use((error, req, res, next) => {
    const status = error.statusCode || 500;
    const source = error.source || 'Unknown';
    const message = error.message;
    const info = error.info || '';
    debug('Showing error');
    debug(error); // For logging on the server
    debug('Showing {x: error}');
    debug({x:error});
    res.status(status).json({
        status: status,
        source: source,
        message: message,
        info: info
    })
});

app.listen(8000);

And the output in the console on the server:

__> npm start

> [email protected] start /Users/bert/Project/Github/Debug-issue711
> export DEBUG=d:* && node app.js

  d:app Showing error +0ms
  d:app Error: I see a red door and I want it painted black
  d:app     at app.get (/Users/bert/Project/Github/Debug-issue711/app.js:15:19)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5)
  d:app     at next (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/route.js:137:13)
  d:app     at Route.dispatch (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/route.js:112:3)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5)
  d:app     at /Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:281:22
  d:app     at Function.process_params (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:335:12)
  d:app     at next (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:275:10)
  d:app     at app.use (/Users/bert/Project/Github/Debug-issue711/app.js:10:5)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5) +1ms
  d:app Showing {x: error} +1ms
  d:app { x: 
  d:app    { Error: I see a red door and I want it painted black
  d:app     at app.get (/Users/bert/Project/Github/Debug-issue711/app.js:15:19)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5)
  d:app     at next (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/route.js:137:13)
  d:app     at Route.dispatch (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/route.js:112:3)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5)
  d:app     at /Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:281:22
  d:app     at Function.process_params (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:335:12)
  d:app     at next (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/index.js:275:10)
  d:app     at app.use (/Users/bert/Project/Github/Debug-issue711/app.js:10:5)
  d:app     at Layer.handle [as handle_request] (/Users/bert/Project/Github/Debug-issue711/node_modules/express/lib/router/layer.js:95:5)
  d:app      source: 'Root-route',
  d:app      info: 
  d:app       { 'additional info': 'No colors anymore I want them to turn black' } } } +0ms

Aha, I thought this got fixed a while back. Apparently not. Thanks for the repro case, by the way :)

The first argument is not util.format'd where it should be.

The standard .toString() on Error objects does not include extraneous information. console.log() is, more or less, just (...args) => stdout.write(util.format(...args)). That's why it's showing the extra information.

For now, use a format string:

debug('%O', error); // 'O' as in 'Open', not a zero.

This will get fixed in the future.

I get the same behaviour using the make-error-cause package:

process.env.DEBUG = '*'

const log = require('debug')('test');
const { BaseError } = require('make-error-cause');

const cause = new Error('This is the cause!');
const error = new BaseError('This is the error!', cause);

log("---------")
log(error);
log("---------")
log("%O", error);

2019-07-05T20:26:56.917Z test BaseError: This is the error!
    at ...

2019-07-05T20:26:56.918Z test BaseError: This is the error!
    at ...

The following exception was the direct cause of the above exception:

Error: This is the cause!
    at ...