401 unauthorized errors on Heroku with Delayed Job

Question

We've built and deployed an application on Heroku, and certain processes on this app have begun to time out, and I urgently need to move them to background processes.

I have done this using delayed_job, and carefully followed the steps in Heroku's documentation on how to set this up. Locally, this is working fine.

In production, however, creating the delayed job is throwing a 401. This error appears to be occurring outside of our application, i.e., not in code that we wrote. I am pretty much entirely stumped by this error, since it appears to deal with a lot of Heroku internals. I'm going to paste in portions of the exception notification email that we get when these types of errors occur.

A Heroku::API::Errors::Unauthorized occurred in surveys#export:

Expected(200) <=> Actual(401 Unauthorized)
request => {:chunk_size=>1048576, :connect_timeout=>60, :headers=>{"Accept"=>"application/json", "Accept-Encoding"=>"gzip", "Authorization"=>"Basic Og==", "User-Agent"=>"heroku-rb/0.3.5", "X-Ruby-Version"=>"1.9.3", "X-Ruby-Platform"=>"x86_64-linux", "Host"=>"api.heroku.com:443"}, :instrumentor_name=>"excon", :mock=>false, :nonblock=>false, :read_timeout=>60, :retry_limit=>4, :ssl_ca_file=>"/app/vendor/bundle/ruby/1.9.1/gems/excon-0.16.4/data/cacert.pem", :ssl_verify_peer=>true, :write_timeout=>60, :host=>"api.heroku.com", :path=>"/apps/msu/ps", :port=>"443", :query=>nil, :scheme=>"https", :expects=>200, :method=>:get}
response => #<Excon::Response:0x0000000957d7e0 @body="{\"error\":\"Access denied\"}", @headers={"Cache-Control"=>"no-cache", "Content-Type"=>"application/json; charset=utf-8", "Date"=>"Tue, 13 Nov 2012 17:00:05 GMT", "Server"=>"nginx/1.2.3", "Status"=>"401 Unauthorized", "Strict-Transport-Security"=>"max-age=500", "X-Runtime"=>"11", "Content-Length"=>"25", "Connection"=>"keep-alive"}, @status=401>
vendor/bundle/ruby/1.9.1/gems/excon-0.16.4/lib/excon/connection.rb:290:in `request_kernel'

Request:

• URL : https://example.com/surveys/5/export
• IP address: REDACTED
• Parameters: {"action"=>"export", "controller"=>"forge/surveys", "id"=>"5"}
• Rails root: /app
• Timestamp : 2012-11-13 12:00:06 -0500

Backtrace:

vendor/bundle/ruby/1.9.1/gems/excon-0.16.4/lib/excon/connection.rb:290:in `request_kernel'
vendor/bundle/ruby/1.9.1/gems/excon-0.16.4/lib/excon/connection.rb:101:in `request'
vendor/bundle/ruby/1.9.1/gems/heroku-api-0.3.5/lib/heroku/api.rb:62:in `request'
vendor/bundle/ruby/1.9.1/gems/heroku-api-0.3.5/lib/heroku/api/processes.rb:9:in `get_ps'
vendor/bundle/ruby/1.9.1/gems/workless-1.1.0/lib/workless/scalers/heroku_cedar.rb:18:in `workers'
vendor/bundle/ruby/1.9.1/gems/workless-1.1.0/lib/workless/scalers/heroku_cedar.rb:10:in `up'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.6/lib/active_support/callbacks.rb:407:in `_run__4556705234962331285__create__3481342325198152291__callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.6/lib/active_support/callbacks.rb:405:in `__run_callback'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.6/lib/active_support/callbacks.rb:385:in `_run_create_callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.6/lib/active_record/callbacks.rb:268:in `create'
vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.6/lib/active_record/persistence.rb:344:in `create_or_update'
vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.6/lib/active_record/callbacks.rb:264:in `block in create_or_update'

I have removed the rest of the backtrace. Nothing in the backtrace references anything in our application.

Any help would be appreciated.

Update

Here's the code for survey export - pretty basic!

def export
  @survey.delay.export(current_user.email)
  flash[:notice] = "Your survey exports have been queued for processing and will be emailed to #{current_user.email} when complete."
  redirect_to forge_surveys_path
end

Answer 1

Okay, I figured this out by - of course - browsing the source of the various libraries that were invoked in the backtrace.

The most relevant line:

vendor/bundle/ruby/1.9.1/gems/heroku-api-0.3.5/lib/heroku/api/processes.rb:9:in `get_ps'

This uses the heroku-api gem to go get some worker processes. Browsing the source of the heroku-api gem, I see that when you make a request via the API, it initializes a connection like so:

@api_key = options.delete(:api_key) || ENV['HEROKU_API_KEY']
if !@api_key && options.has_key?(:username) && options.has_key?(:password)
  @connection = Excon.new("#{options[:scheme]}://#{options[:host]}", options.merge(:headers => HEADERS))
  @api_key = self.post_login(options[:username], options[:password]).body["api_key"]
end

My environment did not have ENV['HEROKU_API_KEY'] set. I did have the HEROKU_PASSWORD set, which contains the same data, but that's not what this gem is looking for. Thus, I was getting 401 errors on this.

I will submit an update to the Heroku documentation and ask them to include this as one of the steps, since it is not in there now.

To fix this, I simply did:

heroku config:add HEROKU_API_KEY=KEY

Where KEY is the same as the value for HEROKU_PASSWORD. (You can view all config vars with heroku config).