Mongodb auth fails on *.meteor.com only fixed by deleting and redeploying

[Rob Marscher]

If my app crashes (for whatever reason) or if I deploy a new version, it seems it can no longer connect to mongo at meteor.m0.mongolayer.com.  The logs give "auth fails" errors.  To fix, I've been doing a mongodump, deleting the deployment, deploying again, and then running mongoimport to put the database back.

I'm using a custom CNAME for my url.  That might be involved because this just started happening a few days ago after I deployed to a CNAME rather than a meteor subdomain.

Is this happening to anyone else?  I though it could have been from deploying code for 0.5.7 (I think), but I upgraded last night to 0.6.0 and it happened again today.  Happens about once or twice a day.

Here are some of the logs.  Thanks a lot,

Rob

Fri Apr 05 2013 20:49:46 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:50:48 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:51:46 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:52:46 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:53:46 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:54:46 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:55:31 GMT+0000 (UTC)] NOTICE Starting application on port 17293

[Fri Apr 05 2013 20:55:31 GMT+0000 (UTC)] INFO STATUS running -> starting

[Fri Apr 05 2013 20:55:31 GMT+0000 (UTC)] ERROR Application crashed with code: 1

[Fri Apr 05 2013 20:55:33 GMT+0000 (UTC)] INFO Failed to receive keepalive! Exiting.

[Fri Apr 05 2013 20:55:34 GMT+0000 (UTC)] INFO STATUS starting -> running

[Fri Apr 05 2013 20:55:42 GMT+0000 (UTC)] ERROR Application crashed with code: 1

[Fri Apr 05 2013 20:55:42 GMT+0000 (UTC)] NOTICE Starting application on port 17293

[Fri Apr 05 2013 20:55:42 GMT+0000 (UTC)] INFO STATUS running -> starting

[Fri Apr 05 2013 20:55:43 GMT+0000 (UTC)] WARNING

/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:524

        throw err;

              ^

MongoError: auth fails

    at Object.exports.toError (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/utils.js:108:11)

    at Db.authenticate (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:670:31)

    at Db._executeQueryCommand (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:1702:5)

    at g (events.js:192:14)

    at EventEmitter.emit (events.js:126:20)

    at Server.Base._callHandler (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/base.js:130:25)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:517:20)

    at MongoReply.parseBody (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:127:5)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:476:22)

    at EventEmitter.emit (events.js:96:17)

[Fri Apr 05 2013 20:55:44 GMT+0000 (UTC)] INFO STATUS starting -> running

[Fri Apr 05 2013 20:55:45 GMT+0000 (UTC)] WARNING /meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:524

[Fri Apr 05 2013 20:55:45 GMT+0000 (UTC)] WARNING         throw err;

              ^

[Fri Apr 05 2013 20:55:45 GMT+0000 (UTC)] WARNING MongoError: auth fails

    at Object.exports.toError (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/utils.js:108:11)

    at Db.authenticate (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:670:31)

    at Db._executeQueryCommand (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:1702:5)

    at g (events.js:192:14)

    at EventEmitter.emit (events.js:126:20)

    at Server.Base._callHandler (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/base.js:130:25)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:517:20)

    at MongoReply.parseBody (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:127:5)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:476:22)

    at EventEmitter.emit (events.js:96:17)

[Fri Apr 05 2013 20:55:45 GMT+0000 (UTC)] INFO STATUS running -> waiting

[Fri Apr 05 2013 20:55:45 GMT+0000 (UTC)] ERROR Application crashed with code: 1

[Fri Apr 05 2013 20:55:47 GMT+0000 (UTC)] INFO HIT / 46.165.195.139

[Fri Apr 05 2013 20:55:56 GMT+0000 (UTC)] NOTICE Starting application on port 17293

[Fri Apr 05 2013 20:55:56 GMT+0000 (UTC)] INFO STATUS waiting -> starting

[Fri Apr 05 2013 20:55:56 GMT+0000 (UTC)] INFO STATUS starting -> running

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] WARNING /meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:524

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] WARNING         throw err;

              ^

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] WARNING MongoError: auth fails

    at Object.exports.toError (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/utils.js:108:11)

    at Db.authenticate (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:670:31)

    at Db._executeQueryCommand (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:1702:5)

    at g (events.js:192:14)

    at EventEmitter.emit (events.js:126:20)

    at Server.Base._callHandler (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/base.js:130:25)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:517:20)

    at MongoReply.parseBody (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:127:5)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:476:22)

    at EventEmitter.emit (events.js:96:17)

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] ERROR Application crashed with code: 1

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] INFO STATUS running -> waiting

[Fri Apr 05 2013 20:55:57 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:55:58 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:55:58 GMT+0000 (UTC)] INFO HIT / xxx.xx.xxx.xxx

[Fri Apr 05 2013 20:56:26 GMT+0000 (UTC)] NOTICE Starting application on port 17293

[Fri Apr 05 2013 20:56:26 GMT+0000 (UTC)] INFO STATUS waiting -> starting

[Fri Apr 05 2013 20:56:26 GMT+0000 (UTC)] INFO STATUS starting -> running

[Fri Apr 05 2013 20:56:27 GMT+0000 (UTC)] WARNING         throw err;

              ^

[Fri Apr 05 2013 20:56:27 GMT+0000 (UTC)] WARNING /meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:524

