Add structured logging

[cablett]

I added a structured logger based on @ZJvandeWeg 's earlier PR.

I called it structured_logger but I'm happy to call it something else if you feel that's a bit unwieldy.

Thank you for all your work on this gem @tpitale !

[cablett]

cc/ @stanhu @godfat @ZJvandeWeg

[ZJvandeWeg]

Good direction, my main comment is that I'd input hashes only when using structured logging. That allows for better indexing. Thanks for iterating on my work! 💯

[engwan]

Basically the same comments with @ZJvandeWeg 😄

[cablett]

Thanks @engwan and @ZJvandeWeg ! I'll get those pushed up. Great feedback!

[tpitale]

@cablett Thank you for this PR!

I'd like to step back a bit, and understand: what is problem you're trying to solve?

[tpitale]

Have you looked at existing structured logging options?

1. https://github.com/tilfin/ougai
2. https://github.com/rocketjob/semantic_logger

[stanhu]

what is problem you're trying to solve?

I think it's twofold:

1. Make it easier to debug something if the configuration is wrong.
2. Increase observability in production. For example, we might want to check when the last message was pushed into Redis by mail_room or how many messages were unread when mail_room started. Right now we are using an IMAP Prometheus exporter to get the latter.

Either gem look like they would do the job, and their JSON formatters look similar to what is proposed here. However, this is a pretty lightweight implementation, and the other options require a bit more configuration and add another dependency. Would you prefer to use one of those gems?

[tpitale]

Thank you @stanhu.

So, this is a bit complex, and unfortunately @cablett, you've kind of stumbled into something that has been on my mind for months, if not years.

In summary, I want to get this right. The way I've been thinking about it for quite some time (and obviously, never gotten around to implementing) is two-fold:

1. If there is a misconfiguration, mail_room should crash and provide good information about the crash. So, if you've experienced some sort of misconfiguration, especially one that did not crash, I'd love to hear more about it in an issue.
2. Logging is only one thing I (personally) have wanted to do with this kind of information. Perhaps I want to log to statsd, or use something like sentry, or any number of other services.

So, to handle these I imagine there are 3 things I'd like to do:

1. crashes should provide good information
2. I've been loving erlang/elixir's use of telemetry, the closest thing I've experienced in Ruby is ActiveSupport::Notifications which I also like, but I'm not sure works as a standalone library. If something like this would be available we could "instrument" mail_room and then …
3. Configurable subscribers, where structured logging would be included out of the box

And, just to make it more challenging: mail_room mostly being run from the CLI can make hooking into these services very difficult. This brings up the challenge of extensibility when working with a CLI. Do we allow loading of arbitrary Ruby files to enable people to write their own subscribers to this telemetry information? Or, do we require people to use MailRoom as a library in their own software?

So … all that said, I'm happy to review the details of, and merge, this PR. But, I will likely be requesting changes in service of future work. I will, however, try to begin this work very soon (hopefully this coming weekend).

OR, if you're okay with it, I can carry this information into an issue, and start a design proposal to gather feedback; and close this PR.

[tpitale]

As far as dependencies go, I'm not terribly worried about it, beyond looking at the dependencies of mail_rooms dependencies.

In the case of https://github.com/tilfin/ougai they depend on some sort of JSON encoder/decoder and use oj. If this were configurable I'd feel better, as this is another C library. We already require a C extension with charlock_holmes which I have thought about trying to make optional. It might be possible to also make ougai optional.

https://github.com/rocketjob/semantic_logger requires concurrent-ruby which is quite a large library, but has no dependencies of its own.

[tpitale]

Increase observability in production.

@stanhu if you have time, I'd love to hear more examples of this kind.

What I have so far; we want stats/info for:

• around the state of the mailbox as we interact (e.g., unread count when first starting)
• about the interactions with the mailbox
• about interactions with the message receiver (e.g., the result of each type of delivery_method)

[cablett]

Thank you so much for this @tpitale ! It really helps at the moment to have a glimpse into the information that mail_room can provide, because it's rather opaque at the moment. If this solution is at least acceptable (though perhaps not the ideal), it would still be an improvement.

I suppose what I'm saying is that I'd like to get this merged, as it would satisfy a pain point at present. If you do decide to merge, we can continue to discuss how to iterate on it, which may involve tearing out this logging at a later date (if turns out to be a local maxima), or making it one of several configurable options, etc.

Thanks for the shoutout to telemetry, I'd not used that. I'll check it out for sure. 😄

[tpitale]

@cablett Great, I'll do a quick review of this, and you can maybe rebase on master as there will be a few CI fixes that should help with the Travis failures.

[tpitale]

Yeah, I think this looks great. Only really two requests:

1. try to switch to a non-global logger to a per-mailbox (or disabled) logger config
2. have a no-cost disabled logger option

Thanks @cablett!

[cablett]

Many thanks @tpitale ! I'll do my best to get those done today. Thank you again for your work on this ✨

[cablett]

All looking better now, thanks for those requirements. I think it might be ready now. Would you please have another look? (I realised I resolved some discussions but you might not consider them resolved - please feel free to un-resolve if you have further comments) ✨

[cablett]

The only unresolved thought I have remaining about this is that I had to take out the line in the spec_helper.rb that prevented the test runs from creating new logfiles or polluting stdout with logging rubbish. Do you have a suggestion for how we can do this without a singleton logger?

[tpitale]

Where does this get called?

[tpitale]

Actually, looking at the internals of Logger, if @logdev is nil, it is a noop already. We don't need to add any special code.

Sorry for making you do that. This can come out.

[tpitale]

I think I'll merge this, and then I can just remove this in another commit.

[tpitale]

Thank you @cablett! 💛💙❤️

[stanhu]

@stanhu if you have time, I'd love to hear more examples of this kind. What I have so far; we want stats/info for:

around the state of the mailbox as we interact (e.g., unread count when first starting)
about the interactions with the mailbox
about interactions with the message receiver (e.g., the result of each type of delivery_method)

Yes, that's probably the bulk of it for now. We actually also care about unread count sampled throughout the day, just in case we need to alert on the inbox growing without bound for some reason.