Print an error to console when fails to deliver a log event to Loggly

[alfasin]

We experienced issues were many log events are missing in Loggly control-panel.
Hippo would appreciate it if you can pick up this PR in order for us to be able to debug it on our side and see if the failures are due to network errors or if the logs were submitted properly and failed to get digested on Loggly's side.

This is also implemented in PT transport:
https://github.com/kenperkins/winston-papertrail/blob/master/lib/winston-papertrail.js#L482

and would probably help other users debug issues in the future!

[domainio]

+1

[mgordonathippo]

+1

[Katulus]

@alfasin , have you tested this change yourself? Because I was testing various possible errors such as 403, 502, 404 and only 404 (not found) triggers the code you added. 502 error causes retries that log something like (notice "attemptNumber":2 that increases with each retry):

sendInputLogs: {"msgs":"{\"level\":\"info\",\"message\":\"Hello World from Node.js!\",\"timestamp\":\"2020-07-20T07:24:04.805Z\"}","attemptNumber":2,"sleepUntilNextRetry":4000,"id":1}
requestOptions: {"uri":"<URL>","method":"POST","headers":{},"proxy":null,"body":"{\"level\":\"info\",\"message\":\"Hello World from Node.js!\",\"timestamp\":\"2020-07-20T07:24:04.805Z\"}"}

and 403 logs

Error: Loggly Error (403): Forbidden
    at Request._callback (/home/katulus/windston-test/node_modules/node-loggly-bulk/lib/loggly/common.js:206:31)
    at Request.self.callback (/home/katulus/windston-test/node_modules/request/request.js:185:22)
    at Request.emit (events.js:198:13)
    at Request.<anonymous> (/home/katulus/windston-test/node_modules/request/request.js:1154:10)
    at Request.emit (events.js:198:13)
    at IncomingMessage.<anonymous> (/home/katulus/windston-test/node_modules/request/request.js:1076:12)
    at Object.onceWrapper (events.js:286:20)
    at IncomingMessage.emit (events.js:203:15)
    at endReadableNT (_stream_readable.js:1145:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)

bub none of these run through the callback you modified.

[alfasin]

@Katulus you're right: I tested it by starting to run the project and disconnect the wifi, the error I got is ENOTFOUND

Sounds like there are other cases that are not handled there, any idea how those cases should be handled?
I'd love to add them to this PR as well if possible - any idea where is the code that needs to be changed for that?

Could it be that these changes are needed to be implemented in node-loggly-bulk instead of here?.

[Katulus]

@alfasin , correct, node-loggly-bulk sends logs via this method or this method and it does most of error handling there. As you can see it does retry for most of the errors so if you get for example 502 from Loggly randomly then this retry logic should handle that and send the logs eventually. I'm not sure if it's a good idea to add fixed logging there since most of those intermittent errors are handled by retry logic. If you really want to be notified I would do that via some optional callback where you can do your own logging in your application.

[alfasin]

@Katulus sounds good!
I wasn't able to find documentation for submitting such a callback to Loggly transport. Do you have a pointer to such an example?

[Katulus]

@alfasin , it's not something you can easily do today. There is no API for that since it's hidden behind Winston Transport anyway. You don't have direct access to it, you would have to expose it in some way.
So let's go back to your original requirement - what exactly are you trying to troubleshoot? Since node-loggly-bulk retries in case of failure it's unlikely that particular event would be lost if Loggly occasionally returns 502.

[alfasin]

@Katulus if you have access to the support tickets in Loggly you'll be able to see all the details in Case # - 00566904.
To summarize it: we're missing log events in Loggly, I can't tell the frequency but as an example: we have a daily job that "losses" a print once in a while.

We know that for sure because:

1. the execution path requires that these log lines will be executed
2. the console transport does print that same log lines (in the same executions where we're seeing it's missing in Loggly)

It already happened a few times, it happens ~ once every 3-4 days in that example. And we saw other examples as well.

This is the motivation for having a console.err print when all retries got exhausted or if anything else "bad" happened.

WDYT?

[Katulus]

@alfasin , can you hardcode the logging on your side by direct modification of locally downloaded node module in your app? I'm OK with adding extra logging if we know it provides the value, but so far it's more "trial and error" so I'd like to avoid doing it in official released version.

[alfasin]

@Katulus this is not trial and error, further, printing error to console when failing is something that makes sense to do and as I showed above, PT are doing it as well.

Changing code under node_modules is not an option I have.

[Katulus]

@alfasin that's a fair statement. Let's move on with this PR then. Are you going to create PR for node-loggly-bulk as well to cover more error states?

[alfasin]

Yes I'm looking into it as well, I'll ping you when I do.

Thanks a bunch!

[alfasin]

@Katulus can we merge this PR?

[Katulus]

@alfasin , sorry, I was on PTO last week. I just merged the PR and released the new version 3.1.1 with the change.