JRuby

IO.popen doesn't wait until a process ends but returns immediately

Details

  • Type: Bug Bug
  • Status: Reopened Reopened
  • Priority: Major Major
  • Resolution: Unresolved
  • Affects Version/s: JRuby 1.6.4, JRuby 1.6.5
  • Fix Version/s: None
  • Component/s: Miscellaneous
  • Labels:
    None
  • Environment:
    I reproduced this on Ubuntu 11.10 and on an older CentOS 5.6 with JRuby 1.6.3 and JRuby 1.6.5
  • Number of attachments :
    0

Description

Hi,

I hope that I'm wrong, but at the moment this looks like a serious bug to me, but maybe I just didn't do enough RTFM. I found this bug when using ActionMailer with sendmail. The "/usr/sbin/sendmail" process was only sometimes called and sometimes it wasn't (most often it wasn't but around every tenth time it suddenly worked)

I investigated it deeply and after hours I distilled it down to the following:

hk@hk:~$ rvm use jruby ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now "
Wed Oct 26 16:37:08 +0200 2011
Wed Oct 26 16:37:13 +0200 2011
Wed Oct 26 16:37:13 +0200 2011
hk@hk:~$ rvm use 1.8.7 ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now "
Wed Oct 26 16:37:18 +0200 2011
Wed Oct 26 16:37:23 +0200 2011
Wed Oct 26 16:37:28 +0200 2011
hk@hk:~$

As one can see, the system call on both Ruby Interpreters waits until the subprocess exits. But with MRI it also stops when using IO.popen, but not with JRuby. Here it returns immediately.

I found a very ugly workaround for the moment by doing something like the following:

module ActionMailer
  class Base
    def perform_delivery_sendmail(mail)
      sendmail_args = sendmail_settings[:arguments]
      sendmail_args += " -f \"#{mail['return-path']}\"" if mail['return-path']

      IO.popen("#{sendmail_settings[:location]} #{sendmail_args}", "r+") do |f| #r+ geht, w+ geht nicht richtig, bzw. nur manchmal
        f.puts mail.encoded.gsub(/\r/, '')
        f.close_write
        sleep 1 # <---- added this line in order to give sendmail some time to process
      end
    end
  end
end

Here are some environment infos:

hk@hk:~$ rvm info jruby

jruby-1.6.5:

  system:
    uname:       "Linux hk 3.0.0-12-generic #20-Ubuntu SMP Fri Oct 7 14:56:25 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux"
    bash:        "/bin/bash => GNU bash, Version 4.2.10(1)-release (x86_64-pc-linux-gnu)"
    zsh:         " => not installed"

  rvm:
    version:      "rvm 1.9.0 by Wayne E. Seguin (wayneeseguin@gmail.com) [https://rvm.beginrescueend.com/]"

  ruby:
    interpreter:  "jruby"
    version:      "1.6.5"
    date:         "2011-10-25"
    platform:     "linux-amd64-java"
    patchlevel:   "OpenJDK 64-Bit Server VM 1.6.0_23"
    full_version: "jruby 1.6.5 (ruby-1.8.7-p330) (2011-10-25 9dcd388) (OpenJDK 64-Bit Server VM 1.6.0_23) [linux-amd64-java]"

  homes:
    gem:          "/home/hk/.rvm/gems/jruby-1.6.5"
    ruby:         "/home/hk/.rvm/rubies/jruby-1.6.5"

  binaries:
    ruby:         "/home/hk/.rvm/rubies/jruby-1.6.5/bin/ruby"
    irb:          "/home/hk/.rvm/rubies/jruby-1.6.5/bin/irb"
    gem:          "/home/hk/.rvm/rubies/jruby-1.6.5/bin/gem"
    rake:         "/home/hk/.rvm/gems/jruby-1.6.5/bin/rake"

  environment:
    PATH:         "/home/hk/.rvm/gems/jruby-1.6.5/bin:/home/hk/.rvm/gems/jruby-1.6.5@global/bin:/home/hk/.rvm/rubies/jruby-1.6.5/bin:/home/hk/.rvm/bin:<other stuff>"
    GEM_HOME:     "/home/hk/.rvm/gems/jruby-1.6.5"
    GEM_PATH:     "/home/hk/.rvm/gems/jruby-1.6.5:/home/hk/.rvm/gems/jruby-1.6.5@global"
    MY_RUBY_HOME: "/home/hk/.rvm/rubies/jruby-1.6.5"
    IRBRC:        "/home/hk/.rvm/rubies/jruby-1.6.5/.irbrc"
    RUBYOPT:      ""
    gemset:       ""


hk@hk:~$ 

hk@hk:~$ rvm info 1.8.7

ruby-1.8.7-p352:

  system:
    uname:       "Linux hk 3.0.0-12-generic #20-Ubuntu SMP Fri Oct 7 14:56:25 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux"
    bash:        "/bin/bash => GNU bash, Version 4.2.10(1)-release (x86_64-pc-linux-gnu)"
    zsh:         " => not installed"

  rvm:
    version:      "rvm 1.9.0 by Wayne E. Seguin (wayneeseguin@gmail.com) [https://rvm.beginrescueend.com/]"

  ruby:
    interpreter:  "ruby"
    version:      "1.8.7"
    date:         "2011-06-30"
    platform:     "x86_64-linux"
    patchlevel:   "2011-06-30 patchlevel 352"
    full_version: "ruby 1.8.7 (2011-06-30 patchlevel 352) [x86_64-linux]"

  homes:
    gem:          "/home/hk/.rvm/gems/ruby-1.8.7-p352"
    ruby:         "/home/hk/.rvm/rubies/ruby-1.8.7-p352"

  binaries:
    ruby:         "/home/hk/.rvm/rubies/ruby-1.8.7-p352/bin/ruby"
    irb:          "/home/hk/.rvm/rubies/ruby-1.8.7-p352/bin/irb"
    gem:          "/home/hk/.rvm/rubies/ruby-1.8.7-p352/bin/gem"
    rake:         "/home/hk/.rvm/gems/ruby-1.8.7-p352/bin/rake"

  environment:
    PATH:         "/home/hk/.rvm/gems/ruby-1.8.7-p352/bin:/home/hk/.rvm/gems/ruby-1.8.7-p352@global/bin:/home/hk/.rvm/rubies/ruby-1.8.7-p352/bin:<other stuff>"
    GEM_HOME:     "/home/hk/.rvm/gems/ruby-1.8.7-p352"
    GEM_PATH:     "/home/hk/.rvm/gems/ruby-1.8.7-p352:/home/hk/.rvm/gems/ruby-1.8.7-p352@global"
    MY_RUBY_HOME: "/home/hk/.rvm/rubies/ruby-1.8.7-p352"
    IRBRC:        "/home/hk/.rvm/rubies/ruby-1.8.7-p352/.irbrc"
    RUBYOPT:      ""
    gemset:       ""


hk@hk:~$

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Heiko Seebach added a comment - - edited

This bug might be similar or related to JRUBY-5416 and/or JRUBY-5710

Show
Heiko Seebach added a comment - - edited This bug might be similar or related to JRUBY-5416 and/or JRUBY-5710
Hide
Permalink
Edward Anderson added a comment -

Heiko,

I was having the same issue with ActionMailer. Thanks for reporting this and posting your workaround.

Show
Edward Anderson added a comment - Heiko, I was having the same issue with ActionMailer. Thanks for reporting this and posting your workaround.
Hide
Permalink
Hiroshi Nakamura added a comment -

Only formatting changes in description.

Show
Hiroshi Nakamura added a comment - Only formatting changes in description.
Hide
Permalink
Heiko Seebach added a comment - - edited

Hi,
the above patch is for Rails 2.3.x

Meanwhile I see the same problems on Rails 3.0.11, and the patch for this version (and probably all Rails 3.x version) looks like this:

