search

ruby / net-http

Net::HTTP provides a rich library which can be used to build HTTP user-agents.
Other
93 stars 65 forks source link

Latest `content-length` change makes it extremely long to get response #49

Open st0012 opened 2 years ago

st0012 commented 2 years ago

I first noticed this because all ruby/debug's tests ran against Ruby head failed with a timeout error (example):

/home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/protocol.rb:[21](https://github.com/ruby/debug/runs/5799401105?check_suite_focus=true#step:4:21)9:in `rbuf_fill': Net::ReadTimeout with #<Socket:(closed)> (Net::ReadTimeout)
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/protocol.rb:181:in `read_all'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:433:in `read_all'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:312:in `block in read_body_0'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:271:in `inflater'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:294:in `read_body_0'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:210:in `read_body'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:235:in `body'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http/response.rb:168:in `reading_body'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:1601:in `transport_request'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:1557:in `request'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:1458:in `request_get'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:506:in `block in get_response'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:967:in `start'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:628:in `start'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:504:in `get_response'
    from /home/runner/.rubies/ruby-head/lib/ruby/3.2.0+1/net/http.rb:475:in `get'
    from /home/runner/work/debug/debug/test/support/protocol_utils.rb:[22](https://github.com/ruby/debug/runs/5799401105?check_suite_focus=true#step:4:22):in `<module:Protocol_TestUtils>'
    from /home/runner/work/debug/debug/test/support/protocol_utils.rb:10:in `<module:DEBUGGER__>'
    from /home/runner/work/debug/debug/test/support/protocol_utils.rb:9:in `<top (required)>'
    from /home/runner/work/debug/debug/test/support/test_case.rb:10:in `require_relative'
    from /home/runner/work/debug/debug/test/support/test_case.rb:10:in `<top (required)>'
    from /home/runner/work/debug/debug/test/assertion_helper_test.rb:3:in `require_relative'
    from /home/runner/work/debug/debug/test/assertion_helper_test.rb:3:in `<top (required)>'
    from /home/runner/work/debug/debug/vendor/bundle/ruby/3.2.0+1/gems/rake-13.0.6/lib/rake/rake_test_loader.rb:21:in `require'
    from /home/runner/work/debug/debug/vendor/bundle/ruby/3.2.0+1/gems/rake-13.0.6/lib/rake/rake_test_loader.rb:21:in `block in <main>'
    from /home/runner/work/debug/debug/vendor/bundle/ruby/3.2.0+1/gems/rake-13.0.6/lib/rake/rake_test_loader.rb:6:in `select'
    from /home/runner/work/debug/debug/vendor/bundle/ruby/3.2.0+1/gems/rake-13.0.6/lib/rake/rake_test_loader.rb:6:in `<main>'
rake aborted!
Command failed with status (1)
/home/runner/work/debug/debug/vendor/bundle/ruby/3.2.0+1/gems/rake-13.0.6/exe/rake:[27](https://github.com/ruby/debug/runs/5799401105?check_suite_focus=true#step:4:27):in `<top (required)>'

And then I executed this command from a clone of this repo to confirm this:

❯ time ruby -Ilib -rnet/http -e "puts(Net::HTTP::VERSION) ;; puts Net::HTTP.get(URI.parse('https://raw.githubusercontent.com/ruby/debug/master/.gitignore'))"

master

net-http on ξ‚  master [?] via πŸ’Ž v3.1.0 on ☁️  (eu-west-1) took 5s
❯ time ruby -Ilib -rnet/http -e "puts(Net::HTTP::VERSION) ;; puts Net::HTTP.get(URI.parse('https://raw.githubusercontent.com/ruby/debug/master/.gitignore'))"
0.2.0
/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:219:in `rbuf_fill': Net::ReadTimeout with #<Socket:(closed)> (Net::ReadTimeout)
        from /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:181:in `read_all'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:433:in `read_all'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:312:in `block in read_body_0'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:271:in `inflater'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:294:in `read_body_0'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:210:in `read_body'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:235:in `body'
        from /Users/st0012/projects/net-http/lib/net/http/response.rb:168:in `reading_body'
        from /Users/st0012/projects/net-http/lib/net/http.rb:1601:in `transport_request'
        from /Users/st0012/projects/net-http/lib/net/http.rb:1557:in `request'
        from /Users/st0012/projects/net-http/lib/net/http.rb:1458:in `request_get'
        from /Users/st0012/projects/net-http/lib/net/http.rb:506:in `block in get_response'
        from /Users/st0012/projects/net-http/lib/net/http.rb:967:in `start'
        from /Users/st0012/projects/net-http/lib/net/http.rb:628:in `start'
        from /Users/st0012/projects/net-http/lib/net/http.rb:504:in `get_response'
        from /Users/st0012/projects/net-http/lib/net/http.rb:475:in `get'
        from -e:1:in `<main>'
ruby -Ilib -rnet/http -e   0.17s user 0.09s system 0% cpu 2:00.48 total

prev commit (bfb5a13)

net-http on ξ‚  HEAD (bfb5a13) [?] via πŸ’Ž v3.1.0 on ☁️  (eu-west-1)
❯ time ruby -Ilib -rnet/http -e "puts(Net::HTTP::VERSION) ;; puts Net::HTTP.get(URI.parse('https://raw.githubusercontent.com/ruby/debug/master/.gitignore'))"
0.2.0
/.bundle/
/.yardoc
/_yardoc/
/coverage/
/doc/
/pkg/
/spec/reports/
/tmp/
*.bundle
/Gemfile.lock
/lib/debug/debug.so
.ruby-version
/debugAdapterProtocol.json
/chromeDevToolsProtocol.json
ruby -Ilib -rnet/http -e   0.16s user 0.08s system 73% cpu 0.339 total
st0012 commented 2 years ago

I did a bit debugging with ruby/debug:

$ ruby -Ilib -rnet/http -rdebug -e "debugger(do: 'trace call') ;;  puts Net::HTTP.get(URI.parse('https://raw.githubusercontent.com/ruby/debug/master/.gitignore'))"

And I think it hangs at 

DEBUGGER (trace/call) #th:1 #depth:19>                  IO#wait_readable at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:219

More traces:

# ...
DEBUGGER (trace/call) #th:1 #depth:20<                   OpenSSL::SSL::SSLSocket#sysread_nonblock #=> :wait_readable at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/openssl/buffering.rb:214
DEBUGGER (trace/call) #th:1 #depth:19<                   OpenSSL::Buffering#read_nonblock #=> :wait_readable at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/openssl/buffering.rb:214
DEBUGGER (trace/call) #th:1 #depth:19>                  Module#=== at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:213
DEBUGGER (trace/call) #th:1 #depth:19<                  Module#=== #=> false at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:213
DEBUGGER (trace/call) #th:1 #depth:19>                  Symbol#=== at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:218
DEBUGGER (trace/call) #th:1 #depth:19<                  Symbol#=== #=> true at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:218
DEBUGGER (trace/call) #th:1 #depth:19>                  OpenSSL::SSL::SSLSocket#io at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:219
DEBUGGER (trace/call) #th:1 #depth:19<                  OpenSSL::SSL::SSLSocket#io #=> #<Socket:fd 11> at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:219
DEBUGGER (trace/call) #th:1 #depth:19>                  IO#wait_readable at /Users/st0012/.rbenv/versions/3.1.0/lib/ruby/3.1.0/net/protocol.rb:219