Crashes on Heroku

[mmorrison]

My instance seems to keep crashing randomly. I believe it is running out of memory but I am unsure why. Do you have any recomended settings, e.g. max thread / minthreads? Have you seen any issues related to this?

[mmorrison]

It appears my Request Throughput seems to running at 30,002 and I am not sure why.

[brandonmikeska]

@mmorrison still haven't figured out if it's LocomotiveCMS or thew new hobby plan by Heroku. It was working on the old pricing plan perfectly but now I get the same errors.

[mmorrison]

@brandonmikeska I am running on the Standard 2x currently, with the same issues.

[brandonmikeska]

@did if this is true, and I believe you @mmorrison, it sounds we may have a memory leak somewhere.

[mmorrison]

@brandonmikeska is there anything I can provide you guys to help narrow down the issue?

[did]

@brandonmikeska @mmorrison how about using this new service https://www.skylight.io? They've got excellent posts on their blog (for instance: http://blog.skylight.io/hunting-for-leaks-in-ruby/).

[mmorrison]

I'll add skylight to the project. But I did start to notice something in the logs and was able to recreate it in the console by accessing the first account, Locomotive::Account.first, not sure if it is related.

SystemStackError: stack level too deep
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/string.rb:79:in `to_bson_cstring'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/string.rb:63:in `to_bson_key'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/symbol.rb:58:in `to_bson_key'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/hash.rb:45:in `block (2 levels) in to_bson'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/hash.rb:43:in `each'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/hash.rb:43:in `block in to_bson'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/encodable.rb:57:in `encode_with_placeholder_and_null'
    from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.4/lib/bson/hash.rb:42:in `to_bson'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/protocol/message.rb:173:in `serialize_selector'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/protocol/message.rb:325:in `serialize'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:171:in `block in write'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:169:in `each'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:169:in `write'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/authenticatable.rb:64:in `login'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/operation/read.rb:55:in `block (2 levels) in execute'
    from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/node.rb:118:in `block in connection'
... 9285 levels...
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/query_cache.rb:190:in `first_with_cache'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:199:in `block (2 levels) in first'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:545:in `with_sorting'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:198:in `block in first'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:457:in `try_cache'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:197:in `first'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual.rb:20:in `first'
    from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/findable.rb:144:in `first'
    from (irb):11
    from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/console.rb:110:in `start'
    from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/console.rb:9:in `start'
    from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/commands_tasks.rb:68:in `console'
    from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
    from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands.rb:17:in `<top (required)>'
    from bin/rails:4:in `require'

[did]

we're not alone: http://stackoverflow.com/questions/32951455/mongoid-infinite-loop-on-query

[rvalyi]

Hello, I have this same error (running on Dokku).

If access the Rails console and do: Locomotive::Site.first

[...]
fields=nil runtime: 963.1169ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 965.1053ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 967.5288ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 969.5954ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 971.8912ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 974.1280ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 976.9187ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 980.5714ms
  MOPED: 172.17.0.214:27017 QUERY        database=loco collection=locomotive_sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 997.7921ms
SystemStackError: stack level too deep
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/string.rb:79:in `to_bson_cstring'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/string.rb:63:in `to_bson_key'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/symbol.rb:58:in `to_bson_key'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/hash.rb:45:in `block (2 levels) in to_bson'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/hash.rb:43:in `each'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/hash.rb:43:in `block in to_bson'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/encodable.rb:57:in `encode_with_placeholder_and_null'
        from /app/vendor/bundle/ruby/2.2.0/gems/bson-3.2.1/lib/bson/hash.rb:42:in `to_bson'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/protocol/message.rb:173:in `serialize_selector'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/protocol/message.rb:325:in `serialize'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:171:in `block in write'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:169:in `each'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/connection.rb:169:in `write'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/authenticatable.rb:64:in `login'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/operation/read.rb:55:in `block (2 levels) in execute'
        from /app/vendor/bundle/ruby/2.2.0/gems/moped-2.0.7/lib/moped/node.rb:118:in `block in connection'
... 9285 levels...
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/query_cache.rb:190:in `first_with_cache'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:199:in `block (2 levels) in first'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:545:in `with_sorting'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:198:in `block in first'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:457:in `try_cache'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual/mongo.rb:197:in `first'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/contextual.rb:20:in `first'
        from /app/vendor/bundle/ruby/2.2.0/gems/mongoid-4.0.2/lib/mongoid/findable.rb:144:in `first'
        from (irb):4
        from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/console.rb:110:in `start'
        from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/console.rb:9:in `start'
        from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/commands_tasks.rb:68:in `console'
        from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
        from /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.4/lib/rails/commands.rb:17:in `<top (required)>'
        from bin/rails:4:in `require'
        from bin/rails:4:in `<main>'irb(main):005:0> 

[rvalyi]

In fact in my case I can simply never connect to the interface as it always break into that loop.

[mmorrison]

I was able to switch over and use Compose MongoDB to get it too work. The stackoverflow article referenced MongoLab using sharded databases on the free plan. I looked into updating the mongo config, as suggested on stackoverflow, but was only able to find a way to change it in Mongo 5.0.

I hope this helps narrow down what the issue could be. I plan to monitor the app and will report back if I see the issue appear with the new Mongo provider.

[rvalyi]

note that in my case have the issue on Dokku (not tested on Heroku), this is using Mongo from https://github.com/dokku/dokku-mongo that is it's using the regular Mongo server 3.0.6 from here https://hub.docker.com/_/mongo/ For some reason I cannot easily make local tests outside this stack these days.

@mmorrison when you mentioned Mongo 5.0, you were talking about mongoid 5 ?

[mmorrison]

@rvalyi Yes sorry I was talking about Mongoid 5.

[rvalyi]

@mmorrison any chance you can share your Gemfile / Gemfle.lock ? would like to test locomotive v3. I tried to just change the mongoid ref to mongoid 5.0.0 in my Gemfile.lock but it doesn't seem as simple as I got this startup error then:

2015-10-09T02:21:35.033633036Z loco[web.1]: [13] Puma starting in cluster mode...
2015-10-09T02:21:35.033869468Z loco[web.1]: [13] * Version 2.13.4 (ruby 2.2.2-p95), codename: A Midsummer Code's Dream
2015-10-09T02:21:35.033983219Z loco[web.1]: [13] * Min threads: 5, max threads: 5
2015-10-09T02:21:35.034066833Z loco[web.1]: [13] * Environment: production
2015-10-09T02:21:35.034153963Z loco[web.1]: [13] * Process workers: 2
2015-10-09T02:21:35.034385462Z loco[web.1]: [13] * Preloading application
2015-10-09T02:21:37.945361518Z loco[web.1]: [13] ! Unable to load application: LoadError: cannot load such file -- bson
2015-10-09T02:21:37.945622485Z loco[web.1]: /app/vendor/bundle/ruby/2.2.0/bundler/gems/engine-45ac1129da05/lib/locomotive/dependencies.rb:1:in `require': cannot load such file -- bson (LoadError)
2015-10-09T02:21:37.945692608Z loco[web.1]:     from /app/vendor/bundle/ruby/2.2.0/bundler/gems/engine-45ac1129da05/lib/locomotive/dependencies.rb:1:in `<top (required)>'
2015-10-09T02:21:37.945729816Z loco[web.1]:     from /app/vendor/bundle/ruby/2.2.0/bundler/gems/engine-45ac1129da05/lib/locomotive/engine.rb:1:in `require'
[...]

[did]

working on it (https://trello.com/c/achbxT8J/83-mongoid-upgrade-to-mongoid-5-0)

[rvalyi]

Hello thanks @did. BTW I'll answer your email just been terribly busy these days and yes upgrading our website before signing new contracts (we have the wagon repo) is part of the rush... But kudos for the terrific work as usual.

[mmorrison]

@rvalyi Yea here is my Gemfile.lock, https://gist.github.com/mmorrison/c1489e4201fa6921843b.

[mmorrison]

@rvalyi @did I really appreciate your help!

[did]

@rvalyi thanks! (talk to you soon!)

[did]

I keep updated my work on that here: https://trello.com/c/achbxT8J/83-mongoid-upgrade-to-mongoid-5-0

[did]

Bummer, back to mongoid 4 :-( Check this out https://jira.mongodb.org/browse/MONGOID-4159. This issue is so big that we can't upgrade to mongoid 5.

So, the initial issue is about MongoLab databases being sharded and Mongoid 4.0 seems unable to query collections without sharded keys. Let me ask people from MongoLab.

[did]

Email sent to the Mongolab team.

[rvalyi]

@did too bad for mongoid 5. But notice that in my case I have the issue on Dokku with the regular Mongo server (in a Docker though), it's not Heroku and it's easy to reproduce. If that's really a problem for you to reproduce the issue, I can put an SSH key on that server and let you push and open a Rails console debug if that would help. But really it's just the regular Dokku install with the official Mongo plugin and a push of this repo: https://github.com/akretion/heroku-instant-deploy

[did]

MongoLab's answer:

This Sandbox database is now running MongoDB 3.0.x, which includes changes to MongoDB's authentication mechanism. This new mechanism is supported by certain newer driver versions

For your specific case of Ruby driver, Mongoid 4 doesn't support MongoDB 3.0. In this case if you still want to use the free sandbox database you would have to upgrade to Mongoid 5.

If using a 3.0-compatible driver(like Mongoid 5) is not an option, you may want to consider upgrading to a Shared or Dedicated plan (https://mongolab.com/plans/pricing/), which will provide MongoDB 2.6 as an option.

Bottom line, Locomotive v3 only works with MongoDB 2.6.

[rvalyi]

hum, my test on Dokku was with MongoDB server 3.0.6, not 2.6, so it may explain why had the issue too.

@did now https://jira.mongodb.org/browse/MONGOID-4159 seems to have been reported recently and also it's classified as Blocker - P1, so eventually the mongoid team get it fixed soon enough. Sounds possible?

[did]

@rvalyi so I'm watching the issue, see how fast they'll fix it.

[did]

UPDATE MONGOID JIRA Ruby Sprint 27 ends 26/Oct/15

[rvalyi]

I have also seen that it's one of the only 2 major mongoid bugs. So that would be very unlikely they don't fix it...

[treacher]

Yeah i'm pretty sure MongoLab did this to get a bunch of people off their free plans knowing full well that the ruby community isn't quite MongoDB 3.0 ready yet.

[rvalyi]

from the Mongoid bug tracker, the fix entered in code review: https://github.com/mongodb/mongoid/pull/4179

[rvalyi]

@did fixed and released on Monglab side https://github.com/mongodb/mongoid/commits/master https://jira.mongodb.org/browse/MONGOID-4159

How do we stand on LocomotiveCMS regarding mongoid 5?

[did]

The deploy button works again!