module Mail
  # A delivery method implementation which sends via sendmail.
  #
  # To use this, first find out where the sendmail binary is on your computer,
  # if you are on a mac or unix box, it is usually in /usr/sbin/sendmail, this will
  # be your sendmail location.
  #
  #   Mail.defaults do
  #     delivery_method :sendmail
  #   end
  #
  # Or if your sendmail binary is not at '/usr/sbin/sendmail'
  #
  #   Mail.defaults do
  #     delivery_method :sendmail, :location => '/absolute/path/to/your/sendmail'
  #   end
  #
  # Then just deliver the email as normal:
  #
  #   Mail.deliver do
  #     to 'mikel@test.lindsaar.net'
  #     from 'ada@test.lindsaar.net'
  #     subject 'testing sendmail'
  #     body 'testing sendmail'
  #   end
  #
  # Or by calling deliver on a Mail message
  #
  #   mail = Mail.new do
  #     to 'mikel@test.lindsaar.net'
  #     from 'ada@test.lindsaar.net'
  #     subject 'testing sendmail'
  #     body 'testing sendmail'
  #   end
  #
  #   mail.deliver!
  class Sendmail

    def initialize(values)
      self.settings = { :location       => '/usr/sbin/sendmail',
                        :arguments      => '-i -t' }.merge(values)
    end

    attr_accessor :settings

    def deliver!(mail)
      envelope_from = mail.return_path || mail.sender || mail.from_addrs.first
      return_path = "-f \"#{envelope_from.to_s.shellescape}\"" if envelope_from

      arguments = [settings[:arguments], return_path].compact.join(" ")

      Sendmail.call(settings[:location], arguments, mail.destinations.collect(&:shellescape).join(" "), mail)
    end

    def Sendmail.call(path, arguments, destinations, mail)
      IO.popen("#{path} #{arguments} #{destinations}", "r+") do |io|
        io.puts mail.encoded.to_lf
        io.close_write  # <------ changed this from flush to close_write
        sleep 1 # <-------- added this line
      end
    end
  end
end

simply put this file e.g. into

config/initializers/sendmail_patch.rb

And I found some more more insights about it:

If I run strace around this command, it works quite reliable also in the unpatched version.
And in the unpatched version I've also seen messages like

lost connection after DATA (949 bytes) from
server...

which makes it pretty clear, that this popen bug terminates sendmail during sending.

Show
Heiko Seebach added a comment - - edited Hi, the above patch is for Rails 2.3.x Meanwhile I see the same problems on Rails 3.0.11, and the patch for this version (and probably all Rails 3.x version) looks like this: module Mail # A delivery method implementation which sends via sendmail. # # To use this , first find out where the sendmail binary is on your computer, # if you are on a mac or unix box, it is usually in /usr/sbin/sendmail, this will # be your sendmail location. # # Mail.defaults do # delivery_method :sendmail # end # # Or if your sendmail binary is not at '/usr/sbin/sendmail' # # Mail.defaults do # delivery_method :sendmail, :location => '/absolute/path/to/your/sendmail' # end # # Then just deliver the email as normal: # # Mail.deliver do # to 'mikel@test.lindsaar.net' # from 'ada@test.lindsaar.net' # subject 'testing sendmail' # body 'testing sendmail' # end # # Or by calling deliver on a Mail message # # mail = Mail. new do # to 'mikel@test.lindsaar.net' # from 'ada@test.lindsaar.net' # subject 'testing sendmail' # body 'testing sendmail' # end # # mail.deliver! class Sendmail def initialize(values) self.settings = { :location => '/usr/sbin/sendmail', :arguments => '-i -t' }.merge(values) end attr_accessor :settings def deliver!(mail) envelope_from = mail.return_path || mail.sender || mail.from_addrs.first return_path = "-f \" #{envelope_from.to_s.shellescape}\"" if envelope_from arguments = [settings[:arguments], return_path].compact.join( " " ) Sendmail.call(settings[:location], arguments, mail.destinations.collect(&:shellescape).join( " " ), mail) end def Sendmail.call(path, arguments, destinations, mail) IO.popen( "#{path} #{arguments} #{destinations}" , "r+" ) do |io| io.puts mail.encoded.to_lf io.close_write # <------ changed this from flush to close_write sleep 1 # <-------- added this line end end end end simply put this file e.g. into config/initializers/sendmail_patch.rb And I found some more more insights about it: If I run strace around this command, it works quite reliable also in the unpatched version. And in the unpatched version I've also seen messages like lost connection after DATA (949 bytes) from server... which makes it pretty clear, that this popen bug terminates sendmail during sending.
Hide
Permalink
Roger Pack added a comment -

is this still unresolved?

Show
Roger Pack added a comment - is this still unresolved?
Hide
Permalink
Heiko Seebach added a comment -

Hi,

