Unable to Replace GoodJob's Logger

[ylg]

It seems the .logger = Logger approaches (direct on GoodJob and via config) only add to the loggers used by GoodJob. Similarly, having a Rails logger configuring, via config.logger = Logger also seems to cause GoodJob to add Rails' logger to its own rather than replacing. That is, taking these approaches results in the original GoodJob log lines appearing, e.g., [GoodJob] [31176] GoodJob shutting down scheduler in addition to the same messages appearing routed through the additional logger.

tldr; I'm not yet seeing how to remove/replace the logging GoodJob does. Is this possible?

[bensheldon]

That's weird. Can you share how you're configuring the logger?

Both of these quiet the logger for me:

# config/initializers/good_job.rb
GoodJob.logger = Logger.new("/dev/null")
# or
Rails.application.configure do
  config.good_job.logger = Logger.new("/dev/null")
end

This is what I see in my console:

[1] pry(main)> GoodJob.logger
=> #<Logger:0x00000001082d35f8
 @default_formatter=#<Logger::Formatter:0x00000001082d35d0 @datetime_format=nil>,
 @formatter=nil,
 @level=0,
 @logdev=
  #<Logger::LogDevice:0x00000001082d3580
   @binmode=false,
   @dev=#<File:/dev/null>,
   @filename="/dev/null",
   @mon_data=#<Monitor:0x00000001082d3558>,
   @mon_data_owner_object_id=12260,
   @shift_age=0,
   @shift_period_suffix="%Y%m%d",
   @shift_size=1048576>,
 @progname=nil> 

[ylg]

Thanks, knowing this is possible and should just work helped me narrow it down. I find it only presents if I assign a SemanticLogger instance to GoodJob. Assigning vanilla or ActiveSupport loggers to GoodJob don't present this behavior, even if SemanticLogger is used everywhere else. Ideally Semantic on Good would just work too, but making it so is probably well outside the scope of GoodJob!

# Start with:

config.logger = SemanticLogger[Rails]
config.active_record.logger = SemanticLogger::DebugAsTraceLogger.new('ActiveRecord')

# Adding any one of the following lines results in GoodJob log entries 
# appearing exactly once for me as does omitting all and letting GoodJob 
# automatically find and use Rails.logger

GoodJob.logger = ::Logger.new(STDOUT)
config.good_job.logger = ::Logger.new(STDOUT)

GoodJob.logger = ActiveSupport::Logger.new(STDOUT)
config.good_job.logger = ActiveSupport::Logger.new(STDOUT)

# Using either one of the below presents duplicate log entries for GoodJob, with
# one entry going through SemanticLogger's appender(s) and one entry appearing
# to go straight to stdout:

GoodJob.logger = SemanticLogger[GoodJob]
config.good_job.logger = SemanticLogger[GoodJob]

[bensheldon]

Interesting! Thank you for digging into that.

I can't find where SemanticLogger defines SemanticLogger[], but I wonder if this is happening: GoodJob.logger, by default (at least after initialize) is Rails.logger.

good_job/lib/good_job/engine.rb

Lines 10 to 15 in 26d1640

	initializer "good_job.logger" do |_app|
	ActiveSupport.on_load(:good_job) do
	self.logger = ::Rails.logger if GoodJob.logger == GoodJob::DEFAULT_LOGGER
	end
	GoodJob::LogSubscriber.attach_to :good_job
	end

I dunno if when you pass in SemanticLogger[GoodJob] if it does anything to check if that class has a logger already, and then like appends to it 🤷🏻

What happens if instead of passing SemanticLogger a Class, you give it a String?

GoodJob.logger = SemanticLogger["GoodJob"]

[ylg]

Sorry, I missed the reply. Passing a string or the literal class presents the same behavior, i.e., GoodJob carries on with its own logging, in addition to logging with the assigned logger.

[bensheldon]

Hmm. Can you tell me in what file you're assigning the logger?

[ylg]

Last line of application.rb; actually the last line within the class definition, like so:

class Application < Rails::Application
  $stdout.sync = true

  [blah blah blah]

  config.logger = SemanticLogger[Rails]
  config.active_record.logger = SemanticLogger::DebugAsTraceLogger.new('ActiveRecord')
  config.good_job.logger = SemanticLogger['GoodJob']
end

[bensheldon]

@ylg I am stumped 😓 when I add rails_semantic_logger and the configuration to the GoodJob demo app (spec/test_app in this repo), I don't get any of GoodJob's logging at all, and only see the ActiveRecord logging.

One last idea is if you inspect GoodJob::LogSubscriber.loggers in the rails console. This is what I currently see:

