Skip to content

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

Closed
Closed
Weird error using IO.copy_stream, IO duck types and enumerators#4903
Assignees
headius
Milestone
JRuby 9.1.16.0

Description

@HoneyryderChuck
HoneyryderChuck
opened on 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.

Activity

  1. headius commented on Dec 19, 2017

    @headius
    headius
    on Dec 19, 2017
    Member

    How peculiar! I'll have a look.

  2. headius
    self-assigned this
    on Dec 19, 2017

  3. headius commented on Dec 19, 2017

    @headius
    headius
    on 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.

  4. HoneyryderChuck commented on Dec 19, 2017

    @HoneyryderChuck
    HoneyryderChuck
    on Dec 19, 2017
    Author

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

  5. headius commented on Dec 20, 2017

    @headius
    headius
    on 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.

  6. HoneyryderChuck commented on Dec 21, 2017

    @HoneyryderChuck
    HoneyryderChuck
    on Dec 21, 2017
    Author

    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.

  7. headius commented on Jan 24, 2018

    @headius
    headius
    on Jan 24, 2018
    Member

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

  8. headius commented on Jan 24, 2018

    @headius
    headius
    on 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.

  9. headius
    added a commit that references this issue on Jan 24, 2018

    Don't view the same buffer; it might be updated while in use.

    c9bfede
  10. headius
    added this to the JRuby 9.1.16.0 milestone on Jan 24, 2018

  11. headius commented on Jan 24, 2018

    @headius
    headius
    on 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.

  12. headius
    closed this as completedon Jan 24, 2018

  13. HoneyryderChuck commented on Jan 24, 2018

    @HoneyryderChuck
    HoneyryderChuck
    on Jan 24, 2018
    Author

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

  14. HoneyryderChuck commented on Feb 21, 2018

    @HoneyryderChuck
    HoneyryderChuck
    on Feb 21, 2018
    Author

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

  15. headius
    added 2 commits that reference this issue on Feb 12, 2021

    Avoid write target modifying shared src bytes

    fdb251b

    Avoid write target modifying shared src bytes

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

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions