New spawned child after a signal always had logger.level set to DEBUG

[nolith]

Hello,

I noticed that if I send an USR1 or USR2 signal to sneakers the respawned workers always have a log level se to DEBUG regardless of the parent configuration.

I tried to write a simple test, which unfortunately didn't fail but shows the problem on the STDOUT

it is supposed to be added to spec/sneakers/integration_spec.rb

    it 'should remember logging level after a signal' do
      assert(Sneakers.logger.level != Logger::WARN, 'log level precondition failed')
      old_log_level = Sneakers.logger.level
      puts "Logger level #{old_log_level}"
      Sneakers.logger.level = Logger::WARN
      job_count = 100

      pid = start_worker(IntegrationWorker)

      integration_log "publishing..."
      p = Sneakers::Publisher.new
      job_count.times do |i|
        p.publish("m #{i}", to_queue: IntegrationWorker.queue_name)
      end

      sleep 2
      puts 'restarting child'
      Process.kill('USR1',pid)
      sleep 2
      assert(Sneakers.logger.level == Logger::WARN, 'Log level was resetted after reloading')
      puts "Logger level #{Sneakers.logger.level}"
      assert_all_accounted_for(
        queue: IntegrationWorker.queue_name,
        pid: pid,
        within_sec: 15,
        jobs: job_count,
      )
    end

[aq1018]

I'm having the same issue here. Also other configs such as heartbeat interval are not respected as well...

[michaelklishin]

@qa sorry but this is very light on details: no Sneakers version information, no way to reproduce, not even a small code snippet. This is not something maintainers can work with.

[michaelklishin]

@nolith is this still relevant in master?

[nolith]

@michaelklishin no way to reproduce? Did you try the test that I wrote?

I no longer use sneakers (changed job) but I take some time to verify it today on master. The bug it's still there.

In order to reproduce:

1. clone master
2. apply this patch

   
   diff --git a/spec/sneakers/integration_spec.rb b/spec/sneakers/integration_spec.rb
   index 472d32c..03ea716 100644
   --- a/spec/sneakers/integration_spec.rb
   +++ b/spec/sneakers/integration_spec.rb
   @@ -142,6 +142,34 @@ describe "integration" do
      )
    end

• it 'should remember logging level after a signal' do
• assert(Sneakers.logger.level != Logger::WARN, 'log level precondition failed')
• old_log_level = Sneakers.logger.level
• puts "Logger level #{old_log_level}"
• Sneakers.logger.level = Logger::WARN
• job_count = 100
• pid = start_worker(IntegrationWorker)
• integration_log "publishing..."
• p = Sneakers::Publisher.new
• job_count.times do |i|
• p.publish("m #{i}", to_queue: IntegrationWorker.queue_name)
• end
• sleep 2
• puts 'restarting child'
• Process.kill('USR1',pid)
• sleep 2
• assert(Sneakers.logger.level == Logger::WARN, 'Log level was resetted after reloa
• puts "Logger level #{Sneakers.logger.level}"
• assert_all_accounted_for(
• queue: IntegrationWorker.queue_name,
• pid: pid,
• within_sec: 15,
• jobs: job_count,
• )
• end end end

  
  1. start redis and rabbitmq
  1. run the modified test: `bundle exec rake TEST=spec/sneakers/integration_spec.rb TESTOPTS="-v" INTEGRATION="1"`

As I said in the first message, the test itself will not fail; but will show the erratic behaviour on standard output.

[ ... cut ... ]
Logger level 3
2017-09-25T08:56:28Z p-36750 t-oxjt38j00 WARN: Loading runner configuration...
2017-09-25T08:56:28Z p-36750 t-oxjt38j00 WARN: Loading runner configuration...
2017-09-25T08:56:28Z p-36750 t-oxjt38j00 WARN: Loading runner configuration...
restarting child
2017-09-25T08:56:35Z p-36750 t-oxjt8wwrg WARN: Loading runner configuration...
2017-09-25T08:56:36Z p-36750 t-oxjt38j00 INFO: Worker 0 finished with status 0
2017-09-25T08:56:36Z p-36750 t-oxjt38j00 INFO: Worker 1 finished with status 0
2017-09-25T08:56:36Z p-36758 t-oxjt38j00 DEBUG: [worker-integration_wy16udoqlysqm9z90nqi5e0:1:rp53ez][#<Thread:0x007ff0a587f260>][integration_wy16udoqlysqm9z90nqi5e0][#<Sneakers::Configuration:0x007ff0a88f1510>] New worker: subscribing.
2017-09-25T08:56:36Z p-36758 t-oxjt38j00 DEBUG: Sent protocol preamble
2017-09-25T08:56:36Z p-36758 t-oxjt38j00 DEBUG: Sent connection.start-ok
[ ... cut ... ]

[michaelklishin]

@nolith thanks for the extra info.

[aiomaster]

Hi, I had the same problem as I tried to update the serverengine gem. It could get fixed with my PR with this line: https://github.com/jondot/sneakers/pull/326/files#diff-6f539bfa8db55d0637a0862618985d34R75

The problem is, that the serverengine resets the loglevel there https://github.com/treasure-data/serverengine/blob/master/lib/serverengine/config_loader.rb#L54 if you don't specify the log_level option. It doesn't do this the first time, cause there is no @logger then. But if you restart a worker there is.