[SERVER-12359] Compacting blocks "admin" db authentication Created: 14/Jan/14  Updated: 09/Jul/16  Resolved: 15/Jan/14

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

Type: Bug Priority: Major - P3
Reporter: Kay Agahd Assignee: Matt Dannenberg
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File exectuables.tar.gz    
Issue Links:
Related
related to SERVER-10000 Can't connect to mongod when another ... Closed
related to SERVER-12264 replicaset nodes appear to be down du... Closed
Participants:

 Description   

In mongo docs is written that "In MongoDB 2.2, compact blocks activities only for its database." and "You may view the intermediate progress (...) by running the db.currentOp() in another shell instance."
http://docs.mongodb.org/manual/reference/command/compact/

That's not true when authentication is enabled because you can't authenticate against the admin database and you can't run db.currentOp() without being authenticated.

$ mongo s230:27017
MongoDB shell version: 2.4.8
connecting to: s230:27017/test
> db.currentOp()
{ "ok" : 0, "errmsg" : "unauthorized" }
> use admin
switched to db admin
> db.auth("admin", "xxxxx")//this blocks while compact is running!

This is quite annoying because we can't check the server status while compact is running.
Btw. MMS shows the server also (wrongly) as DOWN while compact is running!



 Comments   
Comment by Kay Agahd [ 22/May/14 ]

Thank you Eric for your suggestions which will be useful for our next maintenance activities. Thanks also for making the drivers more intelligent in the future. Looking forward to use them asap.

Comment by Eric Milkie [ 22/May/14 ]

We're working on making the drivers more intelligent about handling maintenance mode so that after one query error, further queries would not go to that node until it became SECONDARY again. For the current version of MongoDB, it might work better for you to remove nodes from the cluster (but not the config) before running compact on them; the drivers currently handle this situation better and will not direct queries to the node while it's running compact. Be sure to switch the listening port when restarting a node in stand-alone mode while running compact if you choose to do this.
Also in 2.6, the default sizing algorithm for new records is quantized, which for many workloads reduces the fragmentation rate over time (although it may result in more space consumed overall). With 2.6, you may notice that the necessary frequency to run compact is reduced.

Comment by Kay Agahd [ 22/May/14 ]

Eric, thank you for the detailed explantions. Also, the error message "not master or secondary; cannot currently read from this replSet member" is clear, at least in the shell where the status of the node is shown by "offerstorePL:OTHER>".
A finer grained level is indeed required, which I thought were already done by replacing the former instance wide write lock by the finer grained database wide write lock. Apparently my assumption is wrong for maintenance activities i.e. compact.

Our databases are very write heavy. For performance reasons we try to hold all data in RAM. As mongodb is fragmenting data more and more during time, we need to compact regularly. If we don't compact mongodb will notably slow down.
Also, in order to spread and spead up reads, our applications read preferably from secondaries. However, they will receive an error when the node is being compacted, even if they query a different database than the one being compacted.

Can you suggest us a workaround for this problem?
Thanks!

Comment by Eric Milkie [ 22/May/14 ]

I see now; I was confused when you said "exactly the same blocking behavior". To me, the behavior is quite different (although still problematic for you). Let me see if I can help diagnose this new error message you are receiving.

I believe the behavior you are experiencing is documented here: http://docs.mongodb.org/manual/reference/command/replSetMaintenance/
When the compact command runs on a secondary, it activates maintenance mode, which transitions the state from SECONDARY to RECOVERING while the compact is running. Slave-ok reads are only permitted to a node in SECONDARY state. This behavior was introduced in MongoDB 2.0 SERVER-3427. The reason this was added was to prevent client drivers from sending read requests to a node that will simply hang until the compact is complete (since compact holds a write lock for its entirety). SERVER-7826 is a request to make this functionality finer-grained, which may be what you are looking for here; this work will require changes to all MongoDB drivers since they would need to analyze a query's database target to determine whether to send it to a compacting node or not.

Comment by Kay Agahd [ 22/May/14 ]

Eric, thank you for your quick reply. I did not say that my attempt to authenticate is blocked. I'm aware that you have fixed this issue by caching the auth tokens. However, we are still unable to access database A while database B is being compacted.

If I executed what I've run a few months ago to reproduce the error:

mongo s230:27017/foo -uu -pp  --eval 'rs.slaveOk();db.offer.find({_id:1})' > id1_s230.txt

then I see the following in file id1_s230.txt:

MongoDB shell version: 2.6.1
connecting to: s230:27017/foo
2014-05-22T14:52:38.780+0200 error: {
	"$err" : "not master or secondary; cannot currently read from this replSet member",
	"code" : 13436
} at src/mongo/shell/query.js:131

This corresponds to the output in the shell which I have posted some minutes ago.

So for me the problem is still present, since we can't access any other database from a node where a collection is being compacted.
Thanks for looking into this!

Comment by Eric Milkie [ 22/May/14 ]

Kay, we did test it four months ago and asked you to confirm. I apologize but I don't see how your latest output illustrates that your attempt to authenticate is blocked by a compact running on another database; can you elaborate? It looks like nothing blocks (but you do receive an error). This could be an unrelated issue.

Comment by Kay Agahd [ 22/May/14 ]

Did you ever test the "bugfix"? It still does NOT work!
I've tested it with v2.6.1 (linux 64 bit) and can reproduce exactly the same blocking behaviour.
While MongoDB is compacting the collection "offer" on database "offerStore", I can NOT access another db i.e. "foo":

offerstorePL:OTHER> use foo
switched to db foo
offerstorePL:OTHER> rs.slaveOk()
offerstorePL:OTHER> db.offer.find()
error: {
	"$err" : "not master or secondary; cannot currently read from this replSet member",
	"code" : 13436
}
offerstorePL:OTHER> 

When will you fix this bug eventually?

Comment by Githook User [ 21/Jan/14 ]

Author:

{u'username': u'dannenberg', u'name': u'matt dannenberg', u'email': u'matt.dannenberg@10gen.com'}

Message: SERVER-12359 add testing of auth functionality in a replset during a compact
Branch: master
https://github.com/mongodb/mongo/commit/2e18778f1556117f499fe778a3a44987795e8e91

Comment by Matt Dannenberg [ 17/Jan/14 ]

A-ha. Sorry. I did miss that aspect of your repro. Now that I am reproducing it properly I saw (just as you did) that it is a problem in 2.5.4. However at HEAD of master it seems to have been fixed. I believe this commit fixed the issue.

Our nightly builds are only published if the build passes all the tests, so they are not always up to date with the master branch on github. I'm going to attach some more recent executables to this ticket so that you can try your repro again and confirm that the bad behavior has in fact gone away. Please do not use these executables for anything more than testing.

Comment by Kay Agahd [ 17/Jan/14 ]

Matt, thank you for your detailed answer but you got me wrong. I'm aware that a collection (or even the whole db) is blocked during compact. However, my last example shows that I'm unable to access a different db (foo.offer) while compact is running on offerStore.offer! Please see my steps above. Can you reproduce it?
Btw. even if I use your suggested syntax (adapted for my use case to access another db than the one being compacted)

mongo s230:27017/foo -uu -pp  --eval 'rs.slaveOk();db.offer.find({_id:1})' > id1_s230.txt

the command blocks until compact has finished.

Comment by Matt Dannenberg [ 16/Jan/14 ]

It is true (and expected) that you are unable do a find on a collection that is undergoing a compact(). Does the original repro you posted (the one that uses db.currentOp() instead of a find) give you trouble on 2.5.4 or the nightly you downloaded? I'm able to get responses to auth commands and currentOp() from a node undergoing compact in both the nightly and 2.5.4.

Another potential source of problems is that you are echoing into the mongo shell instead of using the --eval flag. The difference between the two is that with --eval the shell doesn't do any of the replicaset tracking or state initialization that it does when it is run normally. The interactive shell runs commands to print the prompt and calls getLastError() and other commands behind the scenes, which may be what you as blocking. For more on the differences, take a look at the Differences Between Interactive and Scripted Mongo page in the manual. Try running

mongo s230:27017/admin -uu -pp  --eval 'db.currentOp()' > currentOp_s230.txt

rather than

echo "db.currentOp()" | mongo s230:27017/admin -uu -pp > currentOp_s230.txt

Comment by Kay Agahd [ 16/Jan/14 ]

Please see the corresponding logs where you can see that the compact command on db offer was started at 12:13:51.
Even though find on db foo was executed immediately in another shell, it run only 5 seconds later at 12:13:56, only when the compact had finished.

At 12:16:00 the number of offer has been doubled. The compact command was started at 12:16:36. Mongo executed the find on db foo only 22 seconds later at 12:16:58.

http://pastebin.com/raw.php?i=YtNZtPAz

Comment by Kay Agahd [ 16/Jan/14 ]

Btw. I tested v2.5.4 and 2.5 Nightly (mongodb-linux-x86_64-adb2c9c330f67e24adbb5f1a306f8484befe93a9-2014-01-13), both with same results as 2.4.6 and 2.4.7.

I also doubled the number of documents in offer db to increment its compact time. No surprise, the delay time to execute db.offer.find({_id:1}) on db foo doubled too. It executed only when compacting offer db has finished.

Comment by Kay Agahd [ 16/Jan/14 ]

Matt, I've tested again with v2.5.4 (this wil become v2.6, right?) to access another DB while compact is running (not admin-db since credentials are cached). It does not work!
Steps to reproduce:

  • connect to master and insert stuff on another db:

    mongo s209:27017/admin -uu -pp 
    use foo
    db.addUser("u", "p")
    for(x=0;x<1000000;x++){db.offer.insert({_id:x,value:"ca. 1 kb of dummy data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data "})}

  • connect to secondary:

    mongo s230:27017/admin -uu -pp 
    use offerStore
    db.runCommand({compact:"offer"})

  • immediately switch to another shell and try to select from foo db:

    echo "rs.slaveOk();db.offer.find({_id:1})" | mongo s230:27017/foo -uu -pp > id1_s230.txt
    //THIS WILL BLOCK UNTIL COMPACT HAS FINISHED

  • look at the content of id1_s230.txt and you'll see that it could NOT select from db foo while compact was running on db offer because the node is still RECOVERING even though the execution of the select command on foo db was delayed as long as compact was running on offer db :

    MongoDB shell version: 2.5.4
    connecting to: s230:27017/foo
    error: {
            "$err" : "not master or secondary; cannot currently read from this replSet member",
            "code" : 13436
    }
    bye

So, please reopen and fix this issue.

Comment by Matt Dannenberg [ 15/Jan/14 ]

I ran your repro against 2.4.9 to make sure I was doing it correctly and I saw the same problem you did. Then, I ran it against the HEAD of the master branch on github and the problem was no longer present. We are doing some major reworking of the authentication system between 2.4 and 2.6 and I believe this was fixed by some of that work.

Comment by Kay Agahd [ 15/Jan/14 ]

Matt, even if credentials are cached in v2.6, this won't solve the issue because one still can't access other databases while the compact command is running!

Comment by Matt Dannenberg [ 15/Jan/14 ]

This behavior has been corrected in current master and will be in the 2.6 release.

Comment by Kay Agahd [ 15/Jan/14 ]

I used vvvvv to have more verbose logs which wanted to add here but I'm unable to attach it here so I've uploaded them here:
http://pastebin.com/0dM4kiFR

Comment by Kay Agahd [ 15/Jan/14 ]

Here are the steps I executed to reproduce:

  • set up a replicaset with two members using this config:

    # !!! generated by puppet !!!
    # mongod.conf
     
    dbpath=/data/mongod/db
     
    pidfilepath=/data/mongod/mongod.pid
     
    logpath=/data/mongod/log/mongod.log
     
    logappend=true
     
    rest=true
     
    fork=false
     
    shardsvr=true
     
    configsvr=false
     
    port=27017
     
    replSet=offerstoreES
     
    keyFile=/data/keyfile.txt
     
    nojournal=true
     
    directoryperdb=true
     
    vvvvv=true

    mongo s209:27017 
    rs.initiate()
    use admin
    db.addUser("u", "p")
    exit

    mongo s209:27017/admin -uu -pp 
    use offerStore
    db.addUser("u", "p")
    for(x=0;x<1000000;x++){db.offer.insert({_id:x,value:"ca. 1 kb of dummy data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data data "})}
    rs.add("s230:27017")

  • wait until s230 is ready (STARTUP2 > SECONDARY)

    mongo s230:27017/admin -uu -pp 
    use offerStore
    db.runCommand({compact:"offer"})

  • immediately switch to another shell and try to connect to admin db:

    echo "db.currentOp()" | mongo s230:27017/admin -uu -pp > currentOp_s230.txt
    //THIS WILL BLOCK UNTIL COMPACT HAS FINISHED

  • look at the content of currentOp_s230.txt and you'll see that it was executed only when compact has finished already:

    MongoDB shell version: 2.4.6
    connecting to: s230:27017/admin
    { "inprog" : [ ] }
    bye        

Comment by Scott Hernandez (Inactive) [ 15/Jan/14 ]

Please provide the steps you took so we can try to reproduce this.

Comment by Kay Agahd [ 15/Jan/14 ]

Scott, we did not compact the admin database! The current title "Compacting "admin" db blocks authentication" is just wrong and is not what I've initially written, something like "compact blocks more than it should". Why did you change it?

It does not matter which database is being compacted. Btw. we've NEVER compacted the admin database.

This issue is much more dramatic than you thought because it takes much time to compact our database. During the whole compact time (1-3 hours) we can't access this node. The admin database however is quite small and would be fast to compact, so this wouldn't be a big issue.

Please reopen this issue!

Comment by Scott Hernandez (Inactive) [ 14/Jan/14 ]

We will change the docs to include a note that the local and admin databases are special and should not be compacted like normal databases and if they will effect more than just that database (exclusively).

Comment by Scott Hernandez (Inactive) [ 14/Jan/14 ]

In 2.6 we are going to cache that info so it should be much less likely but basically we need to be able to read the admin db to auth as a design.

Comment by Kay Agahd [ 14/Jan/14 ]

See also: https://jira.mongodb.org/browse/SERVER-10000

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