custom_options with Rails.logger.error

[aaronbartell]

I am using Rails.logger.error "some error" in my controller's action. I can see the resulting JSON-formatted log in development.log but it completely bypassed the custom_options code where I add in the params values.

Is this working as designed?

Rails 5.0.x

[dleavitt]

I'll take a stab at this one, as I believe it's working as designed here:

Lograge doesn't mess with direct calls to a logger. It functions by capturing a lot of the events that Rails uses to trigger log writes and silencing them or incorporating them into its own log output.

I think the point of Lograge is sort of "one log line per request" but if you wanted to log your own messages in its format, you could imitate what it's doing here:
https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscribers/base.rb#L22-L23

[kkohrt]

@dleavitt Thanks for the response.
I think we are looking at it not so much as lograge messing with other messages, but the ability for other messages to be inserted into the lograge output.

A specific use case is an exception in the middle of the request/response cycle. Because lograge does not mess with it, the exception hits the logs immediately--before the lograge entry that marks end of request response cycle + its duration. As a result, you then need to check the lograge timestamp and subtract the duration value in order to see if the stacktrace entry falls in the request/response window and may have, in fact, been caused by that particular request.

What I was looking for was the ability to "annotate" the lograge entry on the fly, as it were, so I could capture an error and have some messaging inserted into the logs as part of the request/response log entry in order to definitively connect the cause and the effect.

Granted, we use json formatted logs plus a log aggregator, so having "one log line per request" be a very long log line is not as much of a concern for us as having error messaging dropped in the context as the request/response log entry.

It felt like you were suggesting that a 2nd log entry be created with the same request/response info, but would you say that if we add info to the ActionController payload by overloading
https://github.com/rails/rails/blob/master/actionpack/lib/action_controller/metal/instrumentation.rb#L87-L102
we could then use a custom data extractor and formatter to pull it out again and log whatever we want?
https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscribers/base.rb#L21-L22

[locofocos]

I think the point of Lograge is sort of "one log line per request" but if you wanted to log your own messages in its format, you could imitate what it's doing here:
https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscribers/base.rb#L22-L23

I tried @dleavitt 's suggestion. That does bring in the same "format", in that you'll get something like

key1=value1 key2=value2

but that's really missing the heart of what the original request is. There's useful information (like user_id) that I've set up via config.lograge.custom_options and append_info_to_payload(payload), and this suggestion doesn't pull in those fields. These fields are pulled into our default rails logs, so we get those instrumented on every request (for example). But I want those fields to be included on lines when I call rails.logger.error.

For us to use

lograge/lib/lograge/log_subscribers/base.rb

Lines 22 to 23 in 1729eab

	formatted_message = Lograge.formatter.call(data)
	logger.send(Lograge.log_level, formatted_message)

as an example for how to include custom_options in our output from rails.logger.error, we would have to execute Lograge::LogSubscribers::Base.extract_request, specifically the line data.merge!(custom_options(event)). I don't know how to get the event variable though in order to extract the custom options.

I'm excited to see if #303 can be revived in order to offer this functionality though!

Thanks for all the work the team has put into this so far.