search

shadabahmed / logstasher

Awesome rails logs
MIT License
817 stars 136 forks source link

ActiveJob::Logging::LogSubscriber not being unsubscribed #149

Open owenbendavies opened 5 years ago

owenbendavies commented 5 years ago

When suppress_app_logs is set ActiveJob still has the default logs so I get double logs, e.g.

2019-04-28T10:11:26.013041+00:00 app[web.1]: {"method":"POST","path":"/contact_me/contact_form","format":"html","controller":"pages","action":"contact_form","status":302,"duration":133.44,"db":0.0,"location":"https://example.com/contact_me","route":"pages#contact_form","request_id":"86359372-4aed-4d8f-8a4c-2b3af98d6985","cf_ray":null,"country":null,"host":"example.com","user_id":"8f5f80bb-ab88-4c3b-ad0b-411845eea23f","user_agent":"Mozilla/5.0","fwd":"192.168.1.1","source":"unknown","tags":["request"],"@timestamp":"2019-04-28T10:11:26.011Z","@version":"1"}
2019-04-28T10:11:26.010396+00:00 app[web.1]: {"job_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","queue_name":"DelayedJob(mailers)","job_class":"ActionMailer::DeliveryJob","job_args":["NotificationsMailer","new_message","deliver_now","gid://cms/Message/3"],"request_id":"86359372-4aed-4d8f-8a4c-2b3af98d6985","cf_ray":null,"country":null,"host":"example.com","user_id":"8f5f80bb-ab88-4c3b-ad0b-411845eea23f","user_agent":"Mozilla/5.0","source":"unknown","tags":["job","enqueue"],"@timestamp":"2019-04-28T10:11:26.009Z","@version":"1"}
2019-04-28T10:11:29.221889+00:00 app[worker.1]: {"message":"2019-04-28T10:11:29+0000: [Worker(host:23c9a41b-5a8b-4337-844f-e964f40c3bfb pid:4)] Job ActionMailer::DeliveryJob [3dfe8830-ac51-479d-90a5-e1b8e83edcde] from DelayedJob(mailers) with arguments: [\"NotificationsMailer\", \"new_message\", \"deliver_now\", {\"_aj_globalid\"=\u003e\"gid://cms/Message/3\"}] (id=181) (queue=mailers) RUNNING","@timestamp":"2019-04-28T10:11:29.221+00:00","@version":"1","severity":"INFO","host":null,"fwd":null,"request_id":null,"tags":["rails"]}
2019-04-28T10:11:29.227308+00:00 app[worker.1]: {"job_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","queue_name":"DelayedJob(mailers)","job_class":"ActionMailer::DeliveryJob","job_args":["NotificationsMailer","new_message","deliver_now","gid://cms/Message/3"],"request_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","source":"unknown","tags":["job","perform_start"],"@timestamp":"2019-04-28T10:11:29.227Z","@version":"1"}
2019-04-28T10:11:30.500933+00:00 app[worker.1]: {"request_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","mailer":"NotificationsMailer","action":"new_message","source":"unknown","tags":["mailer","process"],"@timestamp":"2019-04-28T10:11:30.500Z","@version":"1"}
2019-04-28T10:11:30.792405+00:00 app[worker.1]: {"request_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","mailer":"NotificationsMailer","message_id":null,"from":["noreply@example.com"],"to":["email@example.com","another@example.com"],"source":"unknown","tags":["mailer","deliver"],"@timestamp":"2019-04-28T10:11:30.790Z","@version":"1"}
2019-04-28T10:11:30.792820+00:00 app[worker.1]: {"job_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","queue_name":"DelayedJob(mailers)","job_class":"ActionMailer::DeliveryJob","job_args":["NotificationsMailer","new_message","deliver_now","gid://cms/Message/3"],"duration":1565.08,"request_id":"3dfe8830-ac51-479d-90a5-e1b8e83edcde","source":"unknown","tags":["job","perform"],"@timestamp":"2019-04-28T10:11:30.792Z","@version":"1"}
2019-04-28T10:11:30.807098+00:00 app[worker.1]: {"message":"2019-04-28T10:11:30+0000: [Worker(host:23c9a41b-5a8b-4337-844f-e964f40c3bfb pid:4)] Job ActionMailer::DeliveryJob [3dfe8830-ac51-479d-90a5-e1b8e83edcde] from DelayedJob(mailers) with arguments: [\"NotificationsMailer\", \"new_message\", \"deliver_now\", {\"_aj_globalid\"=\u003e\"gid://cms/Message/3\"}] (id=181) (queue=mailers) COMPLETED after 1.5846","@timestamp":"2019-04-28T10:11:30.806+00:00","@version":"1","severity":"INFO","host":null,"fwd":null,"request_id":null,"tags":["rails"]}
2019-04-28T10:11:30.811585+00:00 app[worker.1]: {"message":"2019-04-28T10:11:30+0000: [Worker(host:23c9a41b-5a8b-4337-844f-e964f40c3bfb pid:4)] 1 jobs processed at 0.6272 j/s, 0 failed","@timestamp":"2019-04-28T10:11:30.811+00:00","@version":"1","severity":"INFO","host":null,"fwd":null,"request_id":null,"tags":["rails"]}

I have done some digging and in https://github.com/shadabahmed/logstasher/blob/master/lib/logstasher.rb#L44 events reuturns an array of items, but for ActiveJob::Logging::LogSubscriber it returns an empty array.

Unfortunately I'm not quite sure why this is different.

Thank you, Owen

piotrb commented 4 years ago

There is now a cleaner system in Rails 6 (and possibly earlier) to unsub .. 

ActiveJob::Logging::LogSubscriber.detach_from(:active_job)

I Imagine the same mechanism can be used for most of the other log subscribers