Bug #14829: test-all - 2 fails - 63589 - Windows - part of 'Introduce write_timeout to Net::HTTP'

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 2.6.0dev (2018-06-06 trunk 63593) [x64-mingw32]
• Backport: 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN

[MSP-Greg (Greg L)]

@naruse (Yui NARUSE)

At 63589, Windows builds, both mswin & MinGW are failing on the following two tests:

TestNetHTTP_v1_2#test_timeout_during_HTTP_session_write
TestNetHTTP_v1_2_chunked#test_timeout_during_HTTP_session_write

I am not that familiar with blocking IO. I added some debug code to Net::BufferedIO.write0 as follows:

    def write0(*strs)
      @debug_output << strs.map(&:dump).join if @debug_output
      orig_written_bytes = @written_bytes
      strs.each_with_index do |str, i|
        need_retry = true
        case len = @io.write_nonblock(str, exception: false)
        when Integer
          @written_bytes += len
          len -= str.bytesize
puts "\nlen #{len}" if @write_timeout < 50
          if len == 0
            if strs.size == i+1
puts "@written_bytes #{@written_bytes}    orig_written_bytes #{orig_written_bytes}" if @write_timeout < 50
            return @written_bytes - orig_written_bytes
            else
              need_retry = false
              # next string
            end
          elsif len < 0
            str = str[len, -len]
          else # len > 0
            need_retry = false
            # next string
          end
          # continue looping
        when :wait_writable
puts "\nlen #{len}" if @write_timeout < 50
          @io.to_io.wait_writable(@write_timeout) or raise Net::WriteTimeout
          # continue looping
        else
puts "\nlen #{len}" if @write_timeout < 50
        end while need_retry
puts "\nPast case statement"
      end
    end

Console output for the two tests:

[50/69] TestNetHTTP_v1_2#test_timeout_during_HTTP_session_writeC:/Greg/Ruby26-x64b/lib/ruby/2.6.0/net/http/generic_request.rb:186: warning: net/http: Content-Type did not set; using application/x-www-form-urlencoded

len 0
@written_bytes 225    orig_written_bytes 0

len 0
@written_bytes 25000000    orig_written_bytes 0
#<Thread:0x0000000003c97f40@C:/Greg/GitHub/ruby/test/net/http/test_http.rb:544 aborting> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
        5: from C:/Greg/GitHub/ruby/test/net/http/test_http.rb:545:in `block (2 levels) in test_timeout_during_HTTP_session_write'
        4: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:96:in `assert_raise'
        3: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:96:in `ensure in assert_raise'
        2: from C:/Greg/GitHub/ruby/test/lib/minitest/unit.rb:550:in `flunk'
        1: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:37:in `assert'
C:/Greg/GitHub/ruby/test/lib/minitest/unit.rb:201:in `assert': Net::WriteTimeout expected but nothing was raised. (MiniTest::Assertion)
 = 10.06 s

[69/69] TestNetHTTP_v1_2_chunked#test_timeout_during_HTTP_session_writeC:/Greg/Ruby26-x64b/lib/ruby/2.6.0/net/http/generic_request.rb:186: warning: net/http: Content-Type did not set; using application/x-www-form-urlencoded

len 0
@written_bytes 225    orig_written_bytes 0

len 0
@written_bytes 25000000    orig_written_bytes 0
#<Thread:0x00000000034f15c0@C:/Greg/GitHub/ruby/test/net/http/test_http.rb:544 aborting> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
        5: from C:/Greg/GitHub/ruby/test/net/http/test_http.rb:545:in `block (2 levels) in test_timeout_during_HTTP_session_write'
        4: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:96:in `assert_raise'
        3: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:96:in `ensure in assert_raise'
        2: from C:/Greg/GitHub/ruby/test/lib/minitest/unit.rb:550:in `flunk'
        1: from C:/Greg/GitHub/ruby/test/lib/test/unit/assertions.rb:37:in `assert'
C:/Greg/GitHub/ruby/test/lib/minitest/unit.rb:201:in `assert': Net::WriteTimeout expected but nothing was raised. (MiniTest::Assertion)
 = 10.07 s

I have no idea if this is helpful, and I'm happy to check whatever. Certainly interested in seeing the solution...

Thanks for your work, Greg

[MSP-Greg (Greg L)]

• File http.rb.patch http.rb.patch added
• ruby -v changed from ruby -v: ruby 2.6.0dev (2018-06-06 trunk 63589) [x64-mingw32] to ruby 2.6.0dev (2018-06-06 trunk 63593) [x64-mingw32]

After getting frustrated with something else, I revisited this, as the errors were a test timeout errors. Followed the call stack, and found a solution to fixing the failures on mswin & mingw. I doubt it's the correct solution, but (hopefully) it will give you an idea of where the issue is...

See attached patch.

Thanks, Greg

[MSP-Greg (Greg L)]

See GitHub PR 1883. https://github.com/ruby/ruby/pull/1883

Passed. Patch attached - GitHub_PR_1883.patch.

Thanks, Greg

[MSP-Greg (Greg L)]

• File GitHub_PR_1883.patch GitHub_PR_1883.patch added

[MSP-Greg (Greg L)]

Earlier today, I pushed a patch file equivalent to GitHub _PR_1883.patch to ruby-loco, and the build for

ruby 2.6.0dev (2018-06-07 trunk 63604) [x64-mingw32] was successful.

Hence, the patch works for Travis, Appveyor mswin, and Appveyor MinGW. The test runs on all platforms.

[MSP-Greg (Greg L)]

@naruse (Yui NARUSE) @usa (Usaku NAKAMURA)

Thank you for the work on net/http and write_timeout. Obviously, write_nonblock works differently on Windows and *nix.

I'm by no means an expert on what expected behavior is with net/http, but I think it would certainly be helpful to have the write_timeout tests not skipped on windows.

For one thing, if windows behavior changes in the future, hopefully the test would fail...

Otherwise, feel free to close. Greg

[naruse (Yui NARUSE)]

• Status changed from Open to Closed

Applied in changeset trunk|r63613.

---

assert_raise(Net::ReadTimeout) on Windows [Bug #14829]

From: MSP-Greg [e-mail]

[naruse (Yui NARUSE)]

Sounds reasonable, I merged your patch, thanks!