Timeout on JRuby on Windows

[joankaradimov]

I am experiencing an issue in multipart-post 2.0.0. I have a client piece of code that looks roughly like this:

require 'net/http'
require 'net/http/post/multipart'

http = Net::HTTP.new('localhost', 8080)

http.start do |http|
  File.open('C:/data/asd.png') do |png|
    req = Net::HTTP::Post::Multipart.new('http://localhost:8080/some-endpoint',
      'uploadId' => "some-internal-data",
      'files[]' => UploadIO.new(png, 'image/png', 'asd.png'),
      'size' => 186670,
      )

    # Some headers for session ID and CSRF protection
    req['Cookie'] = "JSESSIONID=1234567890abcdef"
    req['X-Requested-By'] = 'UNUSED'

    http.request(req)
  end
end

The code runs on JRuby 9.1.6.0 on Windows 10. When I run it I get this stack trace:

Net::ReadTimeout: Net::ReadTimeout
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/protocol.rb:158:in `rbuf_fill'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/protocol.rb:136:in `readuntil'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/protocol.rb:146:in `readline'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http/response.rb:40:in `read_status_line'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http/response.rb:29:in `read_new'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http.rb:1448:in `block in transport_request'
        from org/jruby/RubyKernel.java:1118:in `catch'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http.rb:1445:in `transport_request'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http.rb:1418:in `request'
        from (irb):19:in `block in evaluate'
        from org/jruby/RubyIO.java:1141:in `open'
        from (irb):11:in `block in evaluate'
        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http.rb:858:in `start'
        from (irb):10:in `<eval>'
        from org/jruby/RubyKernel.java:998:in `eval'
        from org/jruby/RubyKernel.java:1299:in `loop'
        from org/jruby/RubyKernel.java:1118:in `catch'
        from org/jruby/RubyKernel.java:1118:in `catch'
        from jirb:13:in `<main>'

On the server side there is a Java + Tomcat on Windows. The output from the server is java.net.SocketTimeoutException: null. The stack trace on the server is most likely irrelevant.

I've tried identical code on a JRuby/Linux client with the exact same Java/Windows server and it worked. Furthermore - I tried MRI/Windows client and it worked too. I also tried some older builds of JRuby I have locally and they failed. So there appears to be some incompatibility in multipart-post with JRuby on Windows.

I'm not even sure if I should be logging this here. Still it's probably good to have it here so that it's visible for users of the library. Is there something that can be done other than forwarding this to the JRuby guys?

[ioquatix]

I think this is useful. Thanks to your deep investigation, we know it's probably something to do with JRuby. However, please keep us updated! :)

[joankaradimov]

I haven't logged a bug in JRuby yet. Should I? Could this be a problem in multipart-post?

[ioquatix]

