New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

STDOUT redirect fails in JRuby #4855

Open
cshupp1 opened this Issue Nov 16, 2017 · 6 comments

Comments

Projects
None yet
3 participants
@cshupp1

cshupp1 commented Nov 16, 2017

Consider the following irb session in MRI ruby:

Microsoft Windows [Version 10.0.15063]
(c) 2017 Microsoft Corporation. All rights reserved.

    C:\work\cui_work\misc_utilities>irb
irb(main):001:0> RUBY_VERSION
=> "2.3.3"
irb(main):002:0> log_file = 'c:\temp\log\jruby1.txt'
=> "c:\\temp\\log\\jruby1.txt"
irb(main):003:0> STDOUT.reopen(log_file)

At this point the the irb session appears to lock up, but it isn't really...

Into the irb session I will type:

puts "I love JRuby!!!"

But I will not see that I typed it here, nor will I see the output. Where is it?

C:\work\cui_work\misc_utilities>cat c:\temp\log\jruby1.txt
=> #<IO:c:\temp\log\jruby1.txt>
irb(main):004:0> puts "I love JRuby!!!!"
I love JRuby!!!!
=> nil
irb(main):005:0>

Let us try JRuby:

C:\work\va-ctt\rails>java -jar %JRUBY_JAR% -S jirb
irb(main):001:0> JRUBY_VERSION
=> "9.1.13.0"
irb(main):002:0> log_file = 'c:\temp\log\jruby2.txt'
=> "c:\\temp\\log\\jruby2.txt"
irb(main):003:0> STDOUT.reopen(log_file)
Errno::ENOENT: No such file or directory - c:\temp\log\jruby2.txt
from org/jruby/RubyIO.java:643:in `reopen'
        from (irb):3:in `<eval>'
        from org/jruby/RubyKernel.java:994:in `eval'
from org/jruby/RubyKernel.java:1292:in `loop'
        from org/jruby/RubyKernel.java:1114:in `catch'
        from org/jruby/RubyKernel.java:1114:in `catch'
