search

nomad-cli / houston

Apple Push Notifications; No Dirigible Required
http://nomad-cli.com
MIT License
2.93k stars 229 forks source link

Houston and Sidekiq and SSL problems #46

Closed elaser closed 10 years ago

elaser commented 10 years ago

Hi there! I've been using Houston for awhile and it is awesome for sending out APNS. My rails server is currently on Heroku and I am sending notifications via Houston in the background with Sidekiq. The problem is every hour, I get SSL failure and no more notifications can be fired. What I'm seeing in the logs looks like:

2014-04-09T18:31:03.254876+00:00 app[worker.1]: 2014-04-09T18:31:03Z 2 TID-ov652jh60 NotificationWorker JID-6e547188b78402ed2702f70d INFO: fail: 0.009 sec
2014-04-09T18:31:03.261789+00:00 app[worker.1]: 2014-04-09T18:31:03Z 2 TID-ov652jh60 WARN: {"retry"=>true, "queue"=>"default", "unique"=>true, "class"=>"NotificationWorker", "args"=>[561, "a0233ebdda747002e2b71113bf26adcd8a9188005113c24a4b50ad3098044a41"], "jid"=>"6e547188b78402ed2702f70d", "enqueued_at"=>1397066881.4699736, "error_message"=>"SSL_write: bad write retry", "error_class"=>"OpenSSL::SSL::SSLError", "failed_at"=>1397066881.4908812, "retry_count"=>6, "retried_at"=>1397068263.2529194}
2014-04-09T18:31:03.261843+00:00 app[worker.1]: 2014-04-09T18:31:03Z 2 TID-ov652jh60 WARN: SSL_write: bad write retry
2014-04-09T18:31:03.261929+00:00 app[worker.1]: 2014-04-09T18:31:03Z 2 TID-ov652jh60 WARN: /app/vendor/ruby-2.1.1/lib/ruby/2.1.0/openssl/buffering.rb:326:in `syswrite'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/ruby-2.1.1/lib/ruby/2.1.0/openssl/buffering.rb:326:in `do_write'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/ruby-2.1.1/lib/ruby/2.1.0/openssl/buffering.rb:344:in `write'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/app/wo
rkers/notification_worker.rb:43:in `block in perform'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/connection_pool-2.0.0/lib/connection_pool.rb:58:in `with'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/app/workers/notification_worker.rb:27:in `perform'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:50:in `block (2 levels) in process'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:122:in `call'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:122:in `block in invoke'
2014-04-09T18:31:03.261929+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.7.3.204/lib/new_relic/agent/instrumentation/sidekiq.rb:30:in `block in call'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.7.3.204/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:335:in `perform_action_with_newrelic_trace'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.7.3.204/lib/new_relic/agent/instrumentation/sidekiq.rb:21:in `call'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/retry_jobs.rb:62:in `call'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/logging.rb:22:in `with_context'
2014-04-09T18:31:03.262153+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:127:in `call'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:127:in `invoke'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:49:in `block in process'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:92:in `stats'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:48:in `process'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
2014-04-09T18:31:03.262354+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
2014-04-09T18:31:03.262922+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
2014-04-09T18:31:03.262922+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
2014-04-09T18:31:03.262922+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'

My NotificationWorker file looks like 

class NotificationWorker
    include Sidekiq::Worker
  sidekiq_options unique: true
    require 'houston'

    APN_POOL = ConnectionPool.new(:size => 2, :timeout => 300) do
    uri, certificate = if Rails.env.development?
      [
        Houston::APPLE_DEVELOPMENT_GATEWAY_URI,
        File.read(ENV["APN_CERT"])
      ]
    else
      [
        Houston::APPLE_PRODUCTION_GATEWAY_URI,
        File.read(ENV["APN_CERT"])
      ]
    end

    connection = Houston::Connection.new(uri, certificate, "password")
    connection.open

    connection
  end

  def perform(notification_id, token)
    APN_POOL.with do |connection|
      notification = Notification.find(notification_id)

      remote_notification = Houston::Notification.new(device: token)
      remote_notification.alert = notification.body
      remote_notification.badge = 1
      connection.write(remote_notification.message)
    end
  end
end

My Procfile looks like:

worker: bundle exec sidekiq

I have other workers running but I've limited the problem down to this notification_worker class. Has anyone else run into this problem before also?

Thanks a lot! Anderthan

elaser commented 10 years ago

I was able to resolve this problem by checking to see if the connection pool is dead. If it is I will re-initialize it.

pnicholls commented 10 years ago

hey @elaser I am having this same issue, do you mind posting your worker class up so i can see how you are fixing this?