bug in readonly account authentication

[aharbick]

We have some readonly accounts that are used for adhoc reporting,
etc. At one point today they stopped working on the primary in the
replica set and have ceased to work since then. The following shell
output shows:

1. adding a new readonly user and failing to login as that user.
2. adding a new read/write user and SUCCEEDING to login as that
user.
3. changing an existing readonly user (for whom login was failing)
to read/write and SUCCEEDING.
4. changing the same existing user back to readonly and failing.
5. successful login to an existing readonly account that was
hitting a different database.
6. all of the mongo.log output from the above
7. NOT SHOWN... these same accounts can login to the secondaries
as readonly just fine.

All that adds up to me as weird mojo... Any idea what's wrong and how
I can recover my readonly account access?

Thanks,
Andy

--------------------------------------------------

*** #1 ADDING A NEW READONLY USER WHO CAN'T LOGIN
PRIMARY> db.addUser('test','test123',true);
{
"n" : 0,
"lastOp" : NumberLong("5676496058503397382"),
"connectionId" : 5390,
"err" : null,
"ok" : 1
}
{
"user" : "test",
"readOnly" : true,
"pwd" : "2ee6cd2e57f3a5829ed694d5c367bc48",
"_id" : ObjectId("4ec6f717a159a39a15c992b7")
}
PRIMARY>
bye
[root@prodmongoperf-c logs]# mongo locos_production -u test -p test123
MongoDB shell version: 2.0.1
connecting to: locos_production
Fri Nov 18 19:24:03 DBClientCursor::init call() failed
Fri Nov 18 19:24:03 query failed : locos_production.$cmd
{ authenticate: 1.0, user: "test", nonce: "26f307022dbd6824", key:
"ceaa054814233e1d8bd32b8433ffa694" } to: 127.0.0.1
Fri Nov 18 19:24:03 Error: error doing query: failed shell/
collection.js:150
exception: login failed

*** #2 ADDING A NEW READ/WRITE USER WHO CAN LOGIN

[root@prodmongoperf-c logs]# mongo admin -u root -p
MongoDB shell version: 2.0.1
Enter password:
connecting to: admin
PRIMARY> use locos_production
switched to db locos_production
PRIMARY> db.addUser('test2','test123');
{
"n" : 0,
"lastOp" : NumberLong("5676496204532285446"),
"connectionId" : 5393,
"err" : null,
"ok" : 1
}
{
"user" : "test2",
"readOnly" : false,
"pwd" : "4bbbf44912cad7f221ef4c1a2a571cf1",
"_id" : ObjectId("4ec6f739140e86a432704270")
}
PRIMARY>
bye

*** #3 CHANGING AN EXISTING USER TO READ/WRITE CAN NOW LOGIN

[root@prodmongoperf-c logs]# mongo locos_production -u test2 -p
test123
MongoDB shell version: 2.0.1
connecting to: locos_production
>

> show users;

{
"_id" : ObjectId("4ebc334b6089275164988f7c"),
"user" : "aharbick",
"readOnly" : true,
"pwd" : "eba45d046343b9486adaf2844bd32d29"
}

> db.addUser('aharbick','password');
{
"updatedExisting" : true,
"n" : 1,
"lastOp" : NumberLong("5676497329813717010"),
"connectionId" : 5394,
"err" : null,
"ok" : 1
}
{
"_id" : ObjectId("4ebc334b6089275164988f7c"),
"user" : "aharbick",
"readOnly" : false,
"pwd" : "eba45d046343b9486adaf2844bd32d29"
}
>
[root@prodmongoperf-c logs]# mongo locos_production -u aharbick -p
password
MongoDB shell version: 2.0.1
connecting to: locos_production
>
bye

*** #4 CHANGING THE EXISTING USER BACK TO READONLY FAILS

PRIMARY> db.addUser('aharbick','DrWham',true);
{
"updatedExisting" : true,
"n" : 1,
"lastOp" : NumberLong("5676497510202343425"),
"connectionId" : 5397,
"err" : null,
"ok" : 1
}
{
"_id" : ObjectId("4ebc334b6089275164988f7c"),
"user" : "aharbick",
"readOnly" : true,
"pwd" : "eba45d046343b9486adaf2844bd32d29"
}
PRIMARY>
bye

[root@prodmongoperf-c logs]# mongo locos_production -u aharbick -p
password
MongoDB shell version: 2.0.1
connecting to: locos_production
Fri Nov 18 19:29:31 DBClientCursor::init call() failed
Fri Nov 18 19:29:31 query failed : locos_production.$cmd
{ authenticate: 1.0, user: "aharbick", nonce: "b7c38f240e36d103", key:
"dfe86507734d301fa1da0aebb2f72925" } to: 127.0.0.1
Fri Nov 18 19:29:31 Error: error doing query: failed shell/
collection.js:150
exception: login failed

*** #5 USER IN THE ADMIN DATABASE CAN LOGIN EVEN THOUGH IT'S READONLY

connecting to: admin
PRIMARY> show users;
...
{
"_id" : ObjectId("4e935e22f2c2603dfaaa1536"),
"user" : "nagios",
"readOnly" : true,
"pwd" : "b44a2bd3673a0b2ec5a1278724fe53ff"
}

Fri Nov 18 19:31:21 [conn5401] authenticate: { authenticate: 1,
nonce: "e290720bbaa4b97c", user: "nagios", key:
"fd59e40ed81c6c3be1548f77960328db" }
Fri Nov 18 19:31:21 [conn5401] end connection 127.0.0.1:53135

*** #6 ALL OF THE LOG ACTIVITY DURING THE ABOVE

Fri Nov 18 19:20:55 [conn5388] authenticate: { authenticate: 1.0,
user: "aharbick", nonce: "17d0f4e8ccb70a89", key:
"1ac661876fa3d2b83aa24dc5940539d1" }
Fri Nov 18 19:20:55 [conn5388] AssertionException handling request,
closing client connection: 10057 unauthorized db:locos_production lock
type:1 client:127.0.0.1
Fri Nov 18 19:20:59 [conn71] profile: warning ns local.system.profile
does not exist
Fri Nov 18 19:21:01 [initandlisten] connection accepted from
127.0.0.1:55774 #5389
Fri Nov 18 19:21:01 [conn5389] authenticate: { authenticate: 1.0,
user: "aharbick", nonce: "3c92ab0051801043", key:
"a5d034839f8f4fad2b722212d8f150e8" }
Fri Nov 18 19:21:01 [conn5389] AssertionException handling request,
closing client connection: 10057 unauthorized db:locos_production lock
type:1 client:127.0.0.1

Fri Nov 18 19:29:02 [conn5395] authenticate: { authenticate: 1.0,
user: "aharbick", nonce: "570133c13447e00d", key:
"d35900b884b24cc7d81130fea138b92c" }
Fri Nov 18 19:29:09 [conn5395] end connection 127.0.0.1:53061
Fri Nov 18 19:29:13 [initandlisten] connection accepted from
127.0.0.1:53068 #5396
Fri Nov 18 19:29:13 [conn5396] end connection 127.0.0.1:53068
Fri Nov 18 19:29:19 [initandlisten] connection accepted from
127.0.0.1:53072 #5397
Fri Nov 18 19:29:19 [conn5397] authenticate: { authenticate: 1.0,
user: "root", nonce: "cd01899f518db087", key:
"4cd065898cb115eba625b9ef3b2b9b28" }
Fri Nov 18 19:29:29 [conn5397] end connection 127.0.0.1:53072
Fri Nov 18 19:29:31 [initandlisten] connection accepted from
127.0.0.1:53079 #5398
Fri Nov 18 19:29:31 [conn5398] authenticate: { authenticate: 1.0,
user: "aharbick", nonce: "b7c38f240e36d103", key:
"dfe86507734d301fa1da0aebb2f72925" }
Fri Nov 18 19:29:31 [conn5398] AssertionException handling request,
closing client connection: 10057 unauthorized db:locos_production lock
type:1 client:127.0.0.1
Fri Nov 18 19:29:46 [conn71] profile: warning ns local.system.profile
does not exist
Fri Nov 18 19:29:59 [conn1395] profile: warning ns
local.system.profile does not exist
Fri Nov 18 19:30:05 [initandlisten] connection accepted from
10.130.197.139:35192 #5399
Fri Nov 18 19:30:05 [initandlisten] connection accepted from
10.130.197.139:35194 #5400
Fri Nov 18 19:30:05 [conn5400] authenticate: { authenticate: 1, user:
"locos", nonce: "da1c30a526ff67fe", key:
"c8824889dc9ce2f469a486e916b3ba22" }
Fri Nov 18 19:30:05 [conn5400] authenticate: { authenticate: 1, user:
"locos", nonce: "7c6f50c5c50edaf8", key:
"a74951ef5494bc6333ee726f1b32b85b" }
Fri Nov 18 19:30:05 [conn5400] authenticate: { authenticate: 1, user:
"locos", nonce: "fda76d5bd77afc7a", key:
"346fc03f5f5cb3e7f762da8e84eae9a1" }
Fri Nov 18 19:30:48 [conn1395] profile: warning ns
local.system.profile does not exist
Fri Nov 18 19:31:21 [initandlisten] connection accepted from
127.0.0.1:53135 #5401
Fri Nov 18 19:31:21 [conn5401] authenticate: { authenticate: 1,
nonce: "e290720bbaa4b97c", user: "nagios", key:
"fd59e40ed81c6c3be1548f77960328db" }
Fri Nov 18 19:31:21 [conn5401] end connection 127.0.0.1:53135

[Richard Kreuter]

What are the versions of your primary and secondaries?

[aharbick]

All servers are 2.0.1

[Richard Kreuter]

So far I've been unable to reproduce this. If you have any idea of
when authentication stopped working on the primary, is there anything
in the log file from around that time?

[aharbick]

We went back into the log and found the last time that authentication
worked and then hunted for the first time it stopped working and there
isn't anything interesting.

What's odd is that the current primary is rejecting readonly
accounts. I suspect if we stepped it down it might start working
again... At a minimum stepping it down and then restarting it I think
it'll start again. The point is that it feels like it's some
ephemeral state (based off gut... I don't know how to prove that).

Andy

[Kristina Chodorow]

That's strange. It looks like authenticate is trying to take a lock
before it has authenticated (which it shouldn't be doing).

Can you try, in one long shell session, doing:

$ mongo admin -u nagios -p
password: // whatever
> use foo
> db.addUser("test", "test123", true)
> db.logout()
> db.auth("test", "test123")

Then paste the log & shell output from the beginning to the end?

Not that it should really matter, but it looks like you have profiling
on... what are your profiler settings?

> > > > > Fri Nov 18 19:30:05...
>
> read more »

[aharbick]

Hi Kristina,

We tried two things:

1. Doing exactly as you prescribed (i.e. creating a new database
"foo", adding a user, logging out, and logging in as the new user)
* It worked within the same shell session
* It worked if we killed the shell session and then tried to login
with --username/--password from a new shell session.

2. Creating a new user in our "troubled" database (i.e. adding a
readonly user to "locos_production", db.logout(), db.auth() as the new
user)
* It WORKED within the same shell session
* If FAILED if you killed the shell session and then tried to
login with a new shell session.

Here's what the session looks like:

SUCCEEDS FROM THE SAME SHELL SESSION
----------------------------------------------------------------------------
> db.addUser('fake', 'fake123', true)
{ "n" : 0, "connectionId" : 125, "err" : null, "ok" : 1 }
{
"user" : "fake",
"readOnly" : true,
"pwd" : "f93b35a2d242db296df476b5e3463d90",
"_id" : ObjectId("4ecbf9af0765ed659efa1487")
}
> db.logout()
{ "ok" : 1 }
> db.auth('fake', 'fake123')
1

FAILS TRY TO CREATE A NEW SHELL SESSION
---------------------------------------------------------------------------
connecting to: locos_production
Tue Nov 22 14:30:51 DBClientCursor::init call() failed
Tue Nov 22 14:30:51 query failed : locos_production.$cmd
{ authenticate: 1.0, user: "fake", nonce: "1f0a4588d4a6cbb0", key:
"0f1291b7bffc852a181aeace7f8ee8d7" } to: 127.0.0.1
Tue Nov 22 14:30:51 Error: error doing query: failed shell/

collection.js:150
exception: login failed

THE OUTPUT IN THE MONGOD LOG
--------------------------------------------------------
Tue Nov 22 14:30:29 [conn6983] authenticate: { authenticate: 1.0,
user: "fake", nonce: "be3c034787c4bf37", key:
"d7c6785c77a8695c4eb195b36bbe5d8f" }
Tue Nov 22 14:30:34 [conn6983] end connection 127.0.0.1:39414
Tue Nov 22 14:30:39 [conn71] profile: warning ns local.system.profile
does not exist
Tue Nov 22 14:30:51 [initandlisten] connection accepted from
127.0.0.1:39444 #6986
Tue Nov 22 14:30:51 [conn6986] authenticate: { authenticate: 1.0,
user: "fake", nonce: "1f0a4588d4a6cbb0", key:
"0f1291b7bffc852a181aeace7f8ee8d7" }
Tue Nov 22 14:30:51 [conn6986] AssertionException handling request,

closing client connection: 10057 unauthorized db:locos_production lock
type:1 client:127.0.0.1

Regarding profiling...
1. We have a setting in our mongo configuration file:
profile=1
2. However the profilingLevel is currently 0 (i.e. we're not
profiling)

Another observation...
1. When you try to auth with an invalid account on the problematic
primary you get disconnected with a message like above "failed shell/
collection.js:150"
2. If however you try to auth with an invalid account on one of our
non-problematic secondaries the connection isn't killed. It looks
like this:

MongoDB shell version: 2.0.1
connecting to: test

> use locos_production
switched to db locos_production

> db.auth('fasdf','asdf')
0

So all of the above is to say that something seems uniquely wrong with
our current primary.

Thanks for your help!

> ...
>
> read more »

[Kristina Chodorow]

Thanks!

There seems to be an issue with how profiling is interacting with
authentication. You can follow this case: https://jira.mongodb.org/browse/SERVER-3454.

> > > > > > >         "ok" : 1}...
>
> read more »