Re: 46,000 databases with garbled names

[Sergey Ukolov]

what gui do you use to see data in your mongo? For example we use  RockMongo. For authorisation it requires to provide DB name. If you input wrong DB name - it will be created on server. So... don't you think that someone (hacker) tried automatically access to your data? :)

понедельник, 15 октября 2012 г., 19:02:58 UTC+3 пользователь Max Afonov написал:

Hi All,

I've been confronted with a completely nonsensical issue this morning. On two of our MongoDB replica sets (running mongod 2.0.6) we have found a large number of databases with garbled names. Let me illustrate:

> db.getMongo().getDBNames().length                                                                                                                                                                                                                               

46025

Our application code doesn't create 46,000+ databases. When I looked at the names of these DBs, I found the following:

        "admin���Y�",

        "admin���ZQ",

        "admin���Zy",

        "admin���Zﾐ",

        "admin���Zﾲ",

        "admin���Zﾸ",

        "admin���Zﾹ",

        "admin���Zￃ",

        "admin���[\u0004",

        "admin���[\u0006",

        "admin���[\u001e",

        "admin���[G",

        "admin���[e",

        "admin���[j",

        "admin���[}",

        "admin���[ﾏ",

        "admin���[ﾕ",

        "admin���[ﾝ",

This is just a tiny excerpt. There are many, many of these DBs there. 46,000+ of them!

Has anyone on this list seen anything like this before? Our application is written in Scala and doesn't do anything strange with strings. Furthermore, this seems to have "affected" (for lack of a better term) just the "admin" DB, which our application doesn't access in any way.

The above printouts are coming from the replica set's master. On the slave I found a similar situation. When I ran a db.serverStatus() on the slave, I found the following potentially interesting tidbit:

        "mem" : {

                "bits" : 64,

                "resident" : 5107,

                "virtual" : 100450,

                "supported" : true,

                "mapped" : 47242,

                "mappedWithJournal" : 94484,

                "note" : "virtual minus mapped is large. could indicate a memory leak"

        },

After a restart, the weirdly named DBs have gone and the "mem" section looks like this:

        "mem" : {

                "bits" : 64,

                "resident" : 49,

                "virtual" : 94832,

                "supported" : true,

                "mapped" : 47242,

                "mappedWithJournal" : 94484

        },

Any ideas are greatly appreciated. This caused a panic in our monitoring software. The sysadmins are unhappy, and you all know what this means for me. *shudder*

Cheers,

-max

[Shaun]

Hi Max,

Do you have the logs from right before this happened?

Also, what do these databases actually have in them?  I realize that typing them in the interactive shell may be problematic, so you can use "db.getSiblingDB(db.getMongo().getDBNames()[2]).printCollectionStats()" to print status about the collections in an individual db (the second one in the dbnames array in this case), and "db.getMongo().getDBs()" to print out stats about all of these databases.

On Monday, October 15, 2012 2:26:28 PM UTC-7, Max Afonov wrote:

On Monday, October 15, 2012 4:39:18 PM UTC-4, Sergey Ukolov wrote:

what gui do you use to see data in your mongo? For example we use  RockMongo. For authorisation it requires to provide DB name. If you input wrong DB name - it will be created on server. So... don't you think that someone (hacker) tried automatically access to your data? :)

 

I find this highly unlikely because our environment is strictly firewalled from the outside. It's also extremely difficult for me to believe that someone here would have made 46,000 of these databases, even if it were an honest mistake.

[Max Afonov]

On Tuesday, October 16, 2012 5:44:52 PM UTC-4, Shaun wrote:

Do you have the logs from right before this happened?

Yes! Suddenly one fine day the log file began to get filled with thousands of messages like this one:

 Fri Oct 12 21:31:07 [conn580285] Assertion: 10334:Invalid BSONObj size: -256 (0x00FFFFFF) first element: ^S: MinKey

