2

I wrote an application for Facebook using Ruby, on a Heroku server, and everything was going well until I increased the number of dynos to 2. At this point, about half of the times I went to a new page, I would get an error message, or I would be returned to the home page, depending on what page I went to. I fixed this problem by returning to one dyno, but I still don't know what went wrong. Any ideas? The code can be found here:

https://github.com/runninggraeb/toolshed

and the program can be found here (if you're interested):

https://apps.facebook.com/toolshed

Any help would be appreciated.

All logs are pasted below. Note that the error messages started after I used dyno=web.1, then dyno=web.2.

2013-03-10T22:34:54+00:00 heroku[router]: at=info method=GET path=/auth/facebook host=toolshed.herokuapp.com fwd="24.20.19.205" dyno=web.2 queue=0 wait=7ms connect=5ms service=10ms status=302 bytes=0
2013-03-10T22:34:57+00:00 app[web.1]: 24.20.19.205 - - [10/Mar/2013 22:34:57] "GET /auth/facebook/callback?code=AQC7B6vjC0ksefFLly76DMeqL-hHrR6M49lYgMqiAk01xmF-nbXC9pOAcd_e5x8KTycXcjfXG_ABRUmsfeQlusGECbL7d4PqF-nTIVMA1GBn8hAemVCBKXy8sUspQ1eIZAxICtYeSUk9DzM8-It9-AAbi0FudCRS8PkcTaZ-8SXnNYRk2-iYKMin_fYUG2kT8LbApmaeb1RjtxXQUF8HbvAu HTTP/1.1" 302 - 0.0724
2013-03-10T22:34:57+00:00 app[web.1]: 24.20.19.205 - - [10/Mar/2013 22:34:57] "GET / HTTP/1.1" 200 6836 0.2166
2013-03-10T22:34:57+00:00 heroku[router]: at=info method=GET path=/ host=toolshed.herokuapp.com fwd="24.20.19.205" dyno=web.1 queue=0 wait=9ms connect=15ms service=235ms status=200 bytes=6836
2013-03-10T22:35:01+00:00 app[web.2]: NoMethodError - undefined method `length' for nil:NilClass:
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:708:in `block (2 levels) in route!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:755:in `catch'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:755:in `process_route'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:758:in `block in process_route'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.4.33/lib/new_relic/agent/method_tracer.rb:242:in `trace_execution_scoped'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:808:in `block in invoke'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.4.33/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:268:in `block in perform_action_with_newrelic_trace'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:808:in `catch'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:644:in `block in call!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:808:in `invoke'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:808:in `instance_eval'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/app.rb:86:in `block in <top (required)>'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:1152:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:1152:in `block in compile!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:724:in `instance_eval'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:706:in `each'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:706:in `route!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:724:in `route_eval'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:843:in `dispatch!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.2/lib/rack/head.rb:9:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.4.33/lib/new_relic/agent/instrumentation/sinatra.rb:48:in `block in dispatch_with_newrelic'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.4.33/lib/new_relic/agent/instrumentation/sinatra.rb:47:in `dispatch_with_newrelic'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:1303:in `synchronize'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.4.33/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:263:in `perform_action_with_newrelic_trace'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:707:in `block in route!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/connection.rb:84:in `block in pre_process'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:1272:in `block in call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/connection.rb:82:in `catch'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.2/lib/rack/commonlogger.rb:20:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:644:in `call!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:629:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:190:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/connection.rb:57:in `process'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.2/lib/rack/methodoverride.rb:24:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run_machine'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/sinatra-1.2.6/lib/sinatra/base.rb:1272:in `call'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/connection.rb:82:in `pre_process'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/controllers/controller.rb:86:in `start'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/backends/base.rb:61:in `start'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/runner.rb:185:in `run_command'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/bin/thin:19:in `load'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/server.rb:159:in `start'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.2/lib/rack/session/abstract/id.rb:195:in `context'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/runner.rb:151:in `run!'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/lib/thin/connection.rb:42:in `receive_data'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/bin/thin:19:in `<main>'
2013-03-10T22:35:01+00:00 app[web.2]:  /app/vendor/bundle/ruby/1.9.1/gems/thin-1.2.11/bin/thin:6:in `<top (required)>'
2013-03-10T22:35:01+00:00 app[web.2]: 24.20.19.205 - - [10/Mar/2013 22:35:01] "GET /friends_tools.html HTTP/1.1" 500 30 0.1515
2013-03-10T22:35:01+00:00 heroku[router]: at=info method=GET path=/friends_tools.html host=toolshed.herokuapp.com fwd="24.20.19.205" dyno=web.2 queue=0 wait=0ms connect=4ms service=156ms status=500 bytes=30
yfeldblum
  • 65,165
  • 12
  • 129
  • 169
Ryan
  • 121
  • 1
  • 1
  • 11
  • Paste some of your error logs from Heroku – catsby Mar 11 '13 at 01:37
  • "NoMethodError - undefined method `length' for nil:NilClass:" is an app error. `3.5.8.72` is an older version of the New Relic gem. `bundle update newrelic_rpm` and push that, then see what you get – catsby Mar 11 '13 at 03:03
  • I tried that, but I still got the same error- good thing to fix, though. Thanks! – Ryan Mar 11 '13 at 03:30
  • I helped! http://stackoverflow.com/questions/8865712/rails-3-1-3-on-heroku-no-route-matches-get-assets-rails-png –  May 07 '13 at 20:56

1 Answers1

0

The fact that the problem only crops when scaling beyond one dyno suggests that it might be a shared-state problem. I.e. user authenticates on dyno-1 and a session-id gets stored in-memory on dyno-1. Same user's next request is server by dyno-2 which has no knowledge of the session and blows up. This is pure conjecture, I've haven't inspected your code.

Alternatively, this Sinatra issue has a similar-looking error from New Relic and suggests that upgrading to a pre-release version of the New Relic problem can solve the problem.

friism
  • 19,068
  • 5
  • 80
  • 116
  • If there was a problem with user authentication passing between dyno-1 and dyno-2, do you have any advice as to how to work around this? Would the solution be to store the authentication in another location, or to check with the other dynos? – Ryan Mar 11 '13 at 15:03
  • If the problem is due to shared state, then you have to make sure that shared stateis stored where all dynos access it, i.e. database, shared memcache or something else. – friism Mar 11 '13 at 15:27