roidrage / lograge

An attempt to tame Rails' default policy to log everything.
http://www.paperplanes.de/2012/3/14/on-notifications-logsubscribers-and-bringing-sanity-to-rails-logging.html
MIT License
3.47k stars 300 forks source link

custom_payload is "persisted' (or per se kept) between 2 requests #358

Closed ngouy closed 2 years ago

ngouy commented 2 years ago

if I start to have conditional things I want to sho on my payload based on the controller "type", or how it's shaped, there is a concerning issue: the data that isn't "overwritten" is kept between 2 requests

Example:

code:

# initializers/lograge.rb
Rails.application.configure do
  config.lograge.custom_payload do |controller|
  custom_payload = {}

  custom_payload[:test] = 123
  custom_payload[:respond_to_current_user] = controller.respond_to?(:current_user)

  if controller.respond_to?(:current_user)
    custom_payload[:user_id] = controller.current_user&.id
  end

  custom_payload
end

let's now have 2 consecutive calls, one to a controller that define a current user, and another that has no current user

the first one will have

 test: 123
 respond_to_current_user: true
 user_id: 456

And the second one

 test: 123
 respond_to_current_user: false
 user_id: 456 # oopsie
ngouy commented 2 years ago

I might be wrong, but it might be because of that here https://github.com/roidrage/lograge/blob/c737a13779fef5c2b6050ce9356fd7acb86a8905/lib/lograge/log_subscribers/base.rb#L73 options.merge event.payload[:custom_payload] || {}

what we might want may be options.deep_dup.merge event.payload[:custom_payload] || {}

Otherwise we effectively "definitely" (until further re-write) merge the custom payload to the @@custom_options, which is not what we want

ngouy commented 2 years ago

So. Definitly not the issue. .merge doesn't commit anything (.merge! does)

Not sure if it (and so how) it's specific to our own config or not, but when I try to fork and build failing example (in order to send the part that is supposed to fix it), can't reproduce

ngouy commented 2 years ago

more context: Looks like this happens when we pop threads into a request. Somehow - the child threads, or main thread hanging while child threads resolve - that pick up next query have polluted logs

ngouy commented 2 years ago

So the issue was threading + usage of OGAI with_fields method wrapped in an "around_action" Issue was it affects the shared Logger

https://github.com/tilfin/ougai/issues/107