search

reidmorrison / rails_semantic_logger

Rails Semantic Logger replaces the Rails default logger with Semantic Logger
https://logger.rocketjob.io/rails
Apache License 2.0
330 stars 117 forks source link

Use Sidekiq.logger when Sidekiq::Logging is unavailable #95

Closed bobvanderlinden closed 5 years ago

bobvanderlinden commented 5 years ago

Issue # (if available)

Resolves #94

Sidekiq 6.0 has deprecated usage of Sidekiq::Logger. Sidekiq::Logger is an internal module which applications should not be using. Instead applications should be using Sidekiq.logger, as is documented here: https://github.com/mperham/sidekiq/wiki/Logging#api-changes

Description of changes

This PR attempts to stay backwards compatible by keeping the existing behaviour when Sidekiq::Logging still exists and use Sidekiq.logger when Sidekiq::Logging doesn't exist (which should be the case for Sidekiq 6.0+).

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

MisterFine1 commented 5 years ago

That build appears to have solved the startup issue -- but I ran into a new one. When I ran Sidekiq 6.0, during a job, it generated that following error:

NoMethodError: undefined method `with_context' for #

I'm looking into why now...

MisterFine1 commented 5 years ago

I opened an issue on sidekiq: https://github.com/mperham/sidekiq/issues/4239

gingerlime commented 5 years ago

@MisterFine1 thank you for pushing this forward. Did the posted workaround help?

gingerlime commented 5 years ago

I saw that Sidekiq 6.0.1 was released with the changes that @bobvanderlinden proposed. Can we get this PR ready/merged any time soon? :)

bobvanderlinden commented 5 years ago

Nice. Yes, the current state of the PR should be working for Sidekiq 6.0.1. It might also be simplified to:

Sidekiq.logger = SemanticLogger[:Sidekiq] if defined?(Sidekiq)

As @mperham mentioned Sidekiq.logger is available in Sidekiq for quite some time. It was apparently added back in 2012: https://github.com/mperham/sidekiq/blob/8c9f960a687d234cdee3396117484bc3c92f3219/lib/sidekiq.rb#L94-L96

Shall I just remove all traces of Sidekiq::Logging.logger in this PR?

gingerlime commented 5 years ago

sounds good to me @bobvanderlinden ! Do you have merge rights on this project though? or I guess we'll have to wait for @reidmorrison, right?

Happy to test this PR when you're ready :) thanks again for your patience and coordinating this whole thing 💯

bobvanderlinden commented 5 years ago

Alright, changed the PR to always use Sidekiq.logger.

@reidmorrison could you do a review?

Also, currently we do not incorporate the Sidekiq::Context.current into the logs. It would be nice as a follow-up PR to add this information as well. @reidmorrison could you give a suggestion on how to dynamically add named_tags to all log lines of a certain logger instance?

gingerlime commented 5 years ago

@bobvanderlinden I tested this PR with sidekiq 5.2.7 as well as sidekiq 6.0.1 and it seems to work well 👍

+1 for integrating context into the logs. I currently use a custom middleware for it, but I think it would be much easier for lots of people if this works out of the box! 👍 🥇

gingerlime commented 5 years ago

also, and sorry, I don't want to hijack this thread (maybe I'm also doing something wrong?), but I seem to get a couple of fairly "useless" log entries for sidekiq that I can't fully understand or get rid of...

specifically, I can see an empty "sidekiq start" log, followed by another start with a bit more info (job name, JID)... and same goes for the "sidekiq done" log.

sample initial log entries

2019-10-03 10:26:46.553831 INFO name=Sidekiq message=start payload=null tags= named_tags= duration= process_info=153:processor exception=
2019-10-03 10:26:46.564567 INFO name=Sidekiq message=start payload=null tags=[TasksLauncher JID-fe5bd736c7a45019eebac9c4] named_tags= duration= process_info=153:processor exception=

... here there are some logs from the worker itself if it logs anything ...

then at the end

2019-10-03 10:26:47.202250 INFO name=Sidekiq message=done: 0.638 sec payload=null tags=[TasksLauncher JID-fe5bd736c7a45019eebac9c4] named_tags= duration= process_info=153:processor exception=
2019-10-03 10:26:47.202440 INFO name=Sidekiq message=done payload=null tags= named_tags= duration= process_info=153:processor exception=

Perhaps related to my middleware?

bobvanderlinden commented 5 years ago

Maybe that's related to measure and log lines? I'm not sure, but would I consider it a separate issue.

gingerlime commented 5 years ago

Yes, you're right. It's definitely unrelated. Hope we can merge this in, and then I can try to play around with this middleware again. Or maybe if the project is ok with it, adding the sidekiq context would remove the need for this middleware entirely.

gingerlime commented 5 years ago

@reidmorrison see https://github.com/rocketjob/rails_semantic_logger/pull/95#issuecomment-537836013

As @mperham mentioned Sidekiq.logger is available in Sidekiq for quite some time. It was apparently added back in 2012: https://github.com/mperham/sidekiq/blob/8c9f960a687d234cdee3396117484bc3c92f3219/lib/sidekiq.rb#L94-L96

I personally tested it with Sidekiq 5.2.7 and 6.0.1 and both worked.

bobvanderlinden commented 5 years ago

The first commit of this PR keeps compatibility. See https://github.com/rocketjob/rails_semantic_logger/pull/95/commits/91466a5706d6a97af14ab64577e0f31199166989

The second commit removes compatibility for Sidekiq < 1.2.1. That's for versions more than 7 years old.

The maintainer of Sidekiq (@mperham) suggested to use Sidekiq.logger without relying on the internal logger (Sidekiq::Logger.logger).

Should I add a fallback for using the internal logger again?

gingerlime commented 5 years ago

I don't think this project should support backwards compatibility for > 7 years, nor use internal methods, especially if public ones are available and exposed. +1 for merging this as-is.

EDIT: I think @bobvanderlinden is saying the same thing, but in much more diplomatic way :)