Weird error using IO.copy_stream, IO duck types and enumerators #4903

HoneyryderChuck · 2017-12-18T11:41:25Z

Environment

JRuby 9.1.15.0
Darwin Macintosh.local 16.7.0 Darwin Kernel Version 16.7.0: Mon Nov 13 21:56:25 PST 2017; root:xnu-3789.72.11~1/RELEASE_X86_64 x86_64
To test with latest http-form_data, and with a jpg image (preferably with 46K)

Expected Behavior

I have a very similar code to the one from this sample:

require "http/form_data"

file = HTTP::FormData::File.new(File.join(__dir__, "..", "test", "support", "fixtures", "image.jpg")) 
$buffer = HTTP::FormData.create(image: file)


class ProcIO
  def initialize(&blk)
   @blk = blk
  end

  def write(data)
    @blk.call(data)
    data.bytesize
  end
end


def lazy_stream(&blk)
  return enum_for(__method__) unless block_given?
  IO.copy_stream($buffer, ProcIO.new(&blk))
end

def drain_stream
  @drain_stream ||= lazy_stream
  chunk = @drain_stream.next
  chunk = chunk.dup
  puts "1. drain size: #{chunk.bytesize}"
  # puts "2: drained: #{chunk[0..400].inspect}"
  chunk
rescue StopIteration
  nil 
end

while chunk = drain_stream
  puts "1. yielded size: #{chunk.bytesize}"
  # puts "2. yield #{chunk[0..400].inspect}"
  puts
end

(The puts calls are to debug and show the error)

The purpose of this code is to enumerate the IO.copy_stream call, so that its chunks can be managed inside the while block. This code works in MRI (tested with 2.4).

The main difference in implementation is that in MRI, IO.copy_stream yields chunks of 16384 bytes, while JRuby yields 8192 bytes. I've followed this into this ticket, which leads me to believe that I can't reproduce this bug in older versions of jruby (as they were buffering the source in memory).

If you limit the debug statements to 1. , you'll see these outputs.

# MRI
1. drain size: 16384
1. yielded size: 16384

1. drain size: 16384
1. yielded size: 16384

1. drain size: 13720
1. yielded size: 13720

# JRuby
1. drain size: 8192
1. yielded size: 8192

1. drain size: 8192
1. yielded size: 8192

1. drain size: 8192
1. yielded size: 8192

1. drain size: 8192
1. yielded size: 8192

1. drain size: 8192
1. yielded size: 8192

1. drain size: 5528
1. yielded size: 5528

In the end, the total bytes yielded in both solutions is similar. The gist of it is, the drained chunk must be equal to the yielded chunk.

However, if you limit the debug statements to 2. , you'll see that this is not the case in JRuby:

# MRI
2: drained: "-----------..."
2. yield "-----------..."

2: drained: "\xAE}\xCC#\xFF\x00\x88\xAF\x86\xCD|..."
2. yield "\xAE}\xCC#\xFF\x00\x88\xAF\x86\xCD|..."

2: drained: "\x15\xC7\xAC\x19$\x89\x04\x12N\xE0\b..."
2. yield "\x15\xC7\xAC\x19$\x89\x04\x12N\xE0\b..."

# JRuby
2: drained: "\x86\xC1\xA8d\xB4,\xC16\xF6\x8B\x05..."
2. yield "\x86\xC1\xA8d\xB4,\xC16\xF6\x8B\x05..."

2: drained: "\x86\xC1\xA8d\xB4,\xC16\xF6\x8B\x05..."
2. yield "\x86\xC1\xA8d\xB4,\xC16\xF6\x8B\x05..."

2: drained: "\xAE}\xCC#\xFF\x00\x88\xAF\x86\xCD|..."
2. yield "v\x1A\xCF\xB6\tF\x9D\x82\xC8\xFD|..."

2: drained: "v\x1A\xCF\xB6\tF\x9D\x82\xC8\xFD|..."
2. yield "v\x1A\xCF\xB6$\x89\x04\x12N\xE0\b..."

2: drained: "\x15\xC7\xAC\x19$\x89\x04\x12N\xE0\b..."
2. yield "\x15\xC7\xAC\x19$\x89\x04\x12N\xE0\b..."

2: drained: "\xCA\xF6;\x18\x00\xA9 \xF5\x13\x89G..."
2. yield "\xCA\xF6;\x18\x00\xA9 \xF5\x13\x89G..."

(check the 3rd yield)

Actual Behavior

As stated, I expect the pairs to be the same all the time.

I couldn't single out exactly what is the problem (The File buffer, the IO.copy_stream call, the enumeration...), and had to completely reproduce my usage to create this short script. But it's definitely a bug.

The text was updated successfully, but these errors were encountered:

