From: pharrington <xenogenesis@...>
Date: 2010-04-05T23:15:05+09:00
Subject: Re: Long-standing bug in logger or monitor?

On Apr 5, 6:43 am, Matthew Bloch <matt...@bytemark.co.uk> wrote:
> 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

What were you expecting your code to do? As is, the problem that
snippet is supposed to demonstrate is unclear (at least to me): It
creates 1000 threads which log, then sleep; afterwards it continually
counts the number of threads you created that are sleeping or dead. So
I'd expect this to first print some number very close to (or exactly)
1000, then continually print 1000 after the logging has ended. What am
I missing?