search

artsy / garner

A set of Rack middleware and cache helpers that implement various caching strategies.
MIT License
343 stars 24 forks source link

"TypeError: singleton can't be dumped" error on Heroku #58

Closed monfresh closed 11 years ago

monfresh commented 11 years ago

Everything is working fine in development, but on Heroku, I sometimes get TypeError: singleton can't be dumped. Any idea why?

An example is when visiting a specific location: /api/locations/521d32be1974fcdb2b000103

Here's the Grape+Garner code for that endpoint:

resource "locations" do
  desc "Get the details for a specific location"
  get ':id' do
    garner.options(expires_in: 5.minutes) do
      location = Location.find(params[:id])
      location = present location, with: Entities::Location
      location.as_json
    end
  end
end

Here's the stack trace from New Relic:

…undle/ruby/2.0.0/gems/garner-0.4.4/lib/garner/cache.rb:  12:in `fetch'
…y/2.0.0/gems/garner-0.4.4/lib/garner/cache/identity.rb:  22:in `fetch'
…y/2.0.0/gems/garner-0.4.4/lib/garner/cache/identity.rb:  54:in `options'
                                  /app/app/api/ohana.rb:  41:in `block (2 levels) in <class:API>'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb:  31:in `call'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb:  31:in `block in generate_api_method'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb: 400:in `call'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb: 400:in `run'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb: 164:in `block in call!'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  24:in `call'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  24:in `call!'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  18:in `call'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  24:in `call!'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  18:in `call'
…dor/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/etag.rb:  23:in `call'
…/ruby/2.0.0/gems/rack-1.4.5/lib/rack/conditionalget.rb:  25:in `call'
…y/2.0.0/gems/grape-0.5.0/lib/grape/middleware/error.rb:  26:in `block in call!'
…y/2.0.0/gems/grape-0.5.0/lib/grape/middleware/error.rb:  25:in `catch'
…y/2.0.0/gems/grape-0.5.0/lib/grape/middleware/error.rb:  25:in `call!'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  18:in `call'
…/newrelic-grape-1.3.1/lib/newrelic-grape/instrument.rb:  19:in `block in call!'
…/newrelic-grape-1.3.1/lib/newrelic-grape/instrument.rb:  18:in `call!'
…by/2.0.0/gems/grape-0.5.0/lib/grape/middleware/base.rb:  18:in `call'
…dor/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/head.rb:   9:in `call'
…/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/builder.rb: 134:in `call'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb: 165:in `call!'
…ndle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/endpoint.rb: 155:in `call'
….0.0/gems/rack-mount-0.8.3/lib/rack/mount/route_set.rb: 152:in `block in call'
…ems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:  96:in `block in recognize'
…ems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:  82:in `optimized_each'
…ems/rack-mount-0.8.3/lib/rack/mount/code_generation.rb:  95:in `recognize'
….0.0/gems/rack-mount-0.8.3/lib/rack/mount/route_set.rb: 141:in `call'
…or/bundle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/api.rb: 480:in `call'
…or/bundle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/api.rb:  49:in `call!'
…or/bundle/ruby/2.0.0/gems/grape-0.5.0/lib/grape/api.rb:  45:in `call'
…le/ruby/2.0.0/gems/journey-1.0.4/lib/journey/router.rb:  68:in `block in call'
…le/ruby/2.0.0/gems/journey-1.0.4/lib/journey/router.rb:  56:in `each'
…le/ruby/2.0.0/gems/journey-1.0.4/lib/journey/router.rb:  56:in `call'
…undle/ruby/2.0.0/gems/rack-pjax-0.7.0/lib/rack/pjax.rb:  12:in `call'
…goid-3.1.4/lib/rack/mongoid/middleware/identity_map.rb:  34:in `block in call'
…y/2.0.0/gems/mongoid-3.1.4/lib/mongoid/unit_of_work.rb:  39:in `unit_of_work'
…goid-3.1.4/lib/rack/mongoid/middleware/identity_map.rb:  34:in `call'
…undle/ruby/2.0.0/gems/rack-cors-0.2.8/lib/rack/cors.rb:  54:in `call'
…dle/ruby/2.0.0/gems/warden-1.2.3/lib/warden/manager.rb:  35:in `block in call'
…dle/ruby/2.0.0/gems/warden-1.2.3/lib/warden/manager.rb:  34:in `catch'
…dle/ruby/2.0.0/gems/warden-1.2.3/lib/warden/manager.rb:  34:in `call'
…dor/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/etag.rb:  23:in `call'
…/ruby/2.0.0/gems/rack-1.4.5/lib/rack/conditionalget.rb:  25:in `call'
…0.0/gems/remotipart-1.2.1/lib/remotipart/middleware.rb:  27:in `call'
…/2.0.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb: 210:in `context'
…/2.0.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb: 205:in `call'
…/ruby/2.0.0/gems/rack-1.4.5/lib/rack/methodoverride.rb:  21:in `call'
…/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/runtime.rb:  17:in `call'
                               /app/lib/api_defender.rb:  47:in `call'
…dor/bundle/ruby/2.0.0/gems/rack-1.4.5/lib/rack/lock.rb:  15:in `call'
…by/2.0.0/gems/rack-cache-1.2/lib/rack/cache/context.rb: 136:in `forward'
…by/2.0.0/gems/rack-cache-1.2/lib/rack/cache/context.rb: 245:in `fetch'
…by/2.0.0/gems/rack-cache-1.2/lib/rack/cache/context.rb: 185:in `lookup'
…by/2.0.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:  66:in `call!'
…by/2.0.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:  51:in `call'
…ruby/2.0.0/gems/rack-timeout-0.0.4/lib/rack/timeout.rb:  16:in `block in call'
       /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/timeout.rb:  66:in `timeout'
…ruby/2.0.0/gems/rack-timeout-0.0.4/lib/rack/timeout.rb:  16:in `call'
…by/2.0.0/gems/unicorn-4.6.3/lib/unicorn/http_server.rb: 552:in `process_client'
…by/2.0.0/gems/unicorn-4.6.3/lib/unicorn/http_server.rb: 632:in `worker_loop'
…by/2.0.0/gems/unicorn-4.6.3/lib/unicorn/http_server.rb: 500:in `spawn_missing_workers'
…by/2.0.0/gems/unicorn-4.6.3/lib/unicorn/http_server.rb: 142:in `start'
fancyremarker commented 11 years ago

Is that the full extent of the backtrace, or there lines before it from inside ActiveSupport::Cache (or whichever cache store you're using)?

monfresh commented 11 years ago

This happened on Heroku, and it doesn't look like that error is available in the NewRelic logs anymore. I've stopped using Garner for the time being, but I'll try to reproduce it and send you the full stack.

monfresh commented 11 years ago

I just reproduced this locally. Here's the trace:

TypeError - singleton can't be dumped:
  activesupport (3.2.13) lib/active_support/cache.rb:561:in `dump'
  activesupport (3.2.13) lib/active_support/cache.rb:561:in `initialize'
  activesupport (3.2.13) lib/active_support/cache.rb:363:in `new'
  activesupport (3.2.13) lib/active_support/cache.rb:363:in `block in write'
  activesupport (3.2.13) lib/active_support/cache.rb:520:in `instrument'
  activesupport (3.2.13) lib/active_support/cache.rb:362:in `write'
  activesupport (3.2.13) lib/active_support/cache.rb:299:in `fetch'
  garner (0.4.4) lib/garner/cache.rb:12:in `fetch'
  garner (0.4.4) lib/garner/cache/identity.rb:22:in `fetch'
  garner (0.4.4) lib/garner/cache/identity.rb:54:in `options'
  app/api/ohana.rb:43:in `block (2 levels) in <class:API>'
  grape (0.5.0) lib/grape/endpoint.rb:31:in `call'
  grape (0.5.0) lib/grape/endpoint.rb:31:in `block in generate_api_method'
  grape (0.5.0) lib/grape/endpoint.rb:400:in `call'
  grape (0.5.0) lib/grape/endpoint.rb:400:in `run'
  grape (0.5.0) lib/grape/endpoint.rb:164:in `block in call!'
  grape (0.5.0) lib/grape/middleware/base.rb:24:in `call'
  grape (0.5.0) lib/grape/middleware/base.rb:24:in `call!'
  grape (0.5.0) lib/grape/middleware/base.rb:18:in `call'
  grape (0.5.0) lib/grape/middleware/base.rb:24:in `call!'
  grape (0.5.0) lib/grape/middleware/base.rb:18:in `call'
  rack (1.4.5) lib/rack/etag.rb:23:in `call'
  rack (1.4.5) lib/rack/conditionalget.rb:25:in `call'
  grape (0.5.0) lib/grape/middleware/error.rb:26:in `block in call!'
  grape (0.5.0) lib/grape/middleware/error.rb:25:in `catch'
  grape (0.5.0) lib/grape/middleware/error.rb:25:in `call!'
  grape (0.5.0) lib/grape/middleware/base.rb:18:in `call'
  newrelic-grape (1.3.1) lib/newrelic-grape/instrument.rb:19:in `block in call!'
  newrelic_rpm (3.6.7.152) lib/new_relic/agent/instrumentation/controller_instrumentation.rb:324:in `perform_action_with_newrelic_trace'
  newrelic-grape (1.3.1) lib/newrelic-grape/instrument.rb:18:in `call!'
  grape (0.5.0) lib/grape/middleware/base.rb:18:in `call'
  rack (1.4.5) lib/rack/head.rb:9:in `call'
  rack (1.4.5) lib/rack/builder.rb:134:in `call'
  grape (0.5.0) lib/grape/endpoint.rb:165:in `call!'
  grape (0.5.0) lib/grape/endpoint.rb:155:in `call'
  rack-mount (0.8.3) lib/rack/mount/route_set.rb:152:in `block in call'
  rack-mount (0.8.3) lib/rack/mount/code_generation.rb:96:in `block in recognize'
  rack-mount (0.8.3) lib/rack/mount/code_generation.rb:82:in `optimized_each'
  rack-mount (0.8.3) lib/rack/mount/code_generation.rb:95:in `recognize'
  rack-mount (0.8.3) lib/rack/mount/route_set.rb:141:in `call'
  grape (0.5.0) lib/grape/api.rb:480:in `call'
  grape (0.5.0) lib/grape/api.rb:49:in `call!'
  grape (0.5.0) lib/grape/api.rb:45:in `call'
  journey (1.0.4) lib/journey/router.rb:68:in `block in call'
  journey (1.0.4) lib/journey/router.rb:56:in `each'
  journey (1.0.4) lib/journey/router.rb:56:in `call'
  actionpack (3.2.13) lib/action_dispatch/routing/route_set.rb:612:in `call'
  rack-pjax (0.7.0) lib/rack/pjax.rb:12:in `call'
  newrelic_rpm (3.6.7.152) lib/new_relic/rack/error_collector.rb:43:in `call'
  newrelic_rpm (3.6.7.152) lib/new_relic/rack/agent_hooks.rb:22:in `call'
  newrelic_rpm (3.6.7.152) lib/new_relic/rack/browser_monitoring.rb:16:in `call'
  newrelic_rpm (3.6.7.152) lib/new_relic/rack/developer_mode.rb:28:in `call'
  bullet (4.6.0) lib/bullet/rack.rb:13:in `call'
  mongoid (3.1.4) lib/rack/mongoid/middleware/identity_map.rb:34:in `block in call'
  mongoid (3.1.4) lib/mongoid/unit_of_work.rb:39:in `unit_of_work'
  mongoid (3.1.4) lib/rack/mongoid/middleware/identity_map.rb:34:in `call'
  rack-cors (0.2.8) lib/rack/cors.rb:54:in `call'
  warden (1.2.3) lib/warden/manager.rb:35:in `block in call'
  warden (1.2.3) lib/warden/manager.rb:34:in `catch'
  warden (1.2.3) lib/warden/manager.rb:34:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  rack (1.4.5) lib/rack/etag.rb:23:in `call'
  rack (1.4.5) lib/rack/conditionalget.rb:25:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/head.rb:14:in `call'
  remotipart (1.2.1) lib/remotipart/middleware.rb:27:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/flash.rb:242:in `call'
  rack (1.4.5) lib/rack/session/abstract/id.rb:210:in `context'
  rack (1.4.5) lib/rack/session/abstract/id.rb:205:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/cookies.rb:341:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  activesupport (3.2.13) lib/active_support/callbacks.rb:405:in `_run__3327997775750947040__call__4256537579331788061__callbacks'
  activesupport (3.2.13) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.13) lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  activesupport (3.2.13) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.13) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/reloader.rb:65:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  better_errors (1.0.1) lib/better_errors/middleware.rb:84:in `protected_app_call'
  better_errors (1.0.1) lib/better_errors/middleware.rb:79:in `better_errors_call'
  better_errors (1.0.1) lib/better_errors/middleware.rb:56:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  railties (3.2.13) lib/rails/rack/logger.rb:32:in `call_app'
  railties (3.2.13) lib/rails/rack/logger.rb:16:in `block in call'
  activesupport (3.2.13) lib/active_support/tagged_logging.rb:22:in `tagged'
  railties (3.2.13) lib/rails/rack/logger.rb:16:in `call'
  quiet_assets (1.0.2) lib/quiet_assets.rb:18:in `call_with_quiet_assets'
  actionpack (3.2.13) lib/action_dispatch/middleware/request_id.rb:22:in `call'
  rack (1.4.5) lib/rack/methodoverride.rb:21:in `call'
  rack (1.4.5) lib/rack/runtime.rb:17:in `call'
  activesupport (3.2.13) lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  lib/api_defender.rb:47:in `call'
  rack (1.4.5) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.13) lib/action_dispatch/middleware/static.rb:63:in `call'
   () Users/moncef/.rvm/gems/ruby-2.0.0-p247@ohana-api/bundler/gems/raven-ruby-f597e0aef308/lib/raven/rack.rb:47:in `call'
  rack-timeout (0.0.4) lib/rack/timeout.rb:16:in `block in call'
  /Users/moncef/.rvm/rubies/ruby-2.0.0-p247/lib/ruby/2.0.0/timeout.rb:66:in `timeout'
  rack-timeout (0.0.4) lib/rack/timeout.rb:16:in `call'
  railties (3.2.13) lib/rails/engine.rb:479:in `call'
  railties (3.2.13) lib/rails/application.rb:223:in `call'
  rack (1.4.5) lib/rack/content_length.rb:14:in `call'
  railties (3.2.13) lib/rails/rack/log_tailer.rb:17:in `call'
  rack (1.4.5) lib/rack/handler/webrick.rb:59:in `service'
  /Users/moncef/.rvm/rubies/ruby-2.0.0-p247/lib/ruby/2.0.0/webrick/httpserver.rb:138:in `service'
  /Users/moncef/.rvm/rubies/ruby-2.0.0-p247/lib/ruby/2.0.0/webrick/httpserver.rb:94:in `run'
  /Users/moncef/.rvm/rubies/ruby-2.0.0-p247/lib/ruby/2.0.0/webrick/server.rb:295:in `block in start_thread'
monfresh commented 11 years ago

I think I figured it out. The reason why it only happened intermittently is because it was only caused by locations that have categories. The Category model acts_as_nested_set (using the gem glebtv-mongoid_nested_set) and I was trying to expose categories using Category::Entity, but for some reason it doesn't like that. After exposing categories straight up, the error disappears and I can cache those locations.

fancyremarker commented 11 years ago

Great, thanks! Sounds like this may have been an issue with acts_as_nested_set affecting the method chain that gets invoked when ActiveSupport::Cache tries to unmarshal a string.

I feel like maybe Garner could introduce a set of strategies to deal with errors that bubble up from the underlying cache store, since there are so many uncertain interactions involved with marshaling and unmarshaling. Three example strategies would be:

  1. Pass all exceptions through (the current behavior)
  2. Catch any exceptions on unmarshaling, re-executing the garner block when this happens.

  3. 2, with smart logging of where unmarshaling errors occur (via Graphite or other)