I just tried it with 1.7.0.preview2:

hk@hk:~$ rvm use jruby-1.7.0.preview2
hk@hk:~$ ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now "
2012-09-17 14:05:27 +0100
2012-09-17 14:05:32 +0100
2012-09-17 14:05:32 +0100

hk@hk:~$ rvm use 1.9.3
hk@hk:~$ ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now "
2012-09-17 15:06:26 +0200
2012-09-17 15:06:31 +0200
2012-09-17 15:06:36 +0200

It's definitely still unresolved, yes.

Any idea/approach about how to solve that?

thanks, Heiko

Show
Heiko Seebach added a comment - Hi, I just tried it with 1.7.0.preview2: hk@hk:~$ rvm use jruby-1.7.0.preview2 hk@hk:~$ ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now " 2012-09-17 14:05:27 +0100 2012-09-17 14:05:32 +0100 2012-09-17 14:05:32 +0100 hk@hk:~$ rvm use 1.9.3 hk@hk:~$ ruby -e "cmd='/bin/bash -c \"sleep 5\"'; puts Time.now ; system(cmd); puts Time.now; IO.popen(cmd) {} ; puts Time.now " 2012-09-17 15:06:26 +0200 2012-09-17 15:06:31 +0200 2012-09-17 15:06:36 +0200 It's definitely still unresolved, yes. Any idea/approach about how to solve that? thanks, Heiko
Hide
Permalink
Heiko Seebach added a comment -

btw, there are other usecases, where this issue makes problems, e.g. here https://github.com/thoughtbot/cocaine/issues/24 and so in paperclip, which uses the cocaine gem

Show
Heiko Seebach added a comment - btw, there are other usecases, where this issue makes problems, e.g. here https://github.com/thoughtbot/cocaine/issues/24 and so in paperclip, which uses the cocaine gem
Hide
Permalink
Charles Oliver Nutter added a comment -

This may be something simple, like us not waiting for the process after dispatching to the block. Investigating.

Show
Charles Oliver Nutter added a comment - This may be something simple, like us not waiting for the process after dispatching to the block. Investigating.
Hide
Permalink
Charles Oliver Nutter added a comment -

