search

nahi / httpclient

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

Execution expired #373

Open hickscorp opened 7 years ago

hickscorp commented 7 years ago

I'm opening an issue related to https://github.com/nahi/httpclient/issues/225 because the issue was closed without further explaination.

We have the same random issue. Some days not a single occurence, some days 1000+ occurences.

This occurs when our workers reach out to either Instagram or Facebook. Here is an example of stack trace we get:

/usr/local/lib/ruby/2.3.0/openssl/buffering.rb:57 in sysread
/usr/local/lib/ruby/2.3.0/openssl/buffering.rb:57 in fill_rbuff
/usr/local/lib/ruby/2.3.0/openssl/buffering.rb:204 in gets
/gems/httpclient-2.8.3/lib/httpclient/ssl_socket.rb:62 in gets
/gems/httpclient-2.8.3/lib/httpclient/session.rb:805 in block in parse_header
/usr/local/lib/ruby/2.3.0/timeout.rb:91 in block in timeout
/usr/local/lib/ruby/2.3.0/timeout.rb:101 in timeout
/gems/httpclient-2.8.3/lib/httpclient/session.rb:801 in parse_header
/gems/httpclient-2.8.3/lib/httpclient/session.rb:784 in read_header
/gems/httpclient-2.8.3/lib/httpclient/session.rb:561 in get_header
/gems/httpclient-2.8.3/lib/httpclient.rb:1299 in do_get_header
/gems/httpclient-2.8.3/lib/httpclient.rb:1245 in do_get_block
/gems/httpclient-2.8.3/lib/httpclient.rb:1019 in block in do_request
/gems/httpclient-2.8.3/lib/httpclient.rb:1133 in protect_keep_alive_disconnected
/gems/httpclient-2.8.3/lib/httpclient.rb:1014 in do_request
/gems/httpclient-2.8.3/lib/httpclient.rb:856 in request
/gems/rest-builder-0.9.1/lib/rest-builder/engine/http-client.rb:28 in request_sync
/gems/rest-builder-0.9.1/lib/rest-builder/engine/http-client.rb:23 in request
/gems/rest-builder-0.9.1/lib/rest-builder/engine.rb:28 in block in call
/gems/promise_pool-0.9.0/lib/promise_pool/promise.rb:49 in block (2 levels) in defer
/gems/promise_pool-0.9.0/lib/promise_pool/promise.rb:132 in block in protected_yield
/gems/promise_pool-0.9.0/lib/promise_pool/promise.rb:145 in timeout_protected_yield
/gems/promise_pool-0.9.0/lib/promise_pool/promise.rb:132 in protected_yield
/gems/promise_pool-0.9.0/lib/promise_pool/promise.rb:49 in block in defer
/gems/rest-builder-0.9.1/lib/rest-builder/engine.rb:28 in call
/gems/rest-builder-0.9.1/lib/rest-builder/middleware.rb:34 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/cache.rb:29 in app_call
/gems/rest-core-4.0.0/lib/rest-core/middleware/cache.rb:25 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/json_response.rb:24 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/error_detector.rb:8 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/error_handler.rb:8 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/common_logger.rb:12 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/oauth2_query.rb:17 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/default_headers.rb:8 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/default_site.rb:14 in call
/gems/rest-core-4.0.0/lib/rest-core/middleware/timeout.rb:16 in process
/gems/rest-core-4.0.0/lib/rest-core/middleware/timeout.rb:11 in call
/gems/rest-builder-0.9.1/lib/rest-builder/client.rb:168 in request_full
/gems/rest-builder-0.9.1/lib/rest-builder/client.rb:163 in request
/gems/rest-builder-0.9.1/lib/rest-builder/client.rb:132 in post
app/models/advert_adapters/facebook.rb:341 in block in request
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:299 in block in fetch
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:585 in block in save_block_result_to_cache
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:547 in block in instrument
/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:166 in instrument
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:547 in instrument
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:584 in save_block_result_to_cache
/gems/activesupport-4.2.7.1/lib/active_support/cache.rb:299 in fetch
app/models/advert_adapters/facebook.rb:337 in request
app/models/advert_adapters/facebook.rb:326 in block (2 levels) in <class:Facebook>
app/models/advert_adapters/facebook.rb:282 in update_feed_product
app/jobs/feed_product_updater_job.rb:7 in perform
/gems/activejob-4.2.7.1/lib/active_job/execution.rb:32 in block in perform_now
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:117 in call
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:555 in block (2 levels) in compile
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505 in call
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:498 in block (2 levels) in around
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:343 in block (2 levels) in simple
/gems/i18n-0.7.0/lib/i18n.rb:257 in with_locale
/gems/activejob-4.2.7.1/lib/active_job/translation.rb:7 in block (2 levels) in <module:Translation>
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441 in instance_exec
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441 in block in make_lambda
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:342 in block in simple
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:497 in block in around
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505 in call
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:498 in block (2 levels) in around
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:343 in block (2 levels) in simple
/gems/activejob-4.2.7.1/lib/active_job/logging.rb:23 in block (4 levels) in <module:Logging>
/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164 in block in instrument
/gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:20 in instrument
/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164 in instrument
/gems/activejob-4.2.7.1/lib/active_job/logging.rb:22 in block (3 levels) in <module:Logging>
/gems/activejob-4.2.7.1/lib/active_job/logging.rb:43 in block in tag_logger
/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:68 in block in tagged
/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:26 in tagged
/gems/activesupport-4.2.7.1/lib/active_support/tagged_logging.rb:68 in tagged
/gems/activejob-4.2.7.1/lib/active_job/logging.rb:43 in tag_logger
/gems/activejob-4.2.7.1/lib/active_job/logging.rb:19 in block (2 levels) in <module:Logging>
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441 in instance_exec
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:441 in block in make_lambda
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:342 in block in simple
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:497 in block in around
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:505 in call
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:92 in __run_callbacks__
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:778 in _run_perform_callbacks
/gems/activesupport-4.2.7.1/lib/active_support/callbacks.rb:81 in run_callbacks
/gems/activejob-4.2.7.1/lib/active_job/execution.rb:31 in perform_now
/gems/activejob-4.2.7.1/lib/active_job/execution.rb:21 in execute
/gems/activejob-4.2.7.1/lib/active_job/queue_adapters/sidekiq_adapter.rb:42 in perform
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:158 in execute_job
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:138 in block (4 levels) in process
/gems/sidekiq-4.2.9/lib/sidekiq.rb:36 in block in <module:Sidekiq>
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:133 in block (3 levels) in process
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/chain.rb:128 in block in invoke
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/server/active_record.rb:6 in call
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/chain.rb:130 in block in invoke
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/server/retry_jobs.rb:74 in call
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/chain.rb:130 in block in invoke
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/server/logging.rb:11 in block in call
/gems/sidekiq-4.2.9/lib/sidekiq/logging.rb:32 in with_context
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/server/logging.rb:7 in call
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/chain.rb:130 in block in invoke
/gems/sidekiq-4.2.9/lib/sidekiq/middleware/chain.rb:133 in invoke
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:132 in block (2 levels) in process
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:174 in stats
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:131 in block in process
/gems/sidekiq-4.2.9/lib/sidekiq.rb:35 in block in <module:Sidekiq>
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:126 in process
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:82 in process_one
/gems/sidekiq-4.2.9/lib/sidekiq/processor.rb:70 in run
/gems/sidekiq-4.2.9/lib/sidekiq/util.rb:17 in watchdog
/gems/sidekiq-4.2.9/lib/sidekiq/util.rb:26 in block in safe_thread

I've noticed people having similar issues around the web, without any clear solution.

icybin commented 7 years ago

I have similar problem with lita-cleverbot

lita@admin:~/lita$ ruby test.rb 
/usr/lib/ruby/2.3.0/openssl/buffering.rb:57:in `sysread': execution expired (HTTPClient::ReceiveTimeoutError)
        from /usr/lib/ruby/2.3.0/openssl/buffering.rb:57:in `fill_rbuff'
        from /usr/lib/ruby/2.3.0/openssl/buffering.rb:204:in `gets'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient/ssl_socket.rb:62:in `gets'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:805:in `block in parse_header'
        from /usr/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:801:in `parse_header'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:784:in `read_header'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:561:in `get_header'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1299:in `do_get_header'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1245:in `do_get_block'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in `block in do_request'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in `protect_keep_alive_disconnected'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in `do_request'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:856:in `request'
        from /var/lib/gems/2.3.0/gems/httpclient-2.8.3/lib/httpclient.rb:765:in `post'
        from /var/lib/gems/2.3.0/gems/cleverbot_io-2.0.0/lib/cleverbot.rb:48:in `say'
        from test.rb:7:in `<main>'
hickscorp commented 7 years ago

Bump, anyone?

hickscorp commented 7 years ago

@kyanh-huynh It seems to indeed be the same error. Did you find a way to minimize it? We tried so many things without luck so far... And I feel like we're being ignored by the maintainers.

icybin commented 7 years ago

@hickscorp I'm sorry that you also have this problem. I gave up after many tries. As I need a Slackbot I switch to slack-ruby-bot instead -- I know my case is different.

Best wishes.

TETRA2000 commented 6 years ago

I found this error happens at least when response timeout occurred. I made a simple script to reproduce this error. https://github.com/TETRA2000/httpclient_debug

How about to increase timeout threshold?