Logging Errors

[KeKs0r]

Hi,

I have realized, that logging Errors with server.log is not having the expected result. I have first created a issue with good-logentries, since I thought the issue could be addressed there, but it seems that its could be fixed in good: https://github.com/colonyamerican/good-logentries/issues/4

My problem is, that I have some batch and background operations, that might fail. And I want to log them, but they might be outside a request. So what I do is:

server.log(['error'], new Error('My Error, and I would like to know, where I am from');

But currently I only see errors, without really understanding where they are coming from, since the error stacktrace is missing.

3 Dec 2015 09:22:13.584 { "event": "log", "timestamp": 1449130933582, "tags": [ "job", "error", "schedule" ], "data": { "name": "Error", "message": "job \"176728\" doesnt exist" }, "pid": 37 }

I think it would be a good idea to check if the logged data is an instance of error (Here: https://github.com/hapijs/good/blob/master/lib/utils.js#L31-L44) and if so also include the stacktrace to the logged object.

If you guys agree I would be more than happy to provide an PR.

[arb]

Why not just log a string or regular object instead of an Error object? Seems a little unusual to manually create an error object and want to log that. Also if you REALLY want an error you could try throwing an error from the handler but I wouldn't really recommend that.

[KeKs0r]

I am not creating this error, this was an example. I am logging an Error that bubbles up from some libraries. And I would need the error to have access to the the Stacktrace, Otherwise, I would not know from where the code with the error is called.

I mean, in case of an Error is returned from the response, the Error is also correctly logged with stacktrace, why not allowing the same with normal logs.

[arb]

How does the error bubble up? Are you wrapping it in a try catch block?

Also relating to your PR, that isn't an approach I'm a fan of... the reason I'm using classes and not just sending generic objects is so that the interface is consistent - conditionally adding a value like that sort of breaks that consistency for downstream consumers.

[KeKs0r]

No it is not in a try catch, it is in a normal node callback a la (err, result) => { }

Since it is possible to log objects, how would you like to convert an error object (when logged) into something like:

var origError = new Error('my error message')
// That would than be transformed to something like this:
var objectToLog = {
    error: 'my error message',
    stack: stacktrace // StacktraceObj
}

[arb]

What does your server do with that error? Log it? Reply with it?

[KeKs0r]

The server logs it. Those errors can also be returned (in that case they are logged, since errors in the reply are logged). But most of the cases they are just logged, because they might happen asynchronous.

[arb]

You could try doing

server.log(['error'], {err}) or server.log(['error'], {...err})

depending on your specific server setup. That should get the stack to be logged.

[KeKs0r]

The problem is, that sometimes downstream services give me back Error Objects, sometimes its just a string with an error message, or maybe even other things.

I am not sure, why it is not a good idea to include the Stacktrace of errors by default. Its done if I reply to the user with an error.

I might agree with you, that putting the stack on top level like I did, is not the best idea:

    if(event.data.stack) {
      this.stack = event.data.stack;
    }

But how about something like this:

    if (event.data instanceof Error) {
        this.data = {
            message: event.data.message,
            stack: event.data.stack
        }
    } else {
        this.data = event.data;
    }

Or even:

        this.data = Object.assign({}, error,{
            stack: event.data.stack
        });

If Javascript traces would be attributes and not require invoking the getter, this would already be the default behaviour.

server.log(['error'], {err}) is not solving the issue, trace is still not shown. server.log(['error'], {...err}) is not working for me, even with enabled spread operator in node.

[arb]

const e = new Error('here is your error');
request.server.log(['error'], {
    message: e.message,
    stack: e.stack
});

That'll work. You could create your own Object that extends Error or create some kind of factory function to create these kinds of objects.

This is the very first time this issue has come up which makes me think most people do not log Error object directly via server.log.

[KeKs0r]

I am aware, that this would be a workaround, but I am logging errors in about 100 different places throughout all my plugins. This solution would also require me to know if a downstream service such as libraries, database abstraction, cache abstraction etc. are returning errors. Maybe they are not even concise about it. This would also require me to check everytime I am logging something that I need to check in 100 places if the current error is an actual error object or just something else.

For my use case it makes way more sense to implement it in good. And I think it just adds value. I can't imagine I am the only person "logging errors"

Also this would not change the API or anything for loggers, since I only add one property to the object.

Not sure what the actual reason against implementing this in good, would be. I am already using this in production and it works like a charm, making my error logs 10 times more useful.

I am very open to how we could implement this in good, but I think just having the stracktrace in case of an error is only beneficial.

Alternatively, this would need to be implemented in every downstream logger. Which would also be an option. I will check with the actual logger implementations

[KeKs0r]

Okay found a way to implement this in my main logging service, but still wondering if this is something that all loggers then implemented themselves: https://github.com/logentries/le_node#log-processing-options

[arb]

The reason I'm trying to avoid changing good is for two reasons:

1. It's undergoing a write literally right now
2. You're trying to add something to a class that an ecosystem is using. Can you say, with certainty, that this change won't have any downstream impacts on anything existing in production right now? What if someone is adding their own error value somewhere along the way? (I realize the object is frozen, but there are ways around that if you're determined).

I do agree with you that this is something that could be handled in good, I'm not sure what the right approach is.

Your suggestions above would be acceptable though. Open a PR for that and we can continue the discussion there.

[AdriVanHoudt]

I raised a similar issue on gitter specifically around good-console. Would it be possible to handle errors there (as in log message + stack) since it is mainly used for debugging?

[arb]

Now that good@7 is out, this could easily be handled with an additional transform stream in your pipeline.

[kanongil]

Now that good@7 is out, this could easily be handled with an additional transform stream in your pipeline.

I found https://www.npmjs.com/package/good-errors which does this.

[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.