Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ping worker dies on unexpected error #280

Closed
dblock opened this issue Jul 20, 2019 · 3 comments
Closed

Ping worker dies on unexpected error #280

dblock opened this issue Jul 20, 2019 · 3 comments

Comments

@dblock
Copy link
Collaborator

dblock commented Jul 20, 2019 •
edited
Loading

This is a repro of one of the cases in #257, with some annotated sequence of events.

13:28:51 web.1  | W, [2019-07-20T13:28:51.402443 #72227]  WARN -- dblock: start_reactor
13:28:51 web.1  | W, [2019-07-20T13:28:51.402935 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830722c running>: creating async::notification
13:28:51 web.1  | W, [2019-07-20T13:28:51.403305 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830722c running>: creating ping worker
13:28:51 web.1  | W, [2019-07-20T13:28:51.404431 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, sleeping 30
13:28:51 web.1  | W, [2019-07-20T13:28:51.404779 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830722c running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, client_task is 
13:28:51 web.1  | W, [2019-07-20T13:28:51.407215 #72227]  WARN -- dblock, <Async::Task:0x3fe4f8313b44 client run-loop running>: starting loop
13:28:52 web.1  | I, [2019-07-20T13:28:52.451409 #72227]  INFO -- : Successfully connected team dblock (T04KB5WQH) to https://dblockdotorg.slack.com.
13:29:21 web.1  | W, [2019-07-20T13:29:21.405588 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, run_ping!
13:29:21 web.1  | W, [2019-07-20T13:29:21.405821 #72227]  WARN -- dblock: keep_alive?: false
13:29:21 web.1  | W, [2019-07-20T13:29:21.406009 #72227]  WARN -- dblock: time_since_last_message: 28.954691000282764 vs. 30
13:29:21 web.1  | W, [2019-07-20T13:29:21.406210 #72227]  WARN -- dblock:  returning true
13:29:21 web.1  | W, [2019-07-20T13:29:21.406459 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, sleeping 30
13:29:51 web.1  | W, [2019-07-20T13:29:51.410578 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, run_ping!
13:29:51 web.1  | W, [2019-07-20T13:29:51.410777 #72227]  WARN -- dblock: keep_alive?: false
13:29:51 web.1  | W, [2019-07-20T13:29:51.410962 #72227]  WARN -- dblock: time_since_last_message: 58.95964800007641 vs. 30
13:29:51 web.1  | W, [2019-07-20T13:29:51.411204 #72227]  WARN -- dblock: ping
13:29:51 web.1  | W, [2019-07-20T13:29:51.411766 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, sleeping 30

turn off network

13:30:21 web.1  | W, [2019-07-20T13:30:21.412097 #72227]  WARN -- dblock, <Async::Task:0x3fe4f830f350 client keep-alive running>: restart is #<Async::Notification:0x00007fc9f060d5d0>, run_ping!
13:30:21 web.1  | W, [2019-07-20T13:30:21.412417 #72227]  WARN -- dblock: keep_alive?: false
13:30:21 web.1  | W, [2019-07-20T13:30:21.412602 #72227]  WARN -- dblock: time_since_last_message: 88.9612859999761 vs. 30
13:30:21 web.1  | W, [2019-07-20T13:30:21.412793 #72227]  WARN -- dblock:  returning false
13:30:21 web.1  | W, [2019-07-20T13:30:21.412957 #72227]  WARN -- dblock: restart_async
13:30:21 web.1  | W, [2019-07-20T13:30:21.413343 #72227]  WARN -- dblock, <Async::Task:0x3fe4f8313b44 connected to #<Addrinfo: 3.120.198.117:443 TCP (cerberus-xxxx.lb.slack-msgs.com)> running>: The operation has been cancelled!
13:30:21 web.1  |  1m32s    error: <Async::Task:0x3fe4f830f350 client keep-alive failed> [pid=72227] [2019-07-20 13:30:21 -0400]
13:30:21 web.1  |                |   Faraday::ConnectionFailed: Failed to open TCP connection to slack.com:443 (getaddrinfo: nodename nor servname provided, or not known)
13:30:21 web.1  |                |   → /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:949 in `rescue in block in connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:946 in `block in connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:93 in `block in timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:103 in `timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:945 in `connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:930 in `do_start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:919 in `start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:1470 in `request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:36 in `block in request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent.rb:505 in `disable_all_tracing'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:35 in `request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:87 in `perform_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:43 in `block in call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:92 in `with_net_http_connection'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:38 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response/logger.rb:26 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday_middleware-0.13.1/lib/faraday_middleware/response_middleware.rb:31 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/url_encoded.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/multipart.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/rack_builder.rb:143 in `build_response'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:387 in `run_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:175 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:25 in `request'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:10 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/api/endpoints/rtm.rb:18 in `rtm_connect'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:152 in `restart_async'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:140 in `run_ping!'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/concurrency/async.rb:43 in `block (2 levels) in start_reactor'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/async-1.19.0/lib/async/task.rb:210 in `block in make_fiber'
13:30:21 web.1  |                |   Caused by SocketError: Failed to open TCP connection to slack.com:443 (getaddrinfo: nodename nor servname provided, or not known)
13:30:21 web.1  |                |   → /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:949 in `rescue in block in connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:946 in `block in connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:93 in `block in timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:103 in `timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:945 in `connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:930 in `do_start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:919 in `start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:1470 in `request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:36 in `block in request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent.rb:505 in `disable_all_tracing'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:35 in `request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:87 in `perform_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:43 in `block in call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:92 in `with_net_http_connection'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:38 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response/logger.rb:26 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday_middleware-0.13.1/lib/faraday_middleware/response_middleware.rb:31 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/url_encoded.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/multipart.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/rack_builder.rb:143 in `build_response'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:387 in `run_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:175 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:25 in `request'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:10 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/api/endpoints/rtm.rb:18 in `rtm_connect'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:152 in `restart_async'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:140 in `run_ping!'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/concurrency/async.rb:43 in `block (2 levels) in start_reactor'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/async-1.19.0/lib/async/task.rb:210 in `block in make_fiber'
13:30:21 web.1  |                |   Caused by SocketError: getaddrinfo: nodename nor servname provided, or not known
13:30:21 web.1  |                |   → /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:947 in `initialize'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:947 in `open'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:947 in `block in connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:93 in `block in timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/timeout.rb:103 in `timeout'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:945 in `connect'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:930 in `do_start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:919 in `start'
13:30:21 web.1  |                |     /Users/dblock/.rvm/rubies/ruby-2.6.2/lib/ruby/2.6.0/net/http.rb:1470 in `request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:36 in `block in request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent.rb:505 in `disable_all_tracing'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/net.rb:35 in `request_with_newrelic_trace'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:87 in `perform_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:43 in `block in call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:92 in `with_net_http_connection'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:38 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response/logger.rb:26 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday_middleware-0.13.1/lib/faraday_middleware/response_middleware.rb:31 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/response.rb:8 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/url_encoded.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/request/multipart.rb:15 in `call'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/rack_builder.rb:143 in `build_response'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:387 in `run_request'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/faraday-0.15.4/lib/faraday/connection.rb:175 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:25 in `request'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/faraday/request.rb:10 in `post'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/web/api/endpoints/rtm.rb:18 in `rtm_connect'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:152 in `restart_async'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/client.rb:140 in `run_ping!'
13:30:21 web.1  |                |     /Users/dblock/source/slack/slack-ruby-client/dblock/lib/slack/real_time/concurrency/async.rb:43 in `block (2 levels) in start_reactor'
13:30:21 web.1  |                |     /Users/dblock/.rvm/gems/ruby-2.6.2/gems/async-1.19.0/lib/async/task.rb:210 in `block in make_fiber'

turn network back on, client doesn't do anything after this
@dblock
Copy link
Collaborator Author

dblock commented Jul 20, 2019

Logging in https://github.com/dblock/slack-ruby-client/tree/log-257

@dblock dblock changed the title Failure to reconnect on network outage Ping worker dies on unexpected error Jul 20, 2019
@dblock
Copy link
Collaborator Author

dblock commented Jul 20, 2019

So this is another variation of #277, but with Faraday::ClientError.

This was referenced Jul 20, 2019
Merged
Closed
@dblock
Copy link
Collaborator Author

dblock commented Jul 20, 2019

Closing via #279

@dblock dblock closed this as completed Jul 20, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@dblock