Ok, so this patch makes it behave like you expect, but I need to look back at commit logics for my "obliterateProcess" change to remember why I was so aggressive about shutting down the child. I believe I observed behavior on MRI that indicated it doesn't wait...but it's also possible things have changed (I don't see any SIGTERM or anything in MRI trunk...it just seems to wait).

https://gist.github.com/3745153

Continuing my investigation.

Show
Charles Oliver Nutter added a comment - Ok, so this patch makes it behave like you expect, but I need to look back at commit logics for my "obliterateProcess" change to remember why I was so aggressive about shutting down the child. I believe I observed behavior on MRI that indicated it doesn't wait...but it's also possible things have changed (I don't see any SIGTERM or anything in MRI trunk...it just seems to wait). https://gist.github.com/3745153 Continuing my investigation.
Hide
Permalink
Charles Oliver Nutter added a comment -

Ok, the obliterateProcess stuff may have been me misunderstanding MRI C code at some point.

When shutting down an IO associated with a process, MRI does (in 1.8 and 1.9) an rb_syswait call. rb_syswait has mentions of SIGHUP, SIGQUIT, etc, but for handlers rather than as signals it is sending. It handlers for those signals before doing a waitpid, presumably to intercept them if the child receives them so the parent doesn't try to shut down. It then loops until the child process has completed, and replaces the handlers with what was installed before.

So at the moment I can find no evidence that a popen IO should attempt to kill the child process on close. It should do nothing more than shut down streams and wait.

I'm going to make that change and see what breaks.

Show
Charles Oliver Nutter added a comment - Ok, the obliterateProcess stuff may have been me misunderstanding MRI C code at some point. When shutting down an IO associated with a process, MRI does (in 1.8 and 1.9) an rb_syswait call. rb_syswait has mentions of SIGHUP, SIGQUIT, etc, but for handlers rather than as signals it is sending. It handlers for those signals before doing a waitpid, presumably to intercept them if the child receives them so the parent doesn't try to shut down. It then loops until the child process has completed, and replaces the handlers with what was installed before. So at the moment I can find no evidence that a popen IO should attempt to kill the child process on close. It should do nothing more than shut down streams and wait. I'm going to make that change and see what breaks.
Hide
Permalink
Roger Pack added a comment -

Sounds good. Hopefully jruby can also wait for a process in windows...
-r

Show
Roger Pack added a comment - Sounds good. Hopefully jruby can also wait for a process in windows... -r
Hide
Permalink
Charles Oliver Nutter added a comment -

Waiting will simply be done using waitFor on java.lang.Process, so it should work the same way on Windows. I wish I could remember why I went to such lengths to kill the child process, but I did find some comments talking about Java 5 bugs in waitFor. Perhaps I was trying to work around those bugs and went a little too far...

Show
Charles Oliver Nutter added a comment - Waiting will simply be done using waitFor on java.lang.Process, so it should work the same way on Windows. I wish I could remember why I went to such lengths to kill the child process, but I did find some comments talking about Java 5 bugs in waitFor. Perhaps I was trying to work around those bugs and went a little too far...
Hide
Permalink
Charles Oliver Nutter added a comment -

Well so far the change looks good. I'm running more tests, but should have this wrapped up momentarily.

Show
Charles Oliver Nutter added a comment - Well so far the change looks good. I'm running more tests, but should have this wrapped up momentarily.
Hide
Permalink
Charles Oliver Nutter added a comment -

Fingers crossed!!!

commit 2d497afa890b5da40f234ac63ef6fd4f270e032a
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Tue Sep 18 15:45:07 2012 -0500

    Fix JRUBY-6162
    
    IO.popen doesn't wait until a process ends but returns immediately
    
    I could find no evidence that MRI attempts to hup, quit, int, or
    kill popen child processes, so I removed logic we had in place
    that attempted to destroy the child. The logic now waits properly
    and all tests still pass...so I think we're good.

:100644 100644 7d64db1... 878fc1d... M	src/org/jruby/RubyIO.java
:100644 100644 244899c... baee9be... M	src/org/jruby/util/ShellLauncher.java
Show
Charles Oliver Nutter added a comment - Fingers crossed!!! commit 2d497afa890b5da40f234ac63ef6fd4f270e032a Author: Charles Oliver Nutter <headius@headius.com> Date: Tue Sep 18 15:45:07 2012 -0500 Fix JRUBY-6162 IO.popen doesn't wait until a process ends but returns immediately I could find no evidence that MRI attempts to hup, quit, int, or kill popen child processes, so I removed logic we had in place that attempted to destroy the child. The logic now waits properly and all tests still pass...so I think we're good. :100644 100644 7d64db1... 878fc1d... M src/org/jruby/RubyIO.java :100644 100644 244899c... baee9be... M src/org/jruby/util/ShellLauncher.java
Hide
Permalink
Heiko Seebach added a comment -

Congrats, Charles
Thank you very much,
Heiko

Show
Heiko Seebach added a comment - Congrats, Charles Thank you very much, Heiko
Hide
Permalink
Roger Pack added a comment -


seems to work here at least for trivial cases, thanks much! If waiting on a process is possible in windows now, maybe this bug could also be addressed at some point in the future? http://jira.codehaus.org/browse/JRUBY-4354 Thanks! -r

Show
Roger Pack added a comment - seems to work here at least for trivial cases, thanks much! If waiting on a process is possible in windows now, maybe this bug could also be addressed at some point in the future? http://jira.codehaus.org/browse/JRUBY-4354 Thanks! -r
Hide
Permalink
Charles Oliver Nutter added a comment -

Going to have to reopen this; fixing it to not try to shut down the child process causes some specs to hang...which could lead to hangs for users running RC1. We need to dig a bit deeper and figure out the right magic for popen subprocesses before 1.7 final.

Reverted 2d497af in 73ce313.

Show
Charles Oliver Nutter added a comment - Going to have to reopen this; fixing it to not try to shut down the child process causes some specs to hang...which could lead to hangs for users running RC1. We need to dig a bit deeper and figure out the right magic for popen subprocesses before 1.7 final. Reverted 2d497af in 73ce313.

People

  • Assignee:
    Charles Oliver Nutter
    Reporter:
    Heiko Seebach
Vote (4)
Watch (7)

Dates

  • Created:
    Updated: