Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-20638

Reading the profiling level shouldn't create databases that don't exist

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.0.7, 3.1.9
    • Component/s: Replication, Storage
    • Labels:
    • Backwards Compatibility:
      Minor Change
    • Operating System:
      ALL
    • Backport Completed:
    • Sprint:
      QuInt A (10/12/15)

      Description

      Currently the profile command always creates the database even if it doesn't exist. The plan is to keep that behavior when setting the profiling level, but to return the server-wide default level without creating the database when just reading the profiling level.

      Original Description:

      I am seeing hundreds of instances of failures to drop a database on a secondary in our cloud-dev environment. Here is one example.

      Primary (WT)

      mmsdev:PRIMARY>  db.runCommand({listDatabases:1}).databases.forEach(function (x) {if (x.name == "mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310"){print(x.name)}})
      mmsdev:PRIMARY> 
      

      ubuntu@ip-10-169-132-210:/data/mmsdev_4$ zgrep -i drop mongodb.log*  | grep "mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310"
       
      mongodb.log.2015-09-16T19-01-14.gz:2015-09-16T15:16:29.180+0000 I COMMAND  [conn151320] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 starting
      mongodb.log.2015-09-16T19-01-14.gz:2015-09-16T15:16:29.206+0000 I COMMAND  [conn151320] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 finished
      

      Longer snippet.... note that it is dropped only once (but there are two collections here that have very similar names, dropped back to back).

      2015-09-16T15:16:26.809+0000 I ACCESS   [conn152725] Successfully authenticated as principal __system on local
      2015-09-16T15:16:28.825+0000 I ACCESS   [conn22793] Successfully authenticated as principal mms-monitoring-agent on admin
      2015-09-16T15:16:28.936+0000 I COMMAND  [conn151317] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:33954 locks:{ Global: { acquireCount: { r: 842 } }, Database: { acquireCount: { r:
       421 } } } 191ms
      2015-09-16T15:16:28.981+0000 I COMMAND  [conn151317] dropDatabase mmsdbrrd-raw-PT5S-PT2H-20150916T1310 starting
      2015-09-16T15:16:29.002+0000 I COMMAND  [conn151317] dropDatabase mmsdbrrd-raw-PT5S-PT2H-20150916T1310 finished
      2015-09-16T15:16:29.133+0000 I COMMAND  [conn151320] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:33869 locks:{ Global: { acquireCount: { r: 842 }, acquireWaitCount: { r: 1 }, time
      AcquiringMicros: { r: 22655 } }, Database: { acquireCount: { r: 421 } } } 382ms
      2015-09-16T15:16:29.180+0000 I COMMAND  [conn151320] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 starting
      2015-09-16T15:16:29.206+0000 I COMMAND  [conn151320] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 finished
      2015-09-16T15:16:29.235+0000 I COMMAND  [conn22793] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:33780 locks:{ Global: { acquireCount: { r: 842 }, acquireWaitCount: { r: 2 }, timeAcquiringMicros: { r: 50004 } }, Database: { acquireCount: { r: 421 } } } 389ms
      2015-09-16T15:16:50.383+0000 I NETWORK  [conn152696] end connection 10.169.132.210:50055 (118 connections now open)
      2015-09-16T15:16:50.383+0000 I NETWORK  [conn152697] end connection 10.169.132.210:50056 (118 connections now open)
      2015-09-16T15:16:53.636+0000 I NETWORK  [initandlisten] connection accepted from 10.169.132.210:50106 #152726 (118 connections now open)
      2015-09-16T15:16:53.650+0000 I ACCESS   [conn152726] Successfully authenticated as principal __system on local
      2015-09-16T15:16:56.293+0000 I NETWORK  [conn152724] end connection 10.218.181.240:52421 (117 connections now open)
      

      Secondary (3.0.6 mmapv1)

      mmsdev:SECONDARY> db.runCommand({listDatabases:1}).databases.forEach(function (x) {if (x.name == "mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310"){print(x.name)}})
      mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310
      

      ubuntu@ip-10-218-181-240:/data/mmsdev_1$  zgrep -i drop mongodb.log*  | grep "mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310"
      mongodb.log.2015-09-16T23-18-52.gz:2015-09-16T15:16:29.630+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 starting
      mongodb.log.2015-09-16T23-18-52.gz:2015-09-16T15:16:29.660+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 finished
      

      Longer snippet.... note that it is dropped only once (but there are two collections here that have very similar names, dropped back to back). After the drop, the collection is recreated.

      2015-09-16T15:16:29.219+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-PT5S-PT2H-20150916T1310 starting
      2015-09-16T15:16:29.241+0000 I JOURNAL  [repl writer worker 2] journalCleanup...
      2015-09-16T15:16:29.241+0000 I JOURNAL  [repl writer worker 2] removeJournalFiles
      2015-09-16T15:16:29.249+0000 I JOURNAL  [repl writer worker 2] journalCleanup...
      2015-09-16T15:16:29.249+0000 I JOURNAL  [repl writer worker 2] removeJournalFiles
      2015-09-16T15:16:29.253+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-PT5S-PT2H-20150916T1310 finished
      2015-09-16T15:16:29.440+0000 I INDEX    [repl writer worker 2] allocating new ns file /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1530.ns, filling with zeroes...
      2015-09-16T15:16:29.570+0000 I STORAGE  [FileAllocator] allocating new datafile /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1530.0, filling with zeroes...
      2015-09-16T15:16:29.573+0000 I STORAGE  [FileAllocator] done allocating datafile /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1530.0, size: 64MB,  took 0.002 secs
      2015-09-16T15:16:29.593+0000 I COMMAND  [conn81] command mmsdbrrd-raw-dbs-PT1H-PT1536H-20150828T0000.$cmd command: dbStats { dbstats: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:347 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 141186 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 } }, Metadata: { acquireCount: { R: 1 } } } 154ms
      2015-09-16T15:16:29.630+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 starting
      2015-09-16T15:16:29.653+0000 I JOURNAL  [repl writer worker 2] journalCleanup...
      2015-09-16T15:16:29.653+0000 I JOURNAL  [repl writer worker 2] removeJournalFiles
      2015-09-16T15:16:29.657+0000 I JOURNAL  [repl writer worker 2] journalCleanup...
      2015-09-16T15:16:29.657+0000 I JOURNAL  [repl writer worker 2] removeJournalFiles
      2015-09-16T15:16:29.660+0000 I COMMAND  [repl writer worker 2] dropDatabase mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 finished
      2015-09-16T15:16:29.718+0000 I COMMAND  [conn30216] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:33642 locks:{ Global: { acquireCount: { r: 832 }, acquireWaitCount: { r: 30 }, timeAcquiringMicros: { r: 727351 } }, MMAPV1Journal: { acquireCount: { r: 416 } }, Database: { acquireCount: { r: 416 } } } 846ms
      2015-09-16T15:16:31.094+0000 I INDEX    [conn30216] allocating new ns file /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.ns, filling with zeroes...
      2015-09-16T15:16:31.213+0000 I STORAGE  [FileAllocator] allocating new datafile /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.0, filling with zeroes...
      2015-09-16T15:16:31.219+0000 I STORAGE  [FileAllocator] done allocating datafile /data/mmsdev_1/mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.0, size: 64MB,  took 0.005 secs
      2015-09-16T15:16:31.229+0000 I COMMAND  [conn30216] command mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.$cmd command: profile { profile: -1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:58 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 5 } }, Database: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { W: 1 } } } 137ms
      2015-09-16T15:16:31.322+0000 I COMMAND  [conn81] command mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1420.$cmd command: dbStats { dbstats: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:344 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 112254 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 } }, Metadata: { acquireCount: { R: 1 } } } 113ms
      

      The listDatabases command here is from the monitoring agent, it's a complete coincidence that it arrives in the vicinity of these drops. It is not executed by the Java application code that is dropping databases.

      ubuntu@ip-10-218-181-240:/data/mmsdev_1$ ls -lt | grep mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310 | tail
      -rw------- 1 mongodb mongodb   67108864 Sep 16 15:16 mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.0
      -rw------- 1 mongodb mongodb   16777216 Sep 16 15:16 mmsdbrrd-raw-dbs-PT5S-PT2H-20150916T1310.ns
      

      Full secondary log: https://jira.mongodb.org/secure/attachment/91141/mongodb.log.2015-09-16T23-18-52.txt

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                11 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: