search

nahi / httpclient

'httpclient' gives something like the functionality of libwww-perl (LWP) in Ruby.
https://github.com/nahi/httpclient
703 stars 290 forks source link

scheduler caught exception: execution expired #225

Closed tooh closed 10 years ago

tooh commented 10 years ago

Hi I use the dashing application. This application uses rufus-scheduler. In my dashing job I use httpclient to get content.

I recently started using httpclient so I don't know the exact use of this module.

The job is running every 60s. It works OK for a while and then the below errors are reported:

/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:53:in `sysread'
/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:53:in `fill_rbuff'
/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:200:in `gets'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:352:in `gets'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:881:in `block in parse_header'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:877:in `parse_header'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:860:in `read_header'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:667:in `get_header'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:1202:in `do_get_header'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:1151:in `do_get_block'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:952:in `block in do_request'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:1046:in `protect_keep_alive_disconnected'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:951:in `do_request'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:813:in `request'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient.rb:713:in `post'
nahi commented 10 years ago

@tooh Is that all of the backtrace? Could you share the code snippet you're using httpclient?

And what's happen when you disable keep-alive?

client = HTTPClient.new
client.protocol_version = 'HTTP/1.0' # <= this line

It depends on what exception is happening but it could be keep-alive thing I guess.

tooh commented 10 years ago

Hi Nahi,

Thx for your reply. When I apply

client.protocol_version = 'HTTP/1.0' # <= this line

I get the following, so this makes it worse

unexpected response: #<HTTP::Message::Headers:0x007fe33bab04e8 @http_version="1.1", @body_size=0, @chunked=false, @request_method="GET", @request_uri=#<Addressable::URI:0x3ff19dd6fbf4 URI:removed for security purposes>, @request_query=nil, @request_absolute_uri=nil, @status_code=404, @reason_phrase="Not Found", @body_type=nil, @body_charset=nil, @body_date=nil, @body_encoding=#<Encoding:US-ASCII>, @is_request=false, @header_item=[["Content-Type", "text/html; charset=us-ascii"], ["Server", "Microsoft-HTTPAPI/2.0"], ["Date", "Sun, 02 Nov 2014 08:42:05 GMT"], ["Connection", "close"], ["Content-Length", "315"]], @dumped=false>
nahi commented 10 years ago

Hmm. The response is 404 Not Found so usually it's a wrong URI but actually it depends on protocol_version property, right? Interesting.

Can you try this; (remove protocol_version line frist)

client.get(...)
client.reset_all

for resetting connection each time, and

client.debug_dev = STDERR
client.get(...)

to see what request and response are like?

tooh commented 10 years ago

did the 

client.reset_all

and switched on the debugging

client.debug_dev = STDERR
tooh commented 10 years ago

I did the reset and switched on the debugging.

Output seems OK. I let the job running for a while and see if the errors occurs again

nahi commented 10 years ago

Well, what's happening to this thread? Message order is broken...

Anyway, @tooh , would you please tell us the exception you're getting? The exception should be dumped near;

<here>
/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:53:in `sysread'
/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:53:in `fill_rbuff'
/.rvm/rubies/ruby-1.9.3-p547/lib/ruby/1.9.1/openssl/buffering.rb:200:in `gets'
/.rvm/gems/ruby-1.9.3-p547/gems/httpclient-2.5.2/lib/httpclient/session.rb:352:in `gets'

or the next of the bottom line <here>
tooh commented 10 years ago

After the modifications it is still running without errors.

Fingers crossed.

nahi commented 10 years ago

OK, so it would be the connection recycling problem, perhaps with Microsoft-HTTPAPI/2.0.

You use httpclient instance, like @client = HTTPClient.new; client.get() and using code>@client</code repeatedly, or, you use class method like HTTPClient.get(...)?

If you need to connect with the server many times reusing code>@client</code has benefit to run faster. And on the platform I'm using httpclient it runs without problem...

nahi commented 10 years ago

I'm not sure why articles are not properly ordered in this ticket but the issue seems to be solved for the original reporter. It's generally good to create single HTTPClient instance and reuse it in long running process.

hickscorp commented 7 years ago

@nahi / @tooh any update on this one?

We recently started having this problem sporadically. First in our dev machines, then in production. We do not use HTTPClient directly, we use gems that themselve use HTTPClient. The stack trace is extremelly vague, but if you start looking for it you'll find people having the problem and never really finding a solution to it, it just randomly disappears.

We clearly pinpointed the problem first appearance after a major update to our Gemset... But it's too late now, we weren't lucky enough to see the issue when we migrated. Sometimes now, the bug occurs within CircleCI environment (while HTTP requests are disabled, and caught by WebMock).... It might be a deadlock problem.

It can occur when using gems such as the Instagram official client, or koala via rest-more.

The bug is completelly random. I'm wondering if some lower level issue might be in play here.

Any insights? Thanks!

In our case, an example stacktrace:

Timeout::Error: execution expired
  from /usr/local/lib/ruby/2.3.0/openssl/buffering.rb:57:in `sysread'
  from /usr/local/lib/ruby/2.3.0/openssl/buffering.rb:57:in `fill_rbuff'
  from /usr/local/lib/ruby/2.3.0/openssl/buffering.rb:204:in `gets'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient/ssl_socket.rb:62:in `gets'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:805:in `block in parse_header'
  from /usr/local/lib/ruby/2.3.0/timeout.rb:91:in `block in timeout'
  from /usr/local/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:801:in `parse_header'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:784:in `read_header'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:561:in `get_header'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1299:in `do_get_header'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1245:in `do_get_block'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in `block in do_request'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in `protect_keep_alive_disconnected'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in `do_request'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:856:in `request'
... 31 levels...
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:299:in `fetch'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:207:in `request'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:196:in `block (2 levels) in <class:Facebook>'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:260:in `setup_account'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:52:in `block in setup'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:50:in `each'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:50:in `all?'
  from /var/deploy/REDACTED/web_head/releases/20170329190708/app/models/advert_adapters/facebook.rb:50:in `setup'
  from (irb):2
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/console.rb:110:in `start'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/console.rb:9:in `start'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:68:in `console'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
  from /var/deploy/REDACTED/web_head/shared/bundle/ruby/2.3.0/gems/railties-4.2.7.1/lib/rails/commands.rb:17:in `<top (required)>'
  from bin/rails:8:in `require'
  from bin/rails:8:in `<main>'
hickscorp commented 7 years ago

Could anyone please give me a commit which supposedly fixed this? We're getting this exception all over the place one day, and not at all the next day. Pretty sure the issue is related to https://github.com/nahi/httpclient/issues/249