From: Matthew Bloch <matthew@...>
Date: 2010-04-05T19:43:37+09:00
Subject: Long-standing bug in logger or monitor?

Hi there,

I've spotted some bad behaviour in a program that I've boiled down to a
test case, and I think it demonstrates a bug in either logger or monitor
or my understanding of how either should work.

It runs 1000 threads, all logging through a single Logger at short
random intervals:

##### SNIP ######
#!/usr/bin/ruby
# demonstrate bug in logger / monitor

require 'logger'

threads = []
logger = Logger.new(STDOUT)

1000.times do 
  threads << Thread.new do
    logger.info "Blah blah blah"
    sleep rand(100.0)/1000.0
  end
end

# will print 1000 after a few seconds, no more log lines
loop do
  p threads.inject(0) { |s,t| t.stop? ? s+1 : s }
  sleep 2
end
##### SNIP ######

For me, all the logging threads stop after a few seconds of running, the
script simply printing "1000" over and over, which seems like an
unintended deadlock.

The logger implementation *appears* to try to synchronize threads, but
it doesn't seem to work.  Debugging my own threading problems is bad
enough, but before I try to debug anyone else's I thought I'd share and
see if anyone had any quicker insights into this issue.  For me, it is
happening every few hours in a program only running six threads.

This happens reliably under the versions in Debian/lenny, Ubuntu/karmic
and a stable 1.9.1 built just now on my laptop, specifically:

ruby 1.8.7 (2008-08-11 patchlevel 72) [x86_64-linux]
ruby 1.8.7 (2009-06-12 patchlevel 174) [i486-linux]
ruby 1.9.1p376 (2009-12-07 revision 26041) [i686-linux]

-- 
Matthew