Search code examples
ruby-on-rails-3twiliosidekiq

Getting weird errors when trying to send a message through Twilio


We made a big upgrade to our backend yesterday and now we're getting some weird errors and I have no idea what they are. The errors seem to be happening when trying to send a message via Twilio's client. Also, things are getting backed up in our sidekiq queue we believe because of these errors. Our sidekiq busy tab has a few things waiting there. Here are some of the errors we're seeing:

  • IOError: closed stream
  • OpenSSL::SSL::SSLError: SSL_connect returned=1 errno=0 state=SSLv3 read server hello A: unknown alert type
  • Net::ReadTimeout: Net::ReadTimeout
  • EOFError: end of file reached
  • IOError: attempt to read body out of block
  • Errno::EBADF: Bad file descriptor

These haven't happened for us much in the past and now they are happening very frequently. Here's a stacktrace for the IOError: closed stream error:

/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/protocol.rb:155 in "select"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/protocol.rb:155 in "rescue in rbuf_fill"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/protocol.rb:152 in "rbuf_fill"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/protocol.rb:134 in "readuntil"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/protocol.rb:144 in "readline"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http/response.rb:39 in "read_status_line"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http/response.rb:28 in "read_new"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1408 in "block in transport_request"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1405 in "catch"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1405 in "transport_request"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1378 in "request"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:27 in "block (2 levels) in request_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent.rb:454 in "disable_all_tracing"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:26 in "block in request_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/cross_app_tracing.rb:38 in "tl_trace_http_request"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:23 in "request_with_newrelic_trace"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1371 in "block in request"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:853 in "start"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb:1369 in "request"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:27 in "block (2 levels) in request_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent.rb:454 in "disable_all_tracing"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:26 in "block in request_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/cross_app_tracing.rb:43 in "tl_trace_http_request"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/net.rb:23 in "request_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/twilio-ruby-3.11.5/lib/twilio-ruby/rest/client.rb:216 in "connect_and_send"
/vendor/bundle/ruby/2.1.0/gems/twilio-ruby-3.11.5/lib/twilio-ruby/rest/client.rb:168 in "block (2 levels) in <class:Client>"
/vendor/bundle/ruby/2.1.0/gems/twilio-ruby-3.11.5/lib/twilio-ruby/rest/list_resource.rb:91 in "create"
/app/models/message_sender.rb:142 in "send_message_with_twilio!"
/app/models/message_sender.rb:66 in "send_sms"
/app/models/message_sender.rb:37 in "send_now"
/app/models/message_sender.rb:19 in "block (2 levels) in save_and_send_from_job"
/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/connection_adapters/abstract/database_statements.rb:201 in "block in transaction"
/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/connection_adapters/abstract/database_statements.rb:209 in "within_new_transaction"
/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/connection_adapters/abstract/database_statements.rb:201 in "transaction"
/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/transactions.rb:208 in "transaction"
/app/models/message_sender.rb:17 in "block in save_and_send_from_job"
/app/models/message_sender.rb:16 in "each"
/app/models/message_sender.rb:16 in "save_and_send_from_job"
/app/workers/send_single_sms_worker.rb:8 in "perform"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:49 in "block (3 levels) in process"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:122 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:122 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/sidekiq.rb:33 in "block in call"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:365 in "perform_action_with_newrelic_trace"
/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.9.5.251/lib/new_relic/agent/instrumentation/sidekiq.rb:29 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidetiq-0.6.1/lib/sidetiq/middleware/history.rb:8 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-history-0.0.1/lib/sidekiq/history/middleware.rb:26 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/active_record.rb:6 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/retry_jobs.rb:62 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/bundler/gems/sidekiq-failures-485c6e56e306/lib/sidekiq/failures/middleware.rb:9 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/logging.rb:11 in "block in call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/logging.rb:22 in "with_context"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/logging.rb:7 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:127 in "call"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:127 in "invoke"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:48 in "block (2 levels) in process"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:108 in "stats"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:47 in "block in process"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:86 in "do_defer"
/vendor/bundle/ruby/2.1.0/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:37 in "process"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26 in "public_send"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26 in "dispatch"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122 in "dispatch"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60 in "block in invoke"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71 in "block in task"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357 in "block in task"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57 in "block in initialize"
/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15 in "block in create"

Solution

  • Most likely found the issue since we haven't had any problems since fixing it this way. Turns out the Twilio Client is not thread safe and we were trying to hammer the same @client with a bunch of different threads. The fix was to make sure that we create a new twilio client every single time we need one.