0x5848a2 0x508f51 0x5df658 0x889079 0x88dcd9 0xaa0bc8 0x6389f7 0x7f7c18473efc 0x7f7c17a0d59d 

 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x112) [0x5848a2]

 /usr/bin/mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x481) [0x508f51]

 /usr/bin/mongod(_ZN5mongo12QueryMessageC1ERNS_9DbMessageE+0x348) [0x5df658]

 /usr/bin/mongod() [0x889079]

 /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x559) [0x88dcd9]

 /usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x78) [0xaa0bc8]

 /usr/bin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x287) [0x6389f7]

 /lib/x86_64-linux-gnu/libpthread.so.0(+0x7efc) [0x7f7c18473efc]

 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f7c17a0d59d]

[Shaun]

Hi Max,

Could you send the log for what happened right before the first of these messages appeared?  That way we can see more context on what it was trying to do when it got this error.

[Max Afonov]

On Wednesday, October 17, 2012 7:42:08 PM UTC-4, Shaun wrote:

Hi Max,

Could you send the log for what happened right before the first of these messages appeared?  That way we can see more context on what it was trying to do when it got this error.

Here's the log roll from just before the badness happened:

 Fri Oct 12 21:25:56 [conn580642] end connection 10.183.66.101:36974

Fri Oct 12 21:25:56 [initandlisten] connection accepted from 10.183.66.101:36983 #580647

Fri Oct 12 21:26:15 [conn580644] end connection 10.180.252.96:50338

Fri Oct 12 21:26:15 [initandlisten] connection accepted from 10.180.252.96:50340 #580648

Fri Oct 12 21:26:26 [conn580645] end connection 10.183.66.101:36983

Fri Oct 12 21:26:26 [initandlisten] connection accepted from 10.183.66.101:36991 #580649

Fri Oct 12 21:26:40 [initandlisten] connection accepted from 10.10.1.197:48338 #580650

Fri Oct 12 21:26:40 [conn580648] end connection 10.10.1.197:48338

Fri Oct 12 21:26:45 [conn580646] end connection 10.180.252.96:50340

Fri Oct 12 21:26:45 [initandlisten] connection accepted from 10.180.252.96:50342 #580651

Fri Oct 12 21:26:56 [conn580647] end connection 10.183.66.101:36991

Fri Oct 12 21:26:56 [initandlisten] connection accepted from 10.183.66.101:36999 #580652

Fri Oct 12 21:27:15 [conn580649] end connection 10.180.252.96:50342

Fri Oct 12 21:27:15 [initandlisten] connection accepted from 10.180.252.96:50344 #580653

Fri Oct 12 21:27:26 [conn580650] end connection 10.183.66.101:36999

Fri Oct 12 21:27:26 [initandlisten] connection accepted from 10.183.66.101:37007 #580654

Fri Oct 12 21:27:37 [initandlisten] connection accepted from 10.10.1.197:53494 #580655

Fri Oct 12 21:27:37 [conn580653] end connection 10.10.1.197:53494

Fri Oct 12 21:27:45 [conn580651] end connection 10.180.252.96:50344

Fri Oct 12 21:27:45 [initandlisten] connection accepted from 10.180.252.96:50348 #580656

Fri Oct 12 21:27:56 [conn580652] end connection 10.183.66.101:37007

Fri Oct 12 21:27:56 [initandlisten] connection accepted from 10.183.66.101:37016 #580657

Fri Oct 12 21:28:15 [conn580654] end connection 10.180.252.96:50348

Fri Oct 12 21:28:15 [initandlisten] connection accepted from 10.180.252.96:50350 #580658

Fri Oct 12 21:28:26 [conn580655] end connection 10.183.66.101:37016

Fri Oct 12 21:28:26 [initandlisten] connection accepted from 10.183.66.101:37025 #580659

Fri Oct 12 21:28:33 [initandlisten] connection accepted from 10.10.1.197:58574 #580660

Fri Oct 12 21:28:33 [conn580658] end connection 10.10.1.197:58574