Based on the backtrace, it looks like the issue is receiving the response:

        from C:/dev/jruby-9.1.6.0/lib/ruby/stdlib/net/http/response.rb:40:in `read_status_line'

But it looks like it's not reading the response correctly and blocking, then timing out.

I don't think it's the fault of multipart-post. If you want to dig a bit deeper, you could try doing a packet capture to see what data is actually being sent back to JRuby. this would be most informative.

[universal]

I'm experiencing the same problem and I've written some dummy app/client to reproduce. I've put the code into the following repository: https://github.com/universal/jruby-multipart-post-test . I've been experiencing this problem for a while now and have circumvented it by using a "java based uploader", but this is not ideal ;)

Also not sure if it is an error of the multipart-post lib, or jruby... maybe there is a flush missing somewhere ;) Non-multipart-posts work fine.

[joankaradimov]

The weirdest thing happened. A colleague of mine finished the piece of code on his Linux. And it now works on my Windows too. The file he is uploading is a plain text file full of the x character. So it's obviously the content of the file. After a little digging I came up this piece of code that fails:

path = 'C:\dev\test.txt'
File.open(path, 'w') do |f|
  f.print "\r\n"
end

File.open(path) do |file|
  req = Net::HTTP::Post::Multipart.new(
    uri('/objects'),
    'uploadId' => upload_id.to_s,
    'files[]' => UploadIO.new(file, 'text/plain', file_name),
    'size' => size,
  )
  req[HttpHeaders::COOKIE] = cookie
  req[CsrfProtectionFilter::HEADER_NAME] = 'UNUSED'
  http.request(req)
end

... yep, CRLF, obviously. Pretty much anything else I tried printing to the file works just fine (my other guesses included "\n", "\0", and a lone "\r").

[joankaradimov]

P.S.
Opening the file like this File.open(path, 'rb') worked fine.

@universal can you confirm this? I wasn't able to run the rails endpoint in jruby-multipart-post-test.

My initial guess was that the content_len parameter of the build_head function in parts.rb had the wrong value. But that's not it. So I'll have to dig some more.

[ioquatix]

This is really awesome, everyone. Thanks for digging into this. So, it looks like a bug to do with the multi-part escaping if the file contains CRLF. Is that correct?

[universal]

Opening the file in 'rb' mode works. My files have been binary all the time, so not sure it is really CRLF causing the error, though they obviously could have contained the byte sequence for CRLF. Maybe it is an encoding issue where too many bytes read in non-binary mode? To be honest I'm kinda clueless.

The variant with File.new also works if you supply the optional mode parameter: File.new("some_file", "rb")

Going to do some tries with the text-files :-)

[universal]

I made some tests with the text-files, and as soon as the file contains a CRLF somewhere it fails, only on JRuby though. So I'm not sure if it just works by accident on Ruby, and it is actually correct to fail on JRuby, since one is supposed to read stuff in binary mode for multipart?

Checks with text files
####################
Trying with mode: r
Trying content: "\r"
success
Trying content: "\n"
success
Trying content: "\u0000"
success
Trying content: "\r\n"
>>> Failed! <<<
Trying content: "a\r"
success
Trying content: "a\n"
success
Trying content: "a\u0000"
success
Trying content: "a\r\n"
>>> Failed! <<<
Trying content: "\ra"
success
Trying content: "\na"
success
Trying content: "\u0000a"
success
Trying content: "\r\na"
>>> Failed! <<<
####################
Trying with mode: rb
Trying content: "\r"
success
Trying content: "\n"
success
Trying content: "\u0000"
success
Trying content: "\r\n"
success
Trying content: "a\r"
success
Trying content: "a\n"
success
Trying content: "a\u0000"
success
Trying content: "a\r\n"
success
Trying content: "\ra"
success
Trying content: "\na"
success
Trying content: "\u0000a"
success
Trying content: "\r\na"
success
finished

[joankaradimov]

The problem appears to be a mismatch between the file size and the length of the byte array that is read from the file.

Using the example image.jpg from universal/jruby-multipart-post-test I get:

irb(main):001:0> f = File.new('image.jpg')
=> #<File:image.jpg>
irb(main):002:0> f.size
=> 135524
irb(main):003:0> f.read.length
=> 135523
irb(main):004:0> f.close
=> nil

However, this keeps getting weirder. That mismatch exists in MRI as well (2.4.1-1 from rubyinstaller.org). And it looks even worse...

irb(main):001:0> f = File.new('image.jpg')
=> #<File:image.jpg>
irb(main):002:0> f.size
=> 135524
irb(main):003:0> f.read.length
=> 708
irb(main):004:0> f.close
=> nil

@universal What flavour of MRI Ruby are you using when testing? Is it from https://rubyinstaller.org/ or is it by chance something from Cygwin/MSYS2?

[universal]

the mri ruby is the rubyinstaller one, 2.3.3 iirc. no cygwin. is there anything you'd like me to check/try?

following tests are on 2.4.1 under ubuntu :-)

2.4.1 :005 > f = File.open("image.jpg", "rb")
 => #<File:image.jpg> 
2.4.1 :006 > f.size
 => 135524 
2.4.1 :007 > f.read.length
 => 135524 
2.4.1 :008 > rbr = f.read[0..100]
 => "" 
2.4.1 :009 > f.rewind
 => 0 
2.4.1 :010 > rbr = f.read[0..100]
 => "\xFF\xD8\xFF\xE0\x00\x10JFIF\x00\x01\x01\x01\x01,\x01,\x00\x00\xFF\xE1\x01\x04Exif\x00\x00MM\x00*\x00\x00\x00\b\x00\x04\x01\x0F\x00\x02\x00\x00\x00\x12\x00\x00\x00>\x01\x10\x00\x02\x00\x00\x00\v\x00\x00\x00P\x82\x9A\x00\x05\x00\x00\x00\x01\x00\x00\x00[\x87i\x00\x04\x00\x00\x00\x01\x00\x00\x00c\x00\x00\x00\x00NIKON COR" 
2.4.1 :011 > f.close
 => nil 
2.4.1 :012 > f = File.open("image.jpg")
 => #<File:image.jpg> 
2.4.1 :013 > rdr = f.read[0..100]
 => "\xFF\xD8\xFF\xE0\u0000\u0010JFIF\u0000\u0001\u0001\u0001\u0001,\u0001,\u0000\u0000\xFF\xE1\u0001\u0004Exif\u0000\u0000MM\u0000*\u0000\u0000\u0000\b\u0000\u0004\u0001\u000F\u0000\u0002\u0000\u0000\u0000\u0012\u0000\u0000\u0000>\u0001\u0010\u0000\u0002\u0000\u0000\u0000\v\u0000\u0000\u0000P\x82\x9A\u0000\u0005\u0000\u0000\u0000\u0001\u0000\u0000\u0000[\x87i\u0000\u0004\u0000\u0000\u0000\u0001\u0000\u0000\u0000c\u0000\u0000\u0000\u0000NIKON COR" 
2.4.1 :014 > f.close
 => nil 
2.4.1 :016 > rdr.encoding
 => #<Encoding:UTF-8> 
2.4.1 :017 > rbr.encoding
 => #<Encoding:ASCII-8BIT>
 f = File.open("image.jpg")
 => #<File:image.jpg> 
2.4.1 :020 > f.read.bytesize
 => 135524 

so reading in default mode, reads it as a utf-8 encoded string, so multiple bytes get coerced into one "char", so size in bytes and length don't match anymore!