[SERVER-9810] Assertion in mongos when running a command via a query on $cmd collection with incorrect limit when auth is enabled Created: 29/May/13  Updated: 10/Dec/14  Resolved: 03/Jun/13

Status: Closed
Project: Core Server
Component/s: Security
Affects Version/s: 2.4.3
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Travis Reeder Assignee: Spencer Brody (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 12.04


Issue Links:
Depends
depends on SERVER-9811 Better error for query on the $cmd na... Closed
Related
Operating System: ALL
Steps To Reproduce:

Happens when we apply high load, ~1000 concurrent processes.

Participants:

 Description   

This is a sharded setup, 5 shards with 3 servers per replica set.

Here's the mongo log:

Wed May 29 21:51:23.305 [conn1730] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:23.308 [conn1730] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701
Wed May 29 21:51:23.355 [Balancer] distributed lock 'balancer/ip-10-38-42-134:27020:1369817037:1804289383' acquired, ts : 51a6785b082e244713019a57
Wed May 29 21:51:23.528 [Balancer] distributed lock 'balancer/ip-10-38-42-134:27020:1369817037:1804289383' unlocked.
Wed May 29 21:51:26.346 [conn1732] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:26.349 [conn1732] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701
Wed May 29 21:51:27.114 [conn1831] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:27.117 [conn1831] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701
Wed May 29 21:51:27.551 [conn1831] authenticate db: db1

{ authenticate: 1, nonce: "5f2f6b45a26b8361", user: "xxx", key: "eeaa0850c0e0e62e4eca0d47230174e3" }

Wed May 29 21:51:27.556 [conn1831] authenticate db: db2

{ authenticate: 1, nonce: "2b340d06a947255", user: "xxx", key: "051e461b5d22c07afb5105a654c72ad9" }

Wed May 29 21:51:27.562 [conn1831] authenticate db: staging_messages_archive_old

{ authenticate: 1, nonce: "dca4f633bb029cac", user: "xxx", key: "c2089a81332e38ff51e3ffb565026b54" }

Wed May 29 21:51:28.497 [conn1776] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:28.500 [conn1776] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701
Wed May 29 21:51:28.501 [conn1810] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:28.504 [conn1810] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701
Wed May 29 21:51:28.529 [conn1988] Assertion failure !namespaceString.isCommand() src/mongo/db/auth/authorization_manager.cpp 701
0xa7e461 0xa42bed 0x744499 0x9b9ec7 0x98e781 0x66b7d1 0xa6ac7e 0x7f8880c16e9a 0x7f887ff29ccd
/usr/bin/mongos(_ZN5mongo15printStackTraceERSo+0x21) [0xa7e461]
/usr/bin/mongos(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xa42bed]
/usr/bin/mongos(_ZN5mongo20AuthorizationManager17checkAuthForQueryERKSs+0x279) [0x744499]
/usr/bin/mongos(_ZN5mongo13ShardStrategy7queryOpERNS_7RequestE+0x247) [0x9b9ec7]
/usr/bin/mongos(_ZN5mongo7Request7processEi+0x1d1) [0x98e781]
/usr/bin/mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x71) [0x66b7d1]
/usr/bin/mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xa6ac7e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8880c16e9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f887ff29ccd]
Wed May 29 21:51:28.532 [conn1988] AssertionException while processing op type : 2004 to : admin.$cmd :: caused by :: 0 assertion src/mongo/db/auth/authorization_manager.cpp:701

After this happens, it pretty much takes down the whole system for a while. Here's what gets returned to client.

May 29 15:18:03 23.20.172.143 ironmq_staging: 2013/05/29 22:18:03 ERROR – internal server error not authorized for insert on staging_ironmq_handles.handles



 Comments   
Comment by Spencer Brody (Inactive) [ 03/Jun/13 ]

Per Gustavo's recommendation I am closing out this ticket. The problem with mgo's background ping task setting the wrong limit has been fixed, and we have verified that using mgo's Run helper to run commands should do the right thing.

If there turns out to be an additional problem beyond what was addressed here, please open a new ticket and link it to this one.

Comment by Gustavo Niemeyer [ 03/Jun/13 ]

As Evan Shaw reported Friday night, the ping command was being sent without an explicit limit (IOW, limit=0). This was fixed and pushed right then. This justifies the warnings in mongos, but it's really inoffensive otherwise. Even the logic relying on the pings actually works fine.

This does not explain why mongos would report an error afterwards, though. Evan Shaw seemed unsure about whether things were actually related or it just happened as a coincidence.

I suggesting closing this bug as fixed and opening another one if there's a different issue than the one found.

Comment by Spencer Brody (Inactive) [ 29/May/13 ]

In that case, you should check your code and make sure that every time you run a command you set a limit of 1 on the query. Alternately you could try using mgo's command helper: Run.

Comment by Travis Reeder [ 29/May/13 ]

And not using a runCommand helper, just the normal driver functions.

Comment by Travis Reeder [ 29/May/13 ]

We're using the golang mgo driver.

Comment by Spencer Brody (Inactive) [ 29/May/13 ]

Hi Travis,
We have reproduced the problem. The issue is that running commands is done by issuing a query against the "$cmd" collection in a database. That query is expected to have a limit of 1, this error can occur if a query on <dbname>.$cmd is received that has no limit set or a limit other than 1 or -1.
Can you please let us know which driver you are using and how you run commands? Are you using a "runCommand" helper or something similar in the driver, or are you issuing queries against the $cmd namespace directly?

Generated at Thu Feb 08 03:21:30 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.