[Fri Apr 05 2013 20:56:27 GMT+0000 (UTC)] WARNING MongoError: auth fails

    at Object.exports.toError (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/utils.js:108:11)

    at Db.authenticate (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:670:31)

    at Db._executeQueryCommand (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:1702:5)

    at g (events.js:192:14)

    at EventEmitter.emit (events.js:126:20)

    at Server.Base._callHandler (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/base.js:130:25)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:517:20)

    at MongoReply.parseBody (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:127:5)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/4055c87e-893c-bb0a-989c-3c81735d0abd/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:476:22)

    at EventEmitter.emit (events.js:96:17)

[Fri Apr 05 2013 20:56:27 GMT+0000 (UTC)] ERROR Application crashed with code: 1

Etc... it continues like this until I delete and deploy again.

[Nick Martin]

Hi Rob,

I've actually been working on tracking down what I hope is this issue for the last couple days. Working with our mongo provider, I think we've got a fix which I'm going to be deploying today. We think it is an odd quirk in the node mongodb driver (https://groups.google.com/forum/#!msg/node-mongodb-native/vBueswt5BII/7G3vGdZKDDEJ) and mongo replica sets. Though the exact error message you've got is slightly different than what I've been seeing (Error: No replica set primary available for query with ReadPreference PRIMARY), I think they might be the same issue.

If you continue to see this happen over the next few days, please let me know!

-- Nick

--
You received this message because you are subscribed to the Google Groups "meteor-talk" group.
To unsubscribe from this group and stop receiving emails from it, send an email to meteor-talk...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Ken Yee]

On Friday, April 5, 2013 7:25:38 PM UTC-4, Rob Marscher wrote:

If my app crashes (for whatever reason) or if I deploy a new version, it seems it can no longer connect to mongo at meteor.m0.mongolayer.com.  The logs give "auth fails" errors.  To fix, I've been doing a mongodump, deleting the deployment,

Are you actually seeing errors continuously or is the log just stopped?
I'm seeing an issue w/ a custom CNAME URL as well and the log just stopped....almost like node.js or mongodb is dead on that cname.

[Rob Marscher]

On Friday, April 5, 2013 8:03:21 PM UTC-4, Ken Yee wrote:

Are you actually seeing errors continuously or is the log just stopped?

I'm seeing an issue w/ a custom CNAME URL as well and the log just stopped....almost like node.js or mongodb is dead on that cname.

I think it keeps going.  I just restored another crash.  I'll check next time -- although fingers crossed that Nick's fix works.  Thanks Nick!!

Also, I should have said mongorestore and not mongoimport in my OP. 

[Kyle Finley]

Hey Nick,

If you need another data point, I started seeing this error today. The site is www.boondockerfarms.com.

The output of the logs:

[Thu Apr 11 2013 18:50:24 GMT+0000 (UTC)] INFO STATUS waiting -> starting

[Thu Apr 11 2013 18:50:24 GMT+0000 (UTC)] NOTICE Starting application on port 17856

[Thu Apr 11 2013 18:50:24 GMT+0000 (UTC)] INFO STATUS starting -> running

[Thu Apr 11 2013 18:50:25 GMT+0000 (UTC)] WARNING         throw err;

              ^

[Thu Apr 11 2013 18:50:25 GMT+0000 (UTC)] WARNING /meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:524

[Thu Apr 11 2013 18:50:25 GMT+0000 (UTC)] WARNING MongoError: auth fails

    at Object.exports.toError (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/utils.js:108:11)

    at Db.authenticate (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:670:31)

    at Db._executeQueryCommand (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/db.js:1702:5)

    at g (events.js:192:14)

    at EventEmitter.emit (events.js:126:20)

    at Server.Base._callHandler (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/base.js:130:25)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:517:20)

    at MongoReply.parseBody (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:127:5)

    at Server.connect.connectionPool.on.server._serverState (/meteor/containers/e528b284-3ba0-5344-ce54-1e98e74977c0/bundle/app/packages/mongo-livedata/node_modules/mongodb/lib/mongodb/connection/server.js:476:22)

    at EventEmitter.emit (events.js:96:17)

[Thu Apr 11 2013 18:50:25 GMT+0000 (UTC)] ERROR Application crashed with code: 1

Prior to deleting the application, I would like to dump the database if possible, but 

> meteor mongo --url www.boondockerfarms.com

yields: Mongo not available for undefined

Does anyone have any ideas on how I might achieve this?

Thank you,

Kyle

[Rob Marscher]

On Thursday, April 11, 2013 3:37:56 PM UTC-4, Kyle Finley wrote:

If you need another data point, I started seeing this error today. The site is www.boondockerfarms.com.

The problem wasn't fixed for me after Nick's update either.  I'm in the process of setting up on Rackspace - which I was going to do anyway as my app is close to going into production.

> meteor mongo --url www.boondockerfarms.com

yields: Mongo not available for undefined

That's interesting.  I didn't experience that.  I was able to get a url and run mongodump successfully.  Good luck! 

 

[Kyle Finley]

Hey Rob, Thank you for your reply.

It looks like they're working on this -- the sites back up (Thank you whomever did that!). The Mongo database is still inaccessible, but now that I have access to the admin, deleting and recreating wouldn't be much of an issue.

[Nick Martin]

Hi Kyle,

Thanks for the report. I'm looking into it. I'm now pretty sure this is separate error than the one I mentioned earlier in the thread. That one turned out to be an issue with I/O load on the primary mongo server, and should be fixed now.

I will see what I can find and let you know.

-- Nick

[Nick Martin]

Hi Kyle,

I got your site back up by manually poking at mongo. Still don't know the root cause, but am continuing to investigate.

-- Nick