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

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

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major - P3
    • Resolution: Fixed
    • None
    • 3.0.7, 3.1.9
    • Replication, Storage
    • Minor Change
    • ALL
    • 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

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. SERVER-13212 ListDatabases implementation can cause dropped dbs to reappear

          • Major - P3 - Major loss of function.
          • Closed

          Activity

            People

              mathias@mongodb.com Mathias Stearn
              cailin.nelson@mongodb.com Cailin Nelson
              Votes:
              0 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: