search

sul-dlss / SearchWorks

SearchWorks (Stanford University Libraries)
http://searchworks.stanford.edu
Other
48 stars 10 forks source link

[SearchWorks/production] Faraday::TimeoutError: too many connection resets #1766

Open drh-stanford opened 7 years ago

drh-stanford commented 7 years ago

[SearchWorks/production] Faraday::TimeoutError: too many connection resets (due to execution expired - Net::OpenTimeout) after 0 requests on 70099183618440, last used 1505247344.7452774 seconds ago

Backtrace

line 7 of [PROJECT_ROOT]/app/models/eds/session.rb: search
line 26 of [PROJECT_ROOT]/app/models/eds/repository.rb: eds_search
line 5 of [PROJECT_ROOT]/app/models/eds/repository.rb: block in search

View full backtrace and more info at honeybadger.io

drh-stanford commented 7 years ago

See https://github.com/ebsco/edsapi-ruby/issues/78

drh-stanford commented 7 years ago

We're still seeing this with the new timeout (from 5 to 10 seconds).

screen shot 2017-09-20 at 10 55 26 am
bmckinney commented 7 years ago

Can you send me the full honeybadger backtrace?

Specifically, trying to rule out that net-http-persistent is involved in any way.

drh-stanford commented 7 years ago

Sure

/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `initialize`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `open`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `block in connect`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/timeout.rb:101 :in `timeout`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:878 :in `connect`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:1481 :in `begin_transport`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:1433 :in `transport_request`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:1407 :in `request`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/net.rb:33 :in `block in request_with_newrelic_trace`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent.rb:438 :in `disable_all_tracing`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/net.rb:32 :in `request_with_newrelic_trace`
 [GEM_ROOT]/gems/net-http-persistent-2.9.4/lib/net/http/persistent.rb:999 :in `request`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/adapter/net_http_persistent.rb:30 :in `perform_request`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/adapter/net_http.rb:38 :in `block in call`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/adapter/net_http.rb:85 :in `with_net_http_connection`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/adapter/net_http.rb:33 :in `call`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/response.rb:8 :in `call`
 [GEM_ROOT]/gems/faraday-detailed_logger-2.1.2/lib/faraday/detailed_logger/middleware.rb:59 :in `call`
 [GEM_ROOT]/gems/faraday_middleware-0.12.2/lib/faraday_middleware/response_middleware.rb:31 :in `call`
[GEM_ROOT]/gems/ebsco-eds-0.3.11.pre/lib/faraday/eds_exception_middleware.rb:13 :in `call`
[GEM_ROOT]/gems/ebsco-eds-0.3.11.pre/lib/faraday/eds_caching_middleware.rb:39 :in `call!`
[GEM_ROOT]/gems/ebsco-eds-0.3.11.pre/lib/faraday/eds_caching_middleware.rb:27 :in `call`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/request/url_encoded.rb:15 :in `call`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/rack_builder.rb:141 :in `build_response`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/connection.rb:387 :in `run_request`
 [GEM_ROOT]/gems/faraday-0.13.1/lib/faraday/connection.rb:174 :in `post`
