ougai icon indicating copy to clipboard operation
ougai copied to clipboard

Sidekiq 7 compatibility and `.child` not returning an instance of the logger class

Open joffotron opened this issue 1 year ago • 1 comments

Hi,

I'm trying to use our custom logger (which inherits from Ougai::Logger) with Sidekiq 7, but am running into trouble. The instructions in the wiki work great for our other app, which is still on Sidekiq 6.

Our logger essentially is:

module Chargefox
  class Logger < Ougai::Logger
    include ActiveSupport::LoggerThreadSafeLevel
    include ActiveSupport::LoggerSilence

    attr_reader :formatter    

    def create_formatter
      Chargefox::StructuredLogFormatter.new
    end
  end
end

In the sidekiq config block:

Sidekiq.configure_server do |config|
    config.logger = Rails.logger.child({'service.namespace' => 'sidekiq'})
    ap "Logger class: #{config.logger.class.name}"
    ap "has method: #{config.logger.respond_to?(:formatter)}"
end
"Logger class: "
"has method: false"
undefined method `formatter' for #<#<Class:0x000000012f9819f0>:0x000000011eaaefc8 @before_log=nil, @level=nil, @parent=#<Chargefox::Logger:0x0000000129ada780 @level=1, @progname=nil, @default_formatter=#<Logger::Formatter:0x0000000129adab18 @datetime_format=nil>, @formatter=#<Chargefox::StructuredLogFormatter:0x0000000129ada758 @app_name="sidekiq", @hostname="ams-mac-020.local", @trace_indent=2, @trace_max_lines=100, @serialize_backtrace=true, @datetime_format="%FT%T.%3N%:z">, @logdev=#<Logger::LogDevice:0x0000000129adaa28 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @binmode=false, @mon_data=#<Monitor:0x0000000129ada9d8>, @mon_data_owner_object_id=9480>, @before_log=nil, @default_message="No message", @exc_key=:err, @with_fields={}>, @with_fields={"service.namespace"=>"sidekiq"}>
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/sidekiq-7.1.6/lib/sidekiq/cli.rb:44:in `run'
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/sidekiq-7.1.6/bin/sidekiq:31:in `<top (required)>'

Should .child return an instance of Chargefox::Logger in this case?

Additionally, If I pass a fresh instance of our logger to Sidekiq, e.g.

config.logger = Chargefox::Logger.new($stdout)

Something else goes pretty wrong and we get a stack overflow:

{"timestamp":1700098610796550000,"utc_time":"2023-11-16T01:36:50Z","service.name":"local-chargefox-core","service.version":"local","service.namespace":"web","severity_text":"DEBUG","message":"Server Middleware: Sidekiq::Failures::Middleware, Sidekiq::Metrics::Middleware, Rollbar::Sidekiq::ResetScope, Sidekiq::Status::ServerMiddleware"}
{"timestamp":1700098610796581000,"utc_time":"2023-11-16T01:36:50Z","service.name":"local-chargefox-core","service.version":"local","service.namespace":"web","severity_text":"INFO","message":"Starting processing, hit Ctrl-C to stop"}
bundler: failed to load command: sidekiq (/Users/joff/.rbenv/versions/3.0.6/bin/sidekiq)
/Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:107:in `binary': stack level too deep (SystemStackError)
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:109:in `visit_CAT'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:103:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:162:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:117:in `unary'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:119:in `visit_GROUP'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:103:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:162:in `visit'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/actionpack-7.0.8/lib/action_dispatch/journey/visitors.rb:107:in `binary'
	 ... 11348 levels...
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.21/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
	from /Users/joff/.rbenv/versions/3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.21/exe/bundle:29:in `<top (required)>'
	from /Users/joff/src/chargefox/ocpp-messages/bin/bundle:118:in `load'
	from /Users/joff/src/chargefox/ocpp-messages/bin/bundle:118:in `<main>'

I expect something breaking has changed here, and we won't be able to drop in our own logger class, and instead will need to supply a formatter for the default Sidekiq:Logger instead? If that is the case, it might be nice to update the wiki :)

joffotron avatar Nov 16 '23 01:11 joffotron

After submitting this, I found https://github.com/sidekiq/sidekiq/pull/5065, but we're now on the latest release, could be related, might not be?

joffotron avatar Nov 16 '23 01:11 joffotron