from uri:classloader:/META-INF/jruby.home/bin/jirb:13:in `<main>'

JRuby will not create the file, MRI ruby does... I will do this:

touch c:\temp\log\jruby2.txt

Trying again:

irb(main):004:0> STDOUT.reopen(log_file)
=> #<IO:c:\temp\log\jruby2.txt>
irb(main):005:0> puts "I love JRuby!!!"
I love JRuby!!!
=> nil
irb(main):006:0> exit

Yields:

C:\work\cui_work\misc_utilities>cat c:\temp\log\jruby2.txt

C:\work\cui_work\misc_utilities>

Why aren't the two consistent?

Thanks,

Cris

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 20, 2017

Member

There's two possibilities.

The first is due to differences in how IO is implemented on Windows versus on UNIX in JRuby. Because Windows POSIX is a little spotty in places, we need to use win32 functions to emulate Ruby behavior. We have not done this work yet. It could affect reopening stdio streams because on Windows they just wrap the ones the JDK provides, rather than being true native streams.

The second is due to our implementation of Readline, which currently uses a Java library called jline. Unfortunately this library takes over the stdio streams, breaking code like yours that wants to be in IRB and still redirect stdio.

On my macos system, your code appeared to work just fine, which makes me think it's not directly a jline problem.

FWIW, this may be the same problem (or similar) as #1372. See also #3721.

Member

headius commented Nov 20, 2017

There's two possibilities.

The first is due to differences in how IO is implemented on Windows versus on UNIX in JRuby. Because Windows POSIX is a little spotty in places, we need to use win32 functions to emulate Ruby behavior. We have not done this work yet. It could affect reopening stdio streams because on Windows they just wrap the ones the JDK provides, rather than being true native streams.

The second is due to our implementation of Readline, which currently uses a Java library called jline. Unfortunately this library takes over the stdio streams, breaking code like yours that wants to be in IRB and still redirect stdio.

On my macos system, your code appeared to work just fine, which makes me think it's not directly a jline problem.

FWIW, this may be the same problem (or similar) as #1372. See also #3721.

@cshupp1

This comment has been minimized.

Show comment
Hide comment
@cshupp1

cshupp1 Nov 20, 2017

Apologies if I didn't mention it, but yes this problem seems exclusive to windows. It is part of a larger problem. We have a Sinatra application that runs fine on Mac and Linux (using these APIS). On windows these APIS cause the application to just die. No Exceptions, just death...

cshupp1 commented Nov 20, 2017

Apologies if I didn't mention it, but yes this problem seems exclusive to windows. It is part of a larger problem. We have a Sinatra application that runs fine on Mac and Linux (using these APIS). On windows these APIS cause the application to just die. No Exceptions, just death...

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 20, 2017

Member

How does this affect a Sinatra application?

Member

headius commented Nov 20, 2017

How does this affect a Sinatra application?

@cshupp1

This comment has been minimized.

Show comment
Hide comment
@cshupp1

cshupp1 Nov 20, 2017

Again apologies for my lack of clarity...

The Sinatra app runs in MRI ruby. When I bring it up it does it's initial babbling and then it just dies, without any exception, but only on Windows. Mac and Linux users have no problems. I begin to suspect it was the 'STDOUT.reopen' that was causing the issues. Out of curiosity, I tried it in JRuby. When JRuby returned:

#<IO:c:\temp\log\jruby2.txt>

and MRI Ruby appeared to lock up I thought I had found the first instance of a bug on Windows MRI Ruby that JRuby could handle. It took further digging before I realized what was going on. It motivated the diff (I will place it last) where I pulled out those redirects. It results in the Sinatra app working on Windows, Linux, and Mac. Again, this app runs via MRI. I just thought I should write up the JRuby bug. Perhaps I stumbled upon a case where two wrongs make a right.

diff --git a/via_soap_emulator/lib/via_soap_emulator.rb b/via_soap_emulator/lib/via_soap_emulator.rb
index fd270c7..38b4028 100755
--- a/via_soap_emulator/lib/via_soap_emulator.rb
+++ b/via_soap_emulator/lib/via_soap_emulator.rb
@@ -18,25 +18,57 @@ LOG_DIR     = CURRENT_DIR + 'log'
 
 prep_the_globals
 
+at_exit do
+  puts "Goodbye!"
+  LOG_HANDLE.close
+end #must be before sinatra
 require 'sinatra'
 
 set :server,  :webrick
 set :port,    (ENV['VIA_PORT'] || '9292').to_i
 
-log_file = "#{LOG_DIR}/#{settings.environment}.log"
-STDOUT.reopen(log_file)
-STDERR.reopen(log_file)
-STDOUT.sync = true
-STDERR.sync = true
+LOG_FILE = "#{LOG_DIR}/#{settings.environment}.log".freeze
+LOG_HANDLE = File.new(LOG_FILE, File::CREAT|File::RDWR|File::TRUNC)
+
+
+module Kernel
+  alias :original_puts :puts
+  alias :original_warn :warn
+end
+
+def log(str)
+  LOG_HANDLE.write(str.to_s + "\n")
+  LOG_HANDLE.flush
+  #original_puts "Wrote to file" #note: you can do things like this here!
+end
+
+def chat (obj, *arg, redirect)
+  log(obj)
+  arg.each do |e|
+    log(e)
+  end
+  self.send(redirect, obj, *arg) #append to the real stdout/sderr too!
+  nil
+end
+
+module Kernel
+  def puts(obj='', *arg)
+    chat(obj, *arg, :original_puts)
+  end
+
+  def warn(msg, *smth)
+    chat(msg, *smth, :original_warn)
+  end
+
+end
 
 configure do
   enable :logging
-  file = File.open(log_file, 'w')
+  file = LOG_HANDLE
   file.sync = true
   use Rack::CommonLogger, file
 end
 
-
 get '/' do
   haml :index
 end
@@ -48,13 +80,12 @@ end
 
 
 get '/log' do
-  File.open(log_file, 'r').read.gsub("\n",'<br>')
+  File.open(LOG_FILE).read.gsub("\n",'<br>')
 end
 
 
 get '/log/clear' do
-  STDOUT.reopen(log_file)
-  STDERR.reopen(STDOUT)
+  LOG_HANDLE.truncate(0)
   redirect '/'
 end
 
@@ -88,7 +119,7 @@ get '/:end_point' do |end_point|
 
   print_stuff
 
-  render_an_xml_file_for end_point
+  render_an_xml_file_for service: "???", end_point: end_point
 end
 

cshupp1 commented Nov 20, 2017

Again apologies for my lack of clarity...

The Sinatra app runs in MRI ruby. When I bring it up it does it's initial babbling and then it just dies, without any exception, but only on Windows. Mac and Linux users have no problems. I begin to suspect it was the 'STDOUT.reopen' that was causing the issues. Out of curiosity, I tried it in JRuby. When JRuby returned:

#<IO:c:\temp\log\jruby2.txt>

and MRI Ruby appeared to lock up I thought I had found the first instance of a bug on Windows MRI Ruby that JRuby could handle. It took further digging before I realized what was going on. It motivated the diff (I will place it last) where I pulled out those redirects. It results in the Sinatra app working on Windows, Linux, and Mac. Again, this app runs via MRI. I just thought I should write up the JRuby bug. Perhaps I stumbled upon a case where two wrongs make a right.

diff --git a/via_soap_emulator/lib/via_soap_emulator.rb b/via_soap_emulator/lib/via_soap_emulator.rb
index fd270c7..38b4028 100755
--- a/via_soap_emulator/lib/via_soap_emulator.rb
+++ b/via_soap_emulator/lib/via_soap_emulator.rb
@@ -18,25 +18,57 @@ LOG_DIR     = CURRENT_DIR + 'log'
 
 prep_the_globals
 
+at_exit do
+  puts "Goodbye!"
+  LOG_HANDLE.close
+end #must be before sinatra
 require 'sinatra'
 
 set :server,  :webrick
 set :port,    (ENV['VIA_PORT'] || '9292').to_i
 
-log_file = "#{LOG_DIR}/#{settings.environment}.log"
-STDOUT.reopen(log_file)
-STDERR.reopen(log_file)
-STDOUT.sync = true
-STDERR.sync = true
+LOG_FILE = "#{LOG_DIR}/#{settings.environment}.log".freeze
+LOG_HANDLE = File.new(LOG_FILE, File::CREAT|File::RDWR|File::TRUNC)
+
+
+module Kernel
+  alias :original_puts :puts
+  alias :original_warn :warn
+end
+
+def log(str)
+  LOG_HANDLE.write(str.to_s + "\n")
+  LOG_HANDLE.flush
+  #original_puts "Wrote to file" #note: you can do things like this here!
+end
+
+def chat (obj, *arg, redirect)
+  log(obj)
+  arg.each do |e|
+    log(e)
+  end
+  self.send(redirect, obj, *arg) #append to the real stdout/sderr too!
+  nil
+end
+
+module Kernel
+  def puts(obj='', *arg)
+    chat(obj, *arg, :original_puts)
+  end
+
+  def warn(msg, *smth)
+    chat(msg, *smth, :original_warn)
+  end
+
+end
 
 configure do
   enable :logging
-  file = File.open(log_file, 'w')
+  file = LOG_HANDLE
   file.sync = true
   use Rack::CommonLogger, file
 end
 
-
 get '/' do
   haml :index
 end
@@ -48,13 +80,12 @@ end
 
 
 get '/log' do
-  File.open(log_file, 'r').read.gsub("\n",'<br>')
+  File.open(LOG_FILE).read.gsub("\n",'<br>')
 end
 
 
 get '/log/clear' do
-  STDOUT.reopen(log_file)
-  STDERR.reopen(STDOUT)
+  LOG_HANDLE.truncate(0)
   redirect '/'
 end
 
@@ -88,7 +119,7 @@ get '/:end_point' do |end_point|
 
   print_stuff
 
-  render_an_xml_file_for end_point
+  render_an_xml_file_for service: "???", end_point: end_point
 end
 

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 21, 2017

Member

Ahh ok, so this isn't something unique to Sinatra; it would affect any library that attempts to redirect STDOUT using reopen on Windows.

I thought that reopen used to work even with the JDK streams. Perhaps we regressed.

Member

headius commented Nov 21, 2017

Ahh ok, so this isn't something unique to Sinatra; it would affect any library that attempts to redirect STDOUT using reopen on Windows.

I thought that reopen used to work even with the JDK streams. Perhaps we regressed.

@headius headius added this to the JRuby 9.1.15.0 milestone Nov 21, 2017

@headius headius modified the milestones: JRuby 9.1.15.0, JRuby 9.2.0.0 Nov 29, 2017

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Nov 29, 2017

Member

Most likely to happen with Windows IO work in 9.2 (unstarted).

Member

headius commented Nov 29, 2017

Most likely to happen with Windows IO work in 9.2 (unstarted).

@enebo enebo modified the milestones: JRuby 9.2.0.0, JRuby 9.2.1.0 May 24, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment