More on logger hang-ups

[Matthew Bloch]

Here's what I see in my program, two threads stuck on writing to the
same logger:

--> #0 MonitorMixin.mon_acquire(queue#Array)
at line /usr/lib/ruby/1.8/monitor.rb:286
#1 MonitorMixin.mon_enter at line /usr/lib/ruby/1.8/monitor.rb:214
#2 MonitorMixin.synchronize at line /usr/lib/ruby/1.8/monitor.rb:240
#3 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#4 Logger.initialize(severity#Fixnum, message#String,
progname#NilClass)
at line /usr/lib/ruby/1.8/logger.rb:327
#5 Logger.debug(progname#String) at
line /usr/lib/ruby/1.8/logger.rb:348
#6 Mauve::Alert.inspect(update#Mauve:roto::AlertUp...)
at line /usr/lib/mauvealert/lib/mauve/alert.rb:322


--> #0 Debugger.interrupt_last
at
line /usr/lib/ruby/gems/1.8/gems/ruby-debug-base-0.10.3/lib/ruby-debug-base.rb:89
#1 at
line /usr/lib/ruby/gems/1.8/gems/ruby-debug-0.10.3/bin/rdebug:351
#2 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#3 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#4 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#5 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#6 Logger.initialize(severity#Fixnum, message#String,
progname#NilClass)
at line /usr/lib/ruby/1.8/logger.rb:327
#7 Logger.debug(progname#String) at
line /usr/lib/ruby/1.8/logger.rb:348
#8 DataMapper::Adapters:ataObjectsAdapter.execute_reader
at
line /usr/lib/mauvealert/external/dm-core-0.10.2/lib/dm-core/adapters/data_objects_adapter.rb:140
....

Restarting the program from within rdebug, and re-interrupting leaves
these backtraces at the same point.

The most likely explanation is that the logger's output device (@dev) is
blocking for *minutes* at a time, but I've no idea why that might be
when it's just a file.

Will dive in and add some instrumentation / timeouts around that write
statement to see if I can work out why it is behaving that way.

 

[Brian Candler]

--> #0 Debugger.interrupt_last
at
line
/usr/lib/ruby/gems/1.8/gems/ruby-debug-base-0.10.3/lib/ruby-debug-base.rb:89
#1 at
line /usr/lib/ruby/gems/1.8/gems/ruby-debug-0.10.3/bin/rdebug:351
#2 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#3 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496
#4 MonitorMixin.write at line /usr/lib/ruby/1.8/logger.rb:504
#5 Logger::LogDevice.write(message#String)
at line /usr/lib/ruby/1.8/logger.rb:496

(1) Note line #4 calling MonitorMixin.write - this seems to imply that
@dev *is* a MonitorMixin??

(2) It looks like LogDevice.write is calling itself re-entrantly here?

Is it possible that you've called Logger.new() with an existing Logger
instance as an argument?

(3) Why is Logger.initialize in the backtrace? The source line number
suggests Logger#add (which makes a lot more sense). But if you are
really calling Logger.new() lots of times, that sounds like a problem. I
would have expected that you'd create a single global Logger instance at
the start of the app, and then pass this around everywhere.

Regards,

Brian.

 

[Matthew Bloch]

(1) Note line #4 calling MonitorMixin.write - this seems to imply that
@dev *is* a MonitorMixin??

Hmm, yes it wasn't a file, it was another Logger::LogDevice - now
changed to a File...

(2) It looks like LogDevice.write is calling itself re-entrantly here?

Yup, by mistake, but not the same LogDevice (separate locks).

Is it possible that you've called Logger.new() with an existing Logger
instance as an argument?

(3) Why is Logger.initialize in the backtrace? The source line number
suggests Logger#add (which makes a lot more sense). But if you are
really calling Logger.new() lots of times, that sounds like a problem.

That is a bit of a mystery, no I've only created one Logger and there's
no Logger#new around.

That suggests the backtrace is wrong / elided somewhere. I'm now
waiting for it to happen again after removing the LogDevice confusion.