headius · 2017-12-19T15:13:07Z

How peculiar! I'll have a look.

headius · 2017-12-19T15:37:38Z

Well so far I can't reproduce this with some random content I generated locally. The chunks appear to match.

I also reviewed the changes made for #4842, and I did not see any obvious bugs there.

The related commits are cd40c31 and f77f4b4.

HoneyryderChuck · 2017-12-19T16:24:58Z

Really? I'd expect something else, I can reproduce it very consistently. How big was your image?

headius · 2017-12-20T16:27:08Z

There's definitely something strange going on. With some larger input I am seeing something similar to what you reported, but it doesn't make any sense. The chunk produced by @drain_stream.next is passed back to the loop. It seems like something is continuing to modify that string, or it is malformed to begin with.

HoneyryderChuck · 2017-12-21T06:57:19Z

yes, when I mean "consistently", I mean "repeating task and seeing it fail quite often". I'm not sure what I should attribute this to, but I'd say it is some internal buffering issue. My problem is "scaling down" my example to know where this actually happens, as if I try to simplify the code path, suddenly everything works flawlessly.

headius · 2018-01-24T18:23:59Z

I still do not have an explanation for this. Poking at it a bit this afternoon.

headius · 2018-01-24T18:33:13Z

Ok, I think I've figured out the issue.

Our Enumerator#next is frequently (usually) backed by a thread, since we do not have a way to do coroutines (e.g. lightweight Fibers) on the JVM. The logic for this thread should pause each time through the loop, waiting for the next item to be requested. In actuality, I believe it is immediately continuing to the next loop, which in this case results in the returned buffer getting overwritten before it can even be dup'ed.

I am trying to confirm this by examining logic in copy_stream to see if it's reusing the same buffer repeatedly without marking it as shared.

Due to a bug in how Enumerator#next progresses (it will run an iteration ahead of requested) this bug was exposed as #4903 where an Enumerator#next-based sink for IO.copy_stream showed previously-returned results getting modified after handoff. The same buffer array was being shared across all chunks written, which works ok if that view were only used within the confines of copy_stream, but in this case the chunks were held across more than a single write. Fixes #4903. See #5007 for the Enumerator#next bug.

headius · 2018-01-24T20:44:21Z

I've pushed a fix for the issue causing the data to be overwritten after it is returned. The triggering issue, Enumerator#next not waiting for a subsequent call to continue iterating, is in #5007 and will probably be fixed in next major release.

HoneyryderChuck · 2018-01-24T20:55:37Z

nice, thx for the fix! I'll test it as soon as I can.

HoneyryderChuck · 2018-02-21T22:45:53Z

@headius just tested this, and I can confirm the fix. Thx again for the top-level support!

When the incoming bytes are on the heap, we can use them in-place for the string we pass to the Ruby write method. However, since the target IO-like may want to modify the incoming string, we must make sure it is marked as shared so our original src bytes will not be modified. This issue originally manifested in jruby#4903 and was fixed by always copying the incoming buffer, but marking the string shared has the same effecit if the target attempts to make any modifications.

headius self-assigned this Dec 19, 2017

headius mentioned this issue Jan 24, 2018

Enumerator#next proceeds to next iteration without being called again #5007

Closed

headius added this to the JRuby 9.1.16.0 milestone Jan 24, 2018

headius closed this as completed Jan 24, 2018

headius mentioned this issue Oct 11, 2018

Lazy enumerable select eagerly evaluates next item #4212

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GitHub Sponsors

Weird error using IO.copy_stream, IO duck types and enumerators #4903

Weird error using IO.copy_stream, IO duck types and enumerators #4903

HoneyryderChuck commented Dec 18, 2017

headius commented Dec 19, 2017

headius commented Dec 19, 2017

HoneyryderChuck commented Dec 19, 2017

headius commented Dec 20, 2017

HoneyryderChuck commented Dec 21, 2017

headius commented Jan 24, 2018

headius commented Jan 24, 2018

headius commented Jan 24, 2018

HoneyryderChuck commented Jan 24, 2018

HoneyryderChuck commented Feb 21, 2018

Weird error using IO.copy_stream, IO duck types and enumerators #4903

Weird error using IO.copy_stream, IO duck types and enumerators #4903

Comments

HoneyryderChuck commented Dec 18, 2017

Environment

Expected Behavior

Actual Behavior

headius commented Dec 19, 2017

headius commented Dec 19, 2017

HoneyryderChuck commented Dec 19, 2017

headius commented Dec 20, 2017

HoneyryderChuck commented Dec 21, 2017

headius commented Jan 24, 2018

headius commented Jan 24, 2018

headius commented Jan 24, 2018

HoneyryderChuck commented Jan 24, 2018

HoneyryderChuck commented Feb 21, 2018