Fri Oct 12 21:28:42 [clientcursormon] mem (MB) res:5317 virt:96547 mapped:47242

Fri Oct 12 21:28:45 [conn580656] end connection 10.180.252.96:50350

Fri Oct 12 21:28:45 [initandlisten] connection accepted from 10.180.252.96:50352 #580661

Fri Oct 12 21:28:56 [conn580657] end connection 10.183.66.101:37025

Fri Oct 12 21:28:56 [initandlisten] connection accepted from 10.183.66.101:37033 #580662

Fri Oct 12 21:29:15 [conn580659] end connection 10.180.252.96:50352

Fri Oct 12 21:29:15 [initandlisten] connection accepted from 10.180.252.96:50354 #580663

Fri Oct 12 21:29:26 [conn580660] end connection 10.183.66.101:37033

Fri Oct 12 21:29:26 [initandlisten] connection accepted from 10.183.66.101:37043 #580664

Fri Oct 12 21:29:34 [initandlisten] connection accepted from 10.10.1.197:35450 #580665

Fri Oct 12 21:29:34 [conn580663] end connection 10.10.1.197:35450

Fri Oct 12 21:29:45 [conn580661] end connection 10.180.252.96:50354

Fri Oct 12 21:29:45 [initandlisten] connection accepted from 10.180.252.96:50357 #580666

Fri Oct 12 21:29:56 [conn580662] end connection 10.183.66.101:37043

Fri Oct 12 21:29:56 [initandlisten] connection accepted from 10.183.66.101:37052 #580667

Fri Oct 12 21:30:15 [conn580664] end connection 10.180.252.96:50357

Fri Oct 12 21:30:15 [initandlisten] connection accepted from 10.180.252.96:50359 #580668

Fri Oct 12 21:30:26 [conn580665] end connection 10.183.66.101:37052

Fri Oct 12 21:30:26 [initandlisten] connection accepted from 10.183.66.101:37060 #580669

Fri Oct 12 21:30:38 [initandlisten] connection accepted from 10.10.1.197:40692 #580670

Fri Oct 12 21:30:38 [conn580668] end connection 10.10.1.197:40692

Fri Oct 12 21:30:45 [conn580666] end connection 10.180.252.96:50359

Fri Oct 12 21:30:45 [initandlisten] connection accepted from 10.180.252.96:50362 #580671

Fri Oct 12 21:30:56 [conn580667] end connection 10.183.66.101:37060

Fri Oct 12 21:30:56 [initandlisten] connection accepted from 10.183.66.101:37068 #580672

There are pages and pages of this above, going back a few hours. Apart from that, only a few "slow" queries were logged.

[Dwight Merriman]

this might just be symptomatic of something going wrong earlier in the run as QueryMessage is usely involved in read-only operations.

aside : since this has been occurring, I recommend you run mongod with --objcheck in the future.

if you can get something that reproduces happy to dive on it and analyze.

[Max Afonov]

On Monday, October 22, 2012 1:03:37 PM UTC-4, Dwight Merriman wrote:

this might just be symptomatic of something going wrong earlier in the run as QueryMessage is usely involved in read-only operations.

aside : since this has been occurring, I recommend you run mongod with --objcheck in the future.

if you can get something that reproduces happy to dive on it and analyze.

Could this have been caused by JAVA-660? We've narrowed the source of badness down to our pre-release verification environment, which at the moment runs a much newer version of mongo-java-driver than our main production deployment. The bug states that mongod behavior is "undefined". I suppose that 46,000+ DBs with garbled names may be included in "undefined" :)

[Shaun]

Hi Max,

You are right, JAVA-660 may be the cause.  2.9.2 has just been released https://github.com/mongodb/mongo-java-driver/wiki/Release-Notes and the release notes there say that the bug caused "corrupted messages to be sent to the server".  That sounds like it could cause a wide variety of issues (including yours).

Let me know if you still have this problem after the upgrade.

Thanks!
~Shaun