Logs from request crash do not follow the configured Logger's format, nor carry over any metadata
hubertlepicki opened this issue · 3 comments
I am not sure which thing is to blame as I updated a bunch of libraries + switched to Bandit in the same round, but since that I noticed that some of the log lines that I'd expect to be logged as error are not marked as one in our DataDog panel.
We're using Gigalixir, with DataDog attached as syslog drain, so I think the problem is that these log lines are not logged with log level = error:
As you can see, logs from other places in the system are properly logged as errors (maked in red), it's just when the request handler crashes on something like parsing JSON or parsing multipart body (i.e. in Plug.Parsers) that I don't see it as error
Is there a Bandit configuration I should change or you folks think it's unrelated and I should look for problem elsewhere?
Bandit intentionally does very little logging on its own; along with Thousand Island they both strongly embrace 'let it crash' as a general policy and so most of the logging you will see comes from the BEAM logging a Bandit process crash. The stacktrace lines in your logs are coming directly from the BEAM, so configuring the level they're logged at is a VM concern concern and specifically not something that Bandit has any configuration for on its own.
I'm not entirely sure where to go to change the level that the BEAM logs crashes at (I'd love to learn, though!). Curiously if I crash a process in an iex session the whole things gets logged as error:
As an aside, this has been a pervasive source of user issues; Cowboy generally silently swallowed errors with no logging of any kind, so when folks switch to Bandit they'll often start seeing crashes and stack traces that have always been there, but never got surfaced.
@hubertlepicki did you find any success with setting logging levels in the BEAM directly? I'd love to have a consistent story to tell folks that bring this up
@mtrudel actually the log levels and format are correct. The problem are in my case the multi-line log statements that are logged, with no span/tracing info attached and DataDog cannot figure it out.
If you look at the screenshot you provided you can see that only the first line has the formatter-provided timestamp and [error] level, the rest of the report is underneath. There are several ways to fix this:
- you can write a custom Console Logger formatter that would split the log multi-line log messages and format each line separately
- you can use this custom logger formatter, that follows Heroku's log format that does precisely that https://hex.pm/packages/logfmt_ex
but we decided to switch to the structured logging using JSON and this library https://github.com/Nebo15/logger_json
So far this is running fine on staging, but I consider the issue resolved as I can see the nicely formatted logs being detected as Errors in DataDog.
This issue can remain closed as it turned out that it didn't have any fault on the Bandit side.