[1] pry(main)> GoodJob::LogSubscriber.loggers
=> [#<SemanticLogger::Logger:0x0000000105c96e30
  @filter=nil,
  @level=nil,
  @level_index=nil,
  @name="GoodJob">]

[ylg]

After only a quick look, it seems the value of GoodJob::LogSubscriber.loggers varies a bit. I tried checking it immediately after the assignment config.good_job.logger = SemanticLogger['GoodJob'] and I see an ActiveSupport logger. Checking it in controller method, i.e., in a Puma fork and thread, I see a SemanticLogger. Interestingly, in no case did I ever see the array holding more than one logger, despite the duplicate logging. Maybe threads/processes are involved somehow.

Unfortunately, in trying to look further I ran into what might be an actual bug (unlike this, which I still feel is some horribly convoluted flavor of PEBKAC and/or a SemanticLogger issue).

good_job/lib/good_job/log_subscriber.rb

Lines 209 to 210 in 65dc794

	if each_logger.respond_to?(:tagged) && each_logger.formatter
	tags_for_logger = if each_logger.formatter.current_tags.include?("ActiveJob")

There, GoodJob checks for tagged and for formatter, but then assumes a positive means formatter exposes current_tags, which is not going to be the case always and is not the case with SemanticLogger. Naively, it seems the check should be for the need?

It looks like there was a change addressing this, but the gap between the test and the assumption is still big enough to fail. #502

[bensheldon]

@ylg one more idea: can you set the logger before you do any other ActiveJob or GoodJob configuration? e.g.

# config/application.rb

config.good_job.logger = SemanticLogger['GoodJob']
# or even...
GoodJob.logger = SemanticLogger['GoodJob']
# ... before you assign ...
config.active_job.queue_adapter = :good_job

Regarding whether loggers respond to #tagged, #current_tags, or #formatter, it's all based on gradually learning as bugs get reported. I'm open if you wanted to make a PR that also did feature testing on #current_tags too.

....AHA! I just found something that looks like it could be the culprit. This is in the CLI code:

good_job/lib/good_job/cli.rb

Lines 157 to 163 in cd3618b

	def set_up_application!
	require RAILS_ENVIRONMENT_RB
	return unless GoodJob::CLI.log_to_stdout? && !ActiveSupport::Logger.logger_outputs_to?(GoodJob.logger, $stdout)
	GoodJob::LogSubscriber.loggers << ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new($stdout))
	GoodJob::LogSubscriber.reset_logger
	end

... which makes me wonder why GoodJob has such a confusing logging interface. I don't remember why I added this; I think it was so that the CLI would always tee and log to STDOUT in addition to any custom logger.

[ylg]

I just tried setting the logger in a few different places trying for both as late as possible and as early as possible, nothing had an impact one way or the other.

Looking at cli.rb, it doesn't seem like that should be invoked by "mainline" Rails, but I didn't look at it very hard so likely missed the point.

Regarding the loggers responding, my point wasn't so much that a certain case breaks the logic, as that the logic is now "assert for A but then run B". I think even in a world where no one had yet written loggers that run afoul of that, the logic seems it ought to be "assert for B and run B". But, my experience has been such logic that appears "off" on first glance usually has some storied history behind it that will burn the house down when I start rewriting, thinking I know better!

[ylg]

Purely for testing purposes, I made these two changes:

sensedata@a26360e
sensedata@d8a26e1

They seem to enable SemanticLogger to work with GoodJob and to work without duplicating logged lines.

The soundness of the approaches are up for question; quite possible Bad Ideas(tm). Also, I did not test these with anything else nor with any completeness. Consider them discussion-in-code rather than concrete suggestions.

[bensheldon]

@ylg thanks for working through this with me.

I'm ok with this change if you wanted to make a PR: sensedata@a26360e

For the other change, I don't want to do that 😄 I do though think that this check could maybe be a little smarter:

good_job/lib/good_job/cli.rb

Line 159 in a26360e

return unless GoodJob::CLI.log_to_stdout? && !ActiveSupport::Logger.logger_outputs_to?(GoodJob.logger, $stdout)

That logic should be a little cleaner:

return if !GoodJob::CLI.log_to_stdout? || ActiveSupport::Logger.logger_outputs_to?(GoodJob.logger, $stdout)

I've been staring at the current logical expression and I don't think that's a behavioral change, but I'm not sure.

SemanticLoggerRails does override the ActiveSupport::Logger.logger_outputs_to? method to always be true (which is why I think that the existing logical expression is maybe incorrect. You can also create an initializer that sets GoodJob::CLI.log_to_stdout = false