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

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

Closed
HoneyryderChuck opened this Issue Dec 18, 2017 · 10 comments

Comments

Projects
None yet
2 participants
@HoneyryderChuck

HoneyryderChuck commented Dec 18, 2017

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.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Dec 19, 2017

Member

How peculiar! I'll have a look.

Member

headius commented Dec 19, 2017

How peculiar! I'll have a look.

@headius headius self-assigned this Dec 19, 2017

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Dec 19, 2017

Member

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.

Member

headius commented Dec 19, 2017

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

This comment has been minimized.

Show comment
Hide comment
@HoneyryderChuck

HoneyryderChuck Dec 19, 2017

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

HoneyryderChuck commented Dec 19, 2017

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

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Dec 20, 2017

Member

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.

Member

headius commented Dec 20, 2017

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

This comment has been minimized.

Show comment
Hide comment
@HoneyryderChuck

HoneyryderChuck Dec 21, 2017

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.

HoneyryderChuck commented Dec 21, 2017

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

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 24, 2018

Member

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

Member

headius commented Jan 24, 2018

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

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 24, 2018

Member

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.

Member

headius commented Jan 24, 2018

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.

headius added a commit that referenced this issue Jan 24, 2018

Don't view the same buffer; it might be updated while in use.
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 headius added this to the JRuby 9.1.16.0 milestone Jan 24, 2018

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 24, 2018

Member

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.

Member

headius commented Jan 24, 2018

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.

@headius headius closed this Jan 24, 2018

@HoneyryderChuck

This comment has been minimized.

Show comment
Hide comment
@HoneyryderChuck

HoneyryderChuck Jan 24, 2018

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

HoneyryderChuck commented Jan 24, 2018

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

@HoneyryderChuck

This comment has been minimized.

Show comment
Hide comment
@HoneyryderChuck

HoneyryderChuck Feb 21, 2018

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

HoneyryderChuck commented Feb 21, 2018

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

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