[GEM_ROOT]/gems/ebsco-eds-0.3.11.pre/lib/ebsco/eds/session.rb:700 :in `do_request`
[GEM_ROOT]/gems/ebsco-eds-0.3.11.pre/lib/ebsco/eds/session.rb:227 :in `search`
[PROJECT_ROOT]/app/models/eds/session.rb:7 :in `search`
[PROJECT_ROOT]/app/models/eds/repository.rb:26 :in `eds_search`
[PROJECT_ROOT]/app/models/eds/repository.rb:5 :in `block in search`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/benchmarkable.rb:41 :in `block in benchmark`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/core_ext/benchmark.rb:12 :in `block in ms`
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/benchmark.rb:308 :in `realtime`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/core_ext/benchmark.rb:12 :in `ms`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/benchmarkable.rb:41 :in `benchmark`
[PROJECT_ROOT]/app/models/eds/repository.rb:4 :in `search`
[PROJECT_ROOT]/app/services/eds/search_service.rb:20 :in `search_results`
[PROJECT_ROOT]/app/controllers/articles_controller.rb:188 :in `search_results`
 [GEM_ROOT]/gems/blacklight-6.10.1/app/controllers/concerns/blacklight/catalog.rb:25 :in `index`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/basic_implicit_render.rb:4 :in `send_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/abstract_controller/base.rb:186 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/rendering.rb:30 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/abstract_controller/callbacks.rb:20 :in `block in process_action`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:131 :in `run_callbacks`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/abstract_controller/callbacks.rb:19 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/rescue.rb:20 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/instrumentation.rb:32 :in `block in process_action`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/notifications.rb:166 :in `block in instrument`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/notifications/instrumenter.rb:21 :in `instrument`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/notifications.rb:166 :in `instrument`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/instrumentation.rb:30 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal/params_wrapper.rb:252 :in `process_action`
 [GEM_ROOT]/gems/activerecord-5.1.2/lib/active_record/railties/controller_runtime.rb:22 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/abstract_controller/base.rb:124 :in `process`
 [GEM_ROOT]/gems/actionview-5.1.2/lib/action_view/rendering.rb:30 :in `process`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal.rb:189 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_controller/metal.rb:253 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:49 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:31 :in `serve`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:46 :in `block in serve`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:33 :in `each`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:33 :in `serve`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:832 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/rack/agent_hooks.rb:30 :in `traced_call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/rack/browser_monitoring.rb:32 :in `traced_call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:36 :in `block in call`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:35 :in `catch`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:35 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/etag.rb:25 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/conditional_get.rb:25 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/head.rb:12 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232 :in `context`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/cookies.rb:613 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/callbacks.rb:26 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:97 :in `run_callbacks`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/callbacks.rb:24 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/debug_exceptions.rb:59 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/show_exceptions.rb:31 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/railties-5.1.2/lib/rails/rack/logger.rb:36 :in `call_app`
 [GEM_ROOT]/gems/railties-5.1.2/lib/rails/rack/logger.rb:24 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:69 :in `block in tagged`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:26 :in `tagged`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:69 :in `tagged`
 [GEM_ROOT]/gems/railties-5.1.2/lib/rails/rack/logger.rb:24 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/remote_ip.rb:79 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/request_id.rb:25 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/method_override.rb:22 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/runtime.rb:22 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/activesupport-5.1.2/lib/active_support/cache/strategy/local_cache_middleware.rb:27 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.2/lib/action_dispatch/middleware/executor.rb:12 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-2.0.3/lib/rack/sendfile.rb:111 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/rack-utf8_sanitizer-1.3.2/lib/rack/utf8_sanitizer.rb:19 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
 [GEM_ROOT]/gems/railties-5.1.2/lib/rails/engine.rb:522 :in `call`
 [GEM_ROOT]/gems/newrelic_rpm-4.2.0.334/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92 :in `call`
/usr/local/rvm/gems/ruby-2.3.4/gems/passenger-5.0.30/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97 :in `process_request`
/usr/local/rvm/gems/ruby-2.3.4/gems/passenger-5.0.30/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:152 :in `accept_and_process_next_request`
/usr/local/rvm/gems/ruby-2.3.4/gems/passenger-5.0.30/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113 :in `main_loop`
/usr/local/rvm/gems/ruby-2.3.4/gems/passenger-5.0.30/src/ruby_supportlib/phusion_passenger/request_handler.rb:416 :in `block (3 levels) in start_threads`
/usr/local/rvm/gems/ruby-2.3.4/gems/passenger-5.0.30/src/ruby_supportlib/phusion_passenger/utils.rb:113 :in `block in create_thread_and_abort_on_exception`
More (120 lines)
Nested Exceptions
Faraday::TimeoutError: too many connection resets (due to execution expired - Net::OpenTimeout) after 0 requests on 70016305801960, last used 1505864356.9476292 seconds ago
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `initialize`
 Net::HTTP::Persistent::Error: too many connection resets (due to execution expired - Net::OpenTimeout) after 0 requests on 70016305801960, last used 1505864356.9476292 seconds ago
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `initialize`
 Net::OpenTimeout: execution expired
/usr/local/rvm/rubies/ruby-2.3.4/lib/ruby/2.3.0/net/http.rb:880 :in `initialize`
bmckinney commented 7 years ago

Yes, I see net-http-persistent catching the error.

Related (https://github.com/drbrain/net-http-persistent/issues/37):

I was bitten by the same issue as @mikerudolph above:

too many connection resets (due to Timeout::Error - Timeout::Error) after 0 requests This is an issue separate from EOFError and SSLError mentioned above, and is easily reproducible. It will occur if the connection was configured with a read timeout and the server didn't reply in a timely fashion. Net::HTTP is going to raise a Timeout::Error and net-http-persistent handles this, among other errors, by resetting the connection, retrying, and ultimately aborting with the misleading message quoted above.

I fixed this for myself by monkeypatching net-http-persistent from master to not handle Timeout::Error. In the case of a server taking too long to generate a response, I don't think resetting the connection does us any good since it wasn't a connection problem to begin with. It would be much better to leave the original Timeout::Error unhandled and let the user retry the request if they will.

drh-stanford commented 7 years ago

So it seems that the core issue is that the server is not responding and we're getting a timeout. Are you getting errors on your end from these timeouts? We can disable net-http-persistent but I think that'll just change the error message if I understand correctly.

bmckinney commented 7 years ago

Agreed, @efrierson and I will open a service issue.

bmckinney commented 7 years ago

@drh-stanford The SI for this is #164706. Someone may contact you to get more details on the IPs involved and to setup additional monitoring on our end.

performance1 commented 7 years ago

Hi, Can you tell which IP address you're coming from please, we think 180.76.15.11 Also, can you execute the test again, the detailed data rolled off our BMC analyzer before we could collect it. Sandy Barry SRE