From: Matthew Bloch <matthew@...>
Date: 2010-04-06T07:16:14+09:00
Subject: More on logger hang-ups

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::Proto::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::DataObjectsAdapter.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.

-- 
Matthew