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]