# More on logger hang-ups

**URL:** <https://www.ruby-forum.com/t/more-on-logger-hang-ups/186377>\
**Category:** Ruby\
**Created:** [April 6, 2010, 12:16am UTC](https://www.ruby-forum.com/t/more-on-logger-hang-ups/186377 "2010-04-06T00:16:59Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![matthewmurcia](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/7cd45c/32.png) [@matthewmurcia](https://www.ruby-forum.com/u/matthewmurcia)\
**Post date:** [April 6, 2010, 12:16am UTC](https://www.ruby-forum.com/t/more-on-logger-hang-ups/186377/1 "2010-04-06T00:16:59Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![matthewmurcia](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/7cd45c/32.png) [@matthewmurcia](https://www.ruby-forum.com/u/matthewmurcia)\
**Post date:** [April 6, 2010, 9:56pm UTC](https://www.ruby-forum.com/t/more-on-logger-hang-ups/186377/2 "2010-04-06T21:56:33Z")

</div>

On Tue, 2010-04-06 at 21:33 +0900, Brian C. wrote:

> > ```
> > #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??

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.

---

<div class="post-metadata">

**Author:** ![matthewmurcia](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/7cd45c/32.png) [@matthewmurcia](https://www.ruby-forum.com/u/matthewmurcia)\
**Post date:** [April 6, 2010, 2:33pm UTC](https://www.ruby-forum.com/t/more-on-logger-hang-ups/186377/3 "2010-04-06T14:33:53Z")

</div>

Matthew B. wrote:

> –\> #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.