[SERVER-10184] file allocation race when database is dropped immediately Created: 11/Jul/13  Updated: 01/Apr/15  Resolved: 06/Aug/14

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

Type: Bug Priority: Major - P3
Reporter: Greg Studer Assignee: Mathias Stearn
Resolution: Duplicate Votes: 0
Labels: buildbot
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
Related
related to SERVER-10096 dur_passthrough.js failing on Nightly... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:
Linked BF Score: 0

 Description   

Came up in a test case here:

From Matt:
This test error cleared up in #1476, but is now failing at a different point in #1482

Jul 09 08:12 6bc6dc7360b9... failure #1482 Failed test_12
Jul 08 08:09 7c21379b0701... success #1481 Build successful
Jul 07 08:19 bdf9a87b13e3... success #1480 Build successful
Jul 06 07:44 bdf9a87b13e3... success #1479 Build successful
Jul 05 08:16 5f949c19a260... success #1478 Build successful
Jul 04 11:04 5f949c19a260... failure #1477 Failed test_15
Jul 03 16:51 c11ea25c522c... success #1476 Build successful
Jul 03 07:31 2b400fabe2fb... failure #1475 Failed test_12

http://buildbot.mongodb.org/builders/Nightly%20Linux%2064-bit/builds/1482
http://buildbot.mongodb.org/builders/Nightly%20Linux%2064-bit/builds/1482/steps/test_12/logs/stdio
http://buildlogs.mongodb.org/Nightly%20Linux%2064-bit/builds/1482/test/durability/dur_passthrough.js

         Test : jstests/dropdb.js ...
2013-07-09 14:45:19 EDT
 m30200| Tue Jul  9 14:45:17.887 [FileAllocator] allocating new datafile /data/db/dur_passthrough/jstests_dropdb.ns, filling with zeroes...
 m30200| Tue Jul  9 14:45:17.992 [FileAllocator] done allocating datafile /data/db/dur_passthrough/jstests_dropdb.ns, size: 16MB,  took 0.105 secs
 m30200| Tue Jul  9 14:45:17.993 [FileAllocator] allocating new datafile /data/db/dur_passthrough/jstests_dropdb.0, filling with zeroes...
 m30200| Tue Jul  9 14:45:18.085 [FileAllocator] done allocating datafile /data/db/dur_passthrough/jstests_dropdb.0, size: 16MB,  took 0.092 secs
 m30200| Tue Jul  9 14:45:19.404 [FileAllocator] allocating new datafile /data/db/dur_passthrough/jstests_dropdb.1, filling with zeroes...
 m30200| Tue Jul  9 14:45:19.405 [conn1] build index jstests_dropdb.c { _id: 1 }
 m30200| Tue Jul  9 14:45:19.406 [conn1] build index done.  scanned 0 total records. 0 secs
 m30200| Tue Jul  9 14:45:19.406 [conn1] insert jstests_dropdb.c ninserted:1 keyUpdates:0 locks(micros) w:1519173 1518ms
 m30200| Tue Jul  9 14:45:19.409 [conn1] dropDatabase jstests_dropdb starting
 m30200| Tue Jul  9 14:45:19.429 [conn1] removeJournalFiles
 m30200| Tue Jul  9 14:45:19.452 [FileAllocator] done allocating datafile /data/db/dur_passthrough/jstests_dropdb.1, size: 32MB,  took 0.047 secs
 m30200| Tue Jul  9 14:45:19.461 [conn1] dropDatabase jstests_dropdb finished
assert: [-1] != [14] are not equal : undefined
Error: Printing Stack Trace
    at printStackTrace (src/mongo/shell/utils.js:37:15)
    at doassert (src/mongo/shell/assert.js:6:5)
    at Function.assert.eq (src/mongo/shell/assert.js:32:5)
    at jstests/dropdb.js:14:8
    at /mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js:35:68
    at Function.Date.timeFunc (src/mongo/shell/types.js:27:17)
    at /mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js:35:45
    at Array.forEach (native)
    at doTest (/mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js:18:11)
    at /mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js:51:9
Tue Jul  9 14:45:19.466 [-1] != [14] are not equal : undefined at src/mongo/shell/assert.js:7
Tue Jul  9 14:45:19.466 Error: error loading js file: jstests/dropdb.js at /mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js:35
failed to load: /mntfast/data/slave/Linux_64bit_Nightly/mongo/jstests/dur/dur_passthrough.js

Seems like the file allocator is still working on the database after it's dropped?



 Comments   
Comment by auto [ 07/Oct/13 ]

Author:

{u'username': u'RedBeard0531', u'name': u'Mathias Stearn', u'email': u'mathias@10gen.com'}

Message: Extra debugging for jstests/dropdb.js

Failure case: SERVER-10184
Branch: v2.4
https://github.com/mongodb/mongo/commit/caa1f8ec2651b18105bbb4704255d563481a4009

Comment by Matt Kangas [ 07/Oct/13 ]

Hit again on V2.4 Windows 64-bit:

http://buildbot.mongodb.org:8081/builders/V2.4%20Windows%2064-bit/builds/207
http://buildbot.mongodb.org:8081/builders/V2.4%20Windows%2064-bit/builds/207/steps/smokeParallel/logs/stdio

Comment by Daniel Pasette (Inactive) [ 01/Sep/13 ]

Hit again on Linux 64 v2.4: http://buildbot.mongodb.org:8081/builders/V2.4%20Linux%2064-bit/builds/197
Log: http://buildlogs.mongodb.org/V2.4%20Linux%2064-bit/builds/197/test/durability/dur_passthrough.js

Comment by Matt Kangas [ 06/Aug/13 ]

Happened again, this time on V2.4. Sadly your extra debugging info hasn't been backported.

V2.4 Linux RHEL 64-bit Build #154 (Mon Aug 5, rev 3fc69c4aa)

http://buildlogs.mongodb.org/V2.4%20Linux%20RHEL%2064-bit/builds/154/test/parallel/basic.js

assert: [-1] != [12] are not equal : undefined
Error: Printing Stack Trace
    at printStackTrace (src/mongo/shell/utils.js:37:15)
    at doassert (src/mongo/shell/assert.js:6:5)
    at Function.assert.eq (src/mongo/shell/assert.js:32:5)
    at jstests/dropdb.js:14:8
    at <anonymous>:7:61
    at Function.Date.timeFunc (src/mongo/shell/types.js:27:17)
    at <anonymous>:7:38
    at Array.forEach (native)
    at Number.__parallelTests__fun (<anonymous>:4:14)
    at ____MongoToV8_newFunction_temp (<anonymous>:181:65)
Tue Aug  6 08:24:48.077 [-1] != [12] are not equal : undefined at src/mongo/shell/assert.js:7
********** Parallel Test FAILED: Error: error loading js file: jstests/dropdb.js

Comment by auto [ 11/Jul/13 ]

Author:

{u'username': u'RedBeard0531', u'name': u'Mathias Stearn', u'email': u'mathias@10gen.com'}

Message: Extra debugging for jstests/dropdb.js

Failure case: SERVER-10184
Branch: master
https://github.com/mongodb/mongo/commit/06107f8ea8fb7fdf1515420a6b1e2c70b087c955

Comment by Mathias Stearn [ 11/Jul/13 ]

The theory that the file was created after the db was dropped seems incorrect both based on examination of the code and the long lines. The drop waits for the all pending files to be created before deleting, as seen in the order of the following log lines (intermediate lines removed for clarity):

 m30200| Tue Jul  9 14:45:19.404 [FileAllocator] allocating new datafile /data/db/dur_passthrough/jstests_dropdb.1, filling with zeroes...
 m30200| Tue Jul  9 14:45:19.409 [conn1] dropDatabase jstests_dropdb starting
 m30200| Tue Jul  9 14:45:19.452 [FileAllocator] done allocating datafile /data/db/dur_passthrough/jstests_dropdb.1, size: 32MB,  took 0.047 secs
 m30200| Tue Jul  9 14:45:19.461 [conn1] dropDatabase jstests_dropdb finished

I'll add some debugging info to the test to make it easier to debug if it fails again.

Comment by Greg Studer [ 11/Jul/13 ]

Initially seen in this ticket, but unrelated to the top-level issue there.

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