Logger raises Bad File Descriptor error with JRuby 1.5.0

Hi list,

I’ve just been trying to give the latest release (RC3) a spin, but I’ve
been getting this error:

Exception in thread
“4285567@qtp0-0”
/home/nick/bin/…/lib/jruby/lib/ruby/1.8/logger.rb:504:in `write’: Bad
file descriptor - Bad file descriptor (Errno::EBADF)

whenever logging is attempted from one of the request threads, but works
fine from the startup thread (it’s a rack app). The error wasn’t there
in 1.4.0, so I’m guessing this is a bug with jruby 1.5. Logging to
STDOUT works as well.

The logger is created with:

logger = Logger.new(config[:log_stdout] ? STDOUT : log_path)

and is shared among all the request threads via a MyApp.logger type
thing.

Shall I file a bug? Any one got any ideas for a workaround or a quick
fix?

Cheers,
Nick


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Have you solved this or filed a bug for it?

We have had the same problem and filed a JIRA issue at

http://jira.codehaus.org/browse/JRUBY-4823

Please tell us if you have solved this.

No progress, sorry. I was only taking 1.5 for a spin, and I sort of
fell at the first hurdle with this one.

My guess was along the same lines as Charles in that comment on the bug:
the reference to the file was being garbage collected which was closing
the underlying fd once the main thread had done its init, but I’m
entering the realms of deep speculation.

I’ll see if I can add something useful to that bug report.

Cheers,
Nick

On Sun, 2010-05-30 at 00:14 +0200, Uwe K. wrote:

Have you solved this or filed a bug for it?

We have had the same problem and filed a JIRA issue at

http://jira.codehaus.org/browse/JRUBY-4823

Please tell us if you have solved this.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Forgot to mention a few facts:

Happens with…

$ java -version
java version “1.6.0_15”
Java™ SE Runtime Environment (build 1.6.0_15-b03)
Java HotSpot™ Server VM (build 14.1-b02, mixed mode)

and

$ java -version
java version “1.6.0_12”
Java™ SE Runtime Environment (build 1.6.0_12-b04)
Java HotSpot™ 64-Bit Server VM (build 11.2-b01, mixed mode)

and RC1 as well (didn’t test RC2, seemed pointless).

I tried a few things on the console, and got the same error after
starting a couple of threads with this runnable and a shared logger
instance:

class LogTest

def initialize(logger)
@logger = logger
end

include java.lang.Runnable

def run
while true
sleep 1
@logger.info(“tick tock”)
end
end

end

It ran fine, but I noticed that when I killed the console I got the same
error from each thread. I have no idea how jruby implements its File IO
so no idea if this is just coincidence.

Cheers,
Nick

On Wed, 2010-05-05 at 17:19 +0100, Nick G. wrote:

in 1.4.0, so I’m guessing this is a bug with jruby 1.5. Logging to
fix?


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

If necessary we could collaborate on a debug build with some logging,
to see where/when the file handle in question is getting shut down or
collected. Basically we’d add some logging to either ChannelStream or
ChannelDescriptor to log when they get closed or finalized and try to
show a backtrace at that point.

  • Charlie

On Mon, Jun 7, 2010 at 4:46 PM, Nick G. [email protected]
wrote:


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Hi,

On Tue, Jun 8, 2010 at 02:33, Charles Oliver N.
[email protected] wrote:

If necessary we could collaborate on a debug build with some logging,
to see where/when the file handle in question is getting shut down or
collected. Basically we’d add some logging to either ChannelStream or
ChannelDescriptor to log when they get closed or finalized and try to
show a backtrace at that point.

I can reproduce the exception with 1.5.0 GA and github master by the
following code. Can you?

0% cat test.rb
require ‘java’
require ‘logger’

from JRUBY-4823

class LogTest
def initialize(logger)
@logger = logger
end

include java.lang.Runnable

def run
@logger.info(“tick tock”)
end
end

logger = Logger.new(‘test.log’)
java.lang.Thread.new(LogTest.new(logger)).start

0% ~/git/jruby-master/bin/jruby -d test.rb
Exception in thread “Thread-0”
/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:504:in write': Bad file descriptor - Bad file descriptor (Errno::EBADF) from /home/nahi/git/jruby-master/lib/ruby/1.8/monitor.rb:191:in mon_synchronize’
from /home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:496:in write' from /home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:326:in add’
from /home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:374:in info' from test.rb:13:in run’
from :1
…internal jruby stack elided…
from
Logger::LogDevice.write(/home/nahi/git/jruby-master/lib/ruby/1.8/monitor.rb:191)
from
MonitorMixin.mon_synchronize(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:496)
from
Logger::LogDevice.write(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:326)
from
Logger.add(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:374)
from Logger.info(test.rb:13)
from LogTest.run(:1)
from (unknown).(unknown)(:1)

Let me know if I should look into more deeper.

Regards,
// NaHi


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Hi again,

And of course backtrace is our friend.

0% ~/git/jruby-master/bin/jruby -J-Djruby.backtrace.style=raw -d test.rb
Exception in thread “Thread-0” Thread.java:1436:in getStackTrace': Bad file descriptor - Bad file descriptor (Errno::EBADF) from RubyException.java:147:in setBacktraceFrames’
from RaiseException.java:177:in setException' from RaiseException.java:73:in
from Ruby.java:3332:in newRaiseException' from Ruby.java:3014:in newErrnoEBADFError’
from RubyIO.java:1459:in fwrite' from RubyIO.java:1245:in write’
from org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen:65535:in
call' from CachingCallSite.java:308:in cacheAndCall’
from CachingCallSite.java:147:in call' from CallOneArgNode.java:57:in interpret’
from NewlineNode.java:104:in interpret' from BlockNode.java:71:in interpret’
from InterpretedBlock.java:373:in evalBlockBody' from InterpretedBlock.java:294:in yield’
from InterpretedBlock.java:228:in yieldSpecific' from Block.java:99:in yieldSpecific’
from ZYieldNode.java:25:in interpret' from NewlineNode.java:104:in interpret’
from EnsureNode.java:96:in interpret' from BeginNode.java:83:in interpret’
from NewlineNode.java:104:in interpret' from BlockNode.java:71:in interpret’
from InterpretedMethod.java:160:in call' from DefaultMethod.java:164:in call’
from AliasMethod.java:81:in call' from CachingCallSite.java:298:in cacheAndCall’
from CachingCallSite.java:116:in callBlock' from CachingCallSite.java:121:in call’
from CallNoArgBlockNode.java:64:in interpret' from NewlineNode.java:104:in interpret’
from InterpretedMethod.java:180:in call' from DefaultMethod.java:172:in call’
from CachingCallSite.java:308:in cacheAndCall' from CachingCallSite.java:147:in call’
from CallOneArgNode.java:57:in interpret' from NewlineNode.java:104:in interpret’
from BlockNode.java:71:in interpret' from InterpretedMethod.java:283:in call’
from DefaultMethod.java:212:in call' from CachingCallSite.java:358:in cacheAndCall’
from CachingCallSite.java:236:in callBlock' from CachingCallSite.java:241:in call’
from FCallThreeArgBlockPassNode.java:36:in interpret' from NewlineNode.java:104:in interpret’
from InterpretedMethod.java:180:in call' from DefaultMethod.java:172:in call’
from CachingCallSite.java:308:in cacheAndCall' from CachingCallSite.java:147:in call’
from test.rb:13:in method__2$RUBY$run' from testInvokermethod__2$RUBY$runFixed0#run:65535:in call’
from testInvokermethod__2$RUBY$runFixed0#run:65535:in call' from LogTest_184718662.gen:13:in run’
from Thread.java:619:in `run’
…internal jruby stack elided…
from
Logger::LogDevice.write(/home/nahi/git/jruby-master/lib/ruby/1.8/monitor.rb:191)
from
MonitorMixin.mon_synchronize(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:496)
from
Logger::LogDevice.write(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:326)
from
Logger.add(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:374)
from Logger.info(test.rb:13)
from LogTest.run(:1)
from (unknown).(unknown)(:1)
0%

Regards,
// NaHi

On Tue, Jun 8, 2010 at 14:35, NAKAMURA, Hiroshi [email protected]
wrote:

following code. Can you?

0% ~/git/jruby-master/bin/jruby -d test.rb
…internal jruby stack elided…
Regards,
// NaHi


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Yep, same for me (RC3).

Charlie, time permitting, I’ll have a go at throwing some debug in to
those classes you mentioned and report back.

Cheers,
Nick

My similar stack trace from NaHi’s test.rb…

Exception in thread “Thread-0” Thread.java:1436:in getStackTrace': Bad file descriptor - Bad file descriptor (Errno::EBADF) from RubyException.java:147:insetBacktraceFrames’
from RaiseException.java:177:in setException' from RaiseException.java:73:in
from Ruby.java:3320:in newRaiseException' from Ruby.java:3006:innewErrnoEBADFError’
from RubyIO.java:1500:in fwrite' from RubyIO.java:1286:inwrite’
from org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen:65535:in
call' from CachingCallSite.java:309:incacheAndCall’
from CachingCallSite.java:148:in call' from CallOneArgNode.java:57:ininterpret’
from NewlineNode.java:104:in interpret' from BlockNode.java:71:ininterpret’
from InterpretedBlock.java:373:in evalBlockBody' from InterpretedBlock.java:294:inyield’
from InterpretedBlock.java:228:in yieldSpecific' from Block.java:99:inyieldSpecific’

On Tue, 2010-06-08 at 14:42 +0900, NAKAMURA, Hiroshi wrote:

from Ruby.java:3332:in newRaiseException' from InterpretedBlock.java:294:inyield’
from AliasMethod.java:81:in call' from NewlineNode.java:104:ininterpret’
from CachingCallSite.java:308:in `cacheAndCall’
from Logger.add(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:374)

0% cat test.rb

/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:504:in `write’: Bad
from MonitorMixin.mon_synchronize(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:496)


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

OK, I hooked that script up to the debugger and watched the difference
between 1.5.1 and 1.4.0.

When the script finishes evaluating, the main thread calls tearDown,
assuming that you’re done with the runtime. In 1.4.0, the file
descriptors escape unharmed, but in 1.5 they are getting registered with
the runtime to be finalized (and therefore closed) in tearDown. Any
threads that are still running that have use these references are rather
out of luck, so I suppose either script writers should be joining to the
threads they create before they relinquish control of the main thread,
or jruby could do this for you somehow.

My app is pretty close to the test script in nature. I was forgetting
to join to my jetty server, so the main thread was returning but my
request threads kept serving. It just happened by chance that this
worked fine in 1.4 even though the runtime was being torn down. So
perhaps not a bug in JRuby. Maybe it’s a bug that you can keep using
the runtime after it is torn down without any warnings though.

Cheers,
Nick

On Fri, 2010-06-11 at 13:25 +0100, Nick G. wrote:

`call’
On Tue, 2010-06-08 at 14:42 +0900, NAKAMURA, Hiroshi wrote:

from Ruby.java:3332:in newRaiseException' from InterpretedBlock.java:294:inyield’
from AliasMethod.java:81:in call' from NewlineNode.java:104:ininterpret’
from CachingCallSite.java:308:in `cacheAndCall’
from Logger.add(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:374)

0% cat test.rb

/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:504:in `write’: Bad
from MonitorMixin.mon_synchronize(/home/nahi/git/jruby-master/lib/ruby/1.8/logger.rb:496)


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email