JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-2950

Net::IMAP#authenticate stalls / blocks in recent versions of JRuby

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.1.3
    • Fix Version/s: JRuby 1.2
    • Component/s: Core Classes/Modules
    • Labels:
      None
    • Environment:
      Ubuntu Linux. Courier IMAP with rawdata:
      OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE ACL ACL2=UNION STARTTLS
    • Testcase included:
      yes
    • Number of attachments :
      0

      Description

      I'm experiencing problems authenticating using the standard Net::IMAP#authenticate method.

      I've reliably reproduced this bug on two recent versions of JRuby (1.1.3 released and current SVN Trunk). Version 1.0.3 does not exhibit this bug - the authentication works correctly.

      c ruby 1.8.4 also functions correctly.

      the code to recreate this is simply:

      require 'net/imap'
      imap = Net::IMAP.new('mail.example.com')
      imap.authenticate('LOGIN', 'example.user@example.com', 'password')

      This code executed from either jirb or a standard script with jruby >1.1.3 consistently blocks, and does not exit.

        Activity

        Hide
        Corin Moss added a comment -

        I should add that for testing with 1.0.3 I reverted the version of jruby-openssl to 0.1 - however I also tried the more recent JRuby with jruby-openssl 0.1 and it made no difference - so I conclude jruby-openssl is not the cause here.

        Show
        Corin Moss added a comment - I should add that for testing with 1.0.3 I reverted the version of jruby-openssl to 0.1 - however I also tried the more recent JRuby with jruby-openssl 0.1 and it made no difference - so I conclude jruby-openssl is not the cause here.
        Hide
        Charles Oliver Nutter added a comment -

        Thanks for the report! I've managed to reproduce it on my machine with a dummy IMAP server. It seems to be stuck in IO.

        Show
        Charles Oliver Nutter added a comment - Thanks for the report! I've managed to reproduce it on my machine with a dummy IMAP server. It seems to be stuck in IO.
        Hide
        Corin Moss added a comment -

        Thanks Charles - glad it's not just me. If you point me at the suspect IO classes (if you've IDed them) I'm happy to have a look at fixing it?

        Show
        Corin Moss added a comment - Thanks Charles - glad it's not just me. If you point me at the suspect IO classes (if you've IDed them) I'm happy to have a look at fixing it?
        Charles Oliver Nutter made changes -
        Field Original Value New Value
        Fix Version/s JRuby 1.1+ [ 13421 ]
        Fix Version/s JRuby 1.0.3 [ 13811 ]
        Hide
        Ferdinand Svehla added a comment -

        Still present in 1.1.5; Maybe this should be priorised, after all it breaks a complete stdlib.

        Show
        Ferdinand Svehla added a comment - Still present in 1.1.5; Maybe this should be priorised, after all it breaks a complete stdlib.
        Hide
        Ferdinand Svehla added a comment -

        The error does not occur when using ssl connections.

        Show
        Ferdinand Svehla added a comment - The error does not occur when using ssl connections.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, I think we've made progress on this. Where it used to appear to block in IO code (specifically ChannelStream.feof, fixed for another bug) it now appears to be stuck waiting on a mutex. Here's the relevant bit of the thread dump I get now:

        "main" prio=5 tid=0x0000000101801000 nid=0x100401000 in Object.wait() [0x00000001003fe000..0x0000000100400c70]
           java.lang.Thread.State: WAITING (on object monitor)
        	at java.lang.Object.wait(Native Method)
        	- waiting on <0x00000001058fcc88> (a org.jruby.libraries.ThreadLibrary$ConditionVariable)
        	at java.lang.Object.wait(Object.java:485)
        	at org.jruby.libraries.ThreadLibrary.wait_timeout(ThreadLibrary.java:75)
        	at org.jruby.libraries.ThreadLibrary$ConditionVariable.wait_ruby(ThreadLibrary.java:216)
        	- locked <0x00000001058fcc88> (a org.jruby.libraries.ThreadLibrary$ConditionVariable)
        	at org.jruby.libraries.ThreadLibrary$ConditionVariable$i_method_0_1$RUBYINVOKER$wait_ruby.call(org/jruby/libraries/ThreadLibrary$ConditionVariable$i_method_0_1$RUBYINVOKER$wait_ruby.gen)
        	at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodNoBlock.call(JavaMethod.java:62)
        	at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:243)
        	at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:152)
        	at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:114)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.ensure_2$RUBY$__ensure___22(monitor.rb:266)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.block_9$RUBY$__block__(monitor.rb:261)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorBlockCallback$block_9$RUBY$__block__xx1.call(Unknown Source)
        	at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:100)
        	at org.jruby.runtime.Block.yield(Block.java:120)
        	at org.jruby.libraries.ThreadLibrary$Mutex.synchronize(ThreadLibrary.java:159)
        	at org.jruby.libraries.ThreadLibrary$Mutex$i_method_0_0$RUBYINVOKER$synchronize.call(org/jruby/libraries/ThreadLibrary$Mutex$i_method_0_0$RUBYINVOKER$synchronize.gen)
        	at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:98)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.method__21$RUBY$mon_wait_for_cond(monitor.rb:256)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorInvokermethod__21$RUBY$mon_wait_for_condFixed2.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/monitorInvokermethod__21$RUBY$mon_wait_for_condFixed2.gen)
        	at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:226)
        	at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:155)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.block_0$RUBY$__block__(monitor.rb:95)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorBlockCallback$block_0$RUBY$__block__xx1.call(Unknown Source)
        	at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:120)
        	at org.jruby.runtime.Block.yield(Block.java:133)
        	at org.jruby.RubyObject.yieldUnder(RubyObject.java:491)
        	at org.jruby.RubyObject.specificEval(RubyObject.java:313)
        	at org.jruby.RubyObject.instance_eval(RubyObject.java:1193)
        	at org.jruby.RubyObject$i_method_multi$RUBYFRAMEDINVOKER$instance_eval.call(org/jruby/RubyObject$i_method_multi$RUBYFRAMEDINVOKER$instance_eval.gen)
        	at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:98)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.method__2$RUBY$wait(monitor.rb:95)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorInvokermethod__2$RUBY$waitOpt.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/monitorInvokermethod__2$RUBY$waitOpt.gen)
        	at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226)
        	at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:216)
        	at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:73)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.method__56$RUBY$get_tagged_response(imap.rb:971)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imapInvokermethod__56$RUBY$get_tagged_responseFixed1.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/net/imapInvokermethod__56$RUBY$get_tagged_responseFixed1.gen)
        	at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:221)
        	at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:280)
        	at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:116)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.ensure_4$RUBY$__ensure___61(imap.rb:1031)
        	at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.block_16$RUBY$__block__(imap.rb:1030)
        

        This is the only non-JVM thread still active, which leads me to believe whatever thread would have triggered the mutex has already done so and terminated by the time we get to this point. So there's possibly some thread behavioral differences between JRuby and MRI.

        If someone wants to look into the remaining issues, I'd recommend poking around net/imap.rb, compariing it with more recent versions on 1_8_6 and 1_9 branches to see whether we're missing some important threading fixes, and otherwise untangling the threading stuff it does. It may not be difficult with a bit of logging and code reading.

        Show
        Charles Oliver Nutter added a comment - Ok, I think we've made progress on this. Where it used to appear to block in IO code (specifically ChannelStream.feof, fixed for another bug) it now appears to be stuck waiting on a mutex. Here's the relevant bit of the thread dump I get now: "main" prio=5 tid=0x0000000101801000 nid=0x100401000 in Object.wait() [0x00000001003fe000..0x0000000100400c70] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000001058fcc88> (a org.jruby.libraries.ThreadLibrary$ConditionVariable) at java.lang.Object.wait(Object.java:485) at org.jruby.libraries.ThreadLibrary.wait_timeout(ThreadLibrary.java:75) at org.jruby.libraries.ThreadLibrary$ConditionVariable.wait_ruby(ThreadLibrary.java:216) - locked <0x00000001058fcc88> (a org.jruby.libraries.ThreadLibrary$ConditionVariable) at org.jruby.libraries.ThreadLibrary$ConditionVariable$i_method_0_1$RUBYINVOKER$wait_ruby.call(org/jruby/libraries/ThreadLibrary$ConditionVariable$i_method_0_1$RUBYINVOKER$wait_ruby.gen) at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodNoBlock.call(JavaMethod.java:62) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:243) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:152) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:114) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.ensure_2$RUBY$__ensure___22(monitor.rb:266) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.block_9$RUBY$__block__(monitor.rb:261) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorBlockCallback$block_9$RUBY$__block__xx1.call(Unknown Source) at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:100) at org.jruby.runtime.Block.yield(Block.java:120) at org.jruby.libraries.ThreadLibrary$Mutex.synchronize(ThreadLibrary.java:159) at org.jruby.libraries.ThreadLibrary$Mutex$i_method_0_0$RUBYINVOKER$synchronize.call(org/jruby/libraries/ThreadLibrary$Mutex$i_method_0_0$RUBYINVOKER$synchronize.gen) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:98) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.method__21$RUBY$mon_wait_for_cond(monitor.rb:256) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorInvokermethod__21$RUBY$mon_wait_for_condFixed2.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/monitorInvokermethod__21$RUBY$mon_wait_for_condFixed2.gen) at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:226) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:155) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.block_0$RUBY$__block__(monitor.rb:95) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorBlockCallback$block_0$RUBY$__block__xx1.call(Unknown Source) at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:120) at org.jruby.runtime.Block.yield(Block.java:133) at org.jruby.RubyObject.yieldUnder(RubyObject.java:491) at org.jruby.RubyObject.specificEval(RubyObject.java:313) at org.jruby.RubyObject.instance_eval(RubyObject.java:1193) at org.jruby.RubyObject$i_method_multi$RUBYFRAMEDINVOKER$instance_eval.call(org/jruby/RubyObject$i_method_multi$RUBYFRAMEDINVOKER$instance_eval.gen) at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:98) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitor.method__2$RUBY$wait(monitor.rb:95) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.monitorInvokermethod__2$RUBY$waitOpt.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/monitorInvokermethod__2$RUBY$waitOpt.gen) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226) at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:216) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:73) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.method__56$RUBY$get_tagged_response(imap.rb:971) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imapInvokermethod__56$RUBY$get_tagged_responseFixed1.call(Users/headius/projects/jruby/lib/ruby/$1_dot_8/net/imapInvokermethod__56$RUBY$get_tagged_responseFixed1.gen) at org.jruby.internal.runtime.methods.CompiledMethod.call(CompiledMethod.java:221) at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:280) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:116) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.ensure_4$RUBY$__ensure___61(imap.rb:1031) at Users.headius.projects.jruby.lib.ruby.$1_dot_8.net.imap.block_16$RUBY$__block__(imap.rb:1030) This is the only non-JVM thread still active, which leads me to believe whatever thread would have triggered the mutex has already done so and terminated by the time we get to this point. So there's possibly some thread behavioral differences between JRuby and MRI. If someone wants to look into the remaining issues, I'd recommend poking around net/imap.rb, compariing it with more recent versions on 1_8_6 and 1_9 branches to see whether we're missing some important threading fixes, and otherwise untangling the threading stuff it does. It may not be difficult with a bit of logging and code reading.
        Hide
        Charles Oliver Nutter added a comment -

        The final issue seems to have been a bug in ConditionVariable where it waited uninterruptibly. When an exception was thrown due to an error on my test IMAP server, it tried to raise in the client thread. The raise fired, but the ConditionVariable continued waiting. The fix was to track in the thread what object it's waiting on, so that when an interrupt is needed it can be fired appropriately. Fixed in r9177.

        If you see any additional issues with IMAP, please file as separate bugs.

        Show
        Charles Oliver Nutter added a comment - The final issue seems to have been a bug in ConditionVariable where it waited uninterruptibly. When an exception was thrown due to an error on my test IMAP server, it tried to raise in the client thread. The raise fired, but the ConditionVariable continued waiting. The fix was to track in the thread what object it's waiting on, so that when an interrupt is needed it can be fired appropriately. Fixed in r9177. If you see any additional issues with IMAP, please file as separate bugs.
        Charles Oliver Nutter made changes -
        Fix Version/s JRuby 1.2 [ 14757 ]
        Resolution Fixed [ 1 ]
        Assignee Charles Oliver Nutter [ headius ]
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s JRuby 1.x+ [ 13421 ]
        Charles Oliver Nutter made changes -
        Status Resolved [ 5 ] Closed [ 6 ]

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Corin Moss
          • Votes:
            1 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: