Using a catch-all console logger does not log debug errors

[Calavoow]

I have registered good with good-console as a logging for my hapi server using the following options

const goodOptions = {
    ops: {
        interval: 1000
    },
    reporters: {
        console: [{
            module: 'good-console'
        }, 'stdout']
    }
};

And an endpoint defined as

module.exports = [{
    method: 'GET',
    path: '/boom',
    handler: function(request, reply) {
        reply(Boom.notFound("Foobar"));
    },
    config: {
        tags: ['api']
    }
}];

I am getting log statements in my console of the following form:

160722/143315.254, [ops] memory: 58Mb, uptime (seconds): 1.629, load: [0.42626953125,0.4453125,0.29833984375]
160722/143315.365, [response] http://localhost:3000: get /boom {} 404 (44ms)
160722/143316.257, [ops] memory: 59Mb, uptime (seconds): 2.634, load: [0.42626953125,0.4453125,0.29833984375]

But in reality another event was emitted by responding with a Boom object. In a second run with debugging enabled in hapi as follows:

const logTags = ['fatal', 'error', 'info', 'debug', 'trace'];
const server = new Hapi.Server({
    debug: {
        request: logTags,
        log: logTags
    }
});

I get the following logs:

160722/143251.118, [ops] memory: 60Mb, uptime (seconds): 1.602, load: [0.64892578125,0.4853515625,0.30810546875]
Debug: handler, error 
    {"msec":1.5427689999341965,"error":"Foobar","data":{"data":null,"isBoom":true,"isServer":false,"output":{"statusCode":404,"payload":{"statusCode":404,"error":"Not Found","message":"Foobar"},"headers":{}}}}
160722/143252.084, [response] http://localhost:3000: get /boom {} 404 (39ms)
160722/143252.127, [ops] memory: 61Mb, uptime (seconds): 2.614, load: [0.64892578125,0.4853515625,0.30810546875]

I expect handler errors and other hapi errors also to be logged to the console when using the good-console logger. Since I did not filter any events with good-squeeze, shouldn't these event also be logged by the logger?

Error events for e.g. authentication failing also are not logged.

P.S. Your guidelines has a dead link to the issue form (https://github.com/spumko/good/issues/new)

[Calavoow]

Adding an extensions option does not help much, e.g.

const goodOptions = {
    ops: {
        interval: 5000
    },
    reporters: {
        console: [{
            module: 'good-console'
        }, 'stdout']
    },
    extensions: ['request-internal']
};

Does report more events, but none of them are useful. Adding request-error to the extensions results in a crash with a vague error message.

[arb]

Fixed the issue link. I forgot about it and I didn't think anyone used it anymore :-D

good is limited by the events hapi emits. So if hapi isn't emitting "request-error" in this scenario there isn't much I can really do about it. We may have to look into hapi internals to see what causes this particular error to be specifically logged.

What is the vague error when you try to add 'request-error' to extensions? Probably a validation error I would assume.

[Calavoow]

I get the following error:

Error: Invalid monitorOptions options child "extensions" fails because ["extensions" at position 1 fails because ["1" contains an invalid value]]
    at Object.exports.assert (.../node_modules/hoek/lib/index.js:732:11)
    at Object.exports.register (.../node_modules/good/lib/index.js:31:10)
    at Object.target [as register] (.../node_modules/hapi/node_modules/joi/lib/object.js:79:30)
    at each (.../node_modules/hapi/lib/plugin.js:317:14)
    at iterate (.../node_modules/hapi/node_modules/items/lib/index.js:36:13)
    at done (.../node_modules/hapi/node_modules/items/lib/index.js:28:25)
    at Object.exports.register (.../node_modules/vision/lib/index.js:57:12)
    at Object.target [as register] (.../node_modules/hapi/node_modules/joi/lib/object.js:79:30)
    at each (.../node_modules/hapi/lib/plugin.js:317:14)
    at iterate (.../node_modules/hapi/node_modules/items/lib/index.js:36:13)
    at done (.../node_modules/hapi/node_modules/items/lib/index.js:28:25)
    at each (.../node_modules/hapi/lib/plugin.js:268:28)
    at iterate (.../node_modules/hapi/node_modules/items/lib/index.js:36:13)
    at Object.exports.serial (.../node_modules/hapi/node_modules/items/lib/index.js:39:9)
    at internals.Plugin.register (.../node_modules/hapi/lib/plugin.js:320:11)
    at Object.<anonymous> (.../app.js:108:8)

I cannot apply good logging to our projects if its not possible to log these error messages, because they contain critical information. For example, when you reply with reply(Boom.xxx("msg", data)) none of that is logged.

[Calavoow]

If I add

server.on('request-internal', (req, event, tags) => {
    console.log(event);
});

to my application, and request an endpoint with

{
    method: 'GET',
    path: '/boom',
    handler: function(request, reply) {
        reply(Boom.notFound("Foobar"));
    },
    config: {
        tags: ['api']
    }
}

I do get a console print of the error. So it should be possible to log these message by just using resuest-internal events.

[arb]

Yea so that's the validation error I was expecting - you can't add extensions for the "request-error" event because it's already being used. Code

As far as "request-internal" you can certainly listen for that. The reason it's not used directly in good is because that event happens multiple times per request. So the filtering rules would get a little complicated... if you want to use that extension, you'll need to write up your own transform stream to make sense of that event.

It shouldn't be too hard - you can probably get what you want by looking at a combination of tags and event.

[Calavoow]

The logs I get (without any filtering rules) with the extension request-internal are not the log results that I'm looking for. Please refer to my second comment for my configuration.

[arb]

As I said https://github.com/hapijs/good/issues/506#issuecomment-234940311, "request-internal" is your path to get this event. good-console is not configured to format "request-internal" in a really usable way. You'll need to write your own transform stream to do that.

I added an extension to good of ["request-internal"] and put a debug statement in the _transform method of good-console.

When the second "request-internal" (because it happens more than once) happens, data.payload[2] is equal to { error:true, handler:true } which means there was the handler error you are talking about. If I examine data.payload[1].data at this same debug point in time, it is equal to

{
  "msec":0.5626409947872162,
  "error":"Foobar",
  "data":{
    "data":null,
    "isBoom":true,
    "isServer":false,
    "output":{
      "statusCode":404,
      "payload":{
        "statusCode":404,
        "error":"Not Found",
        "message":"Foobar"
      },
      "headers":{

      }
    }
  }
}

which is all of the values you need to mimic the debug statement of the hapi server.

So, good-console is getting the event, and everything needed to print that message, but is not designed to handle "request-internal". If you are set on using that event, you'll need to implement your own transform stream for dealing with "request-internal" payloads.

[lock[bot]]

This thread has been automatically locked due to inactivity. Please open a new issue for related bugs or questions following the new issue template instructions.