[SERVER-16776] mmapv1 journaling invariant triggered during replicated insert Created: 08/Jan/15  Updated: 19/Sep/15  Resolved: 27/Feb/15

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

Type: Bug Priority: Major - P3
Reporter: Scott Hernandez (Inactive) Assignee: Kaloian Manassiev
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File small-oplog-rs_findAndModify5.log     File smoke.diff    
Issue Links:
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:
Linked BF Score: 0

 Description   

During random testing I found this failure:

2015-01-08T11:32:21.112-0500 I QUERY    [conn10] command test.$cmd command: insert { insert: "foo", documents: [ { _id: ObjectId('54aeb115d6697db04ba2437e'), tid: 0.0, length: 2097152, field: "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx..." } ], ordered: true } keyUpdates:0 writeConflicts:0 numYields:0  reslen:80 102ms
2015-01-08T11:32:21.270-0500 I STORAGE  [FileAllocator] allocating new datafile /data/db/sconsTests/test.8, filling with zeroes...
2015-01-08T11:32:30.078-0500 I NETWORK  [conn19] end connection 127.0.0.1:60348 (4 connections now open)
2015-01-08T11:32:30.078-0500 I NETWORK  [conn17] end connection 127.0.0.1:60349 (1 connection now open)
2015-01-08T11:32:30.079-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60421 #20 (5 connections now open)
2015-01-08T11:32:30.079-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60422 #18 (2 connections now open)
2015-01-08T11:32:56.352-0500 I STORAGE  [FileAllocator] done allocating datafile /data/db/sconsTests/test.8, size: 2047MB,  took 35.082 secs
2015-01-08T11:32:56.355-0500 I STORAGE  [conn10] MmapV1ExtentManager took 35 seconds to open: /data/db/sconsTests/test.8
2015-01-08T11:32:56.761-0500 I STORAGE  [FileAllocator] allocating new datafile /data/db/sconsTestsSlave/test.8, filling with zeroes...
2015-01-08T11:32:57.728-0500 I STORAGE  [FileAllocator] error: failed to allocate new file: /data/db/sconsTestsSlave/test.8 size: 2146435072 Unable to allocate new file of size 2146435072 errno:28 No space left on device.  will try again in 10 seconds
2015-01-08T11:32:57.958-0500 I -        [repl writer worker 15] Assertion: 12520:new file allocation failure
2015-01-08T11:32:58.189-0500 F JOURNAL  [repl writer worker 15] journal warning files are closing outside locks with writes pending
2015-01-08T11:32:58.191-0500 I -        [repl writer worker 15] Invariant failure false src/mongo/db/storage/mmap_v1/dur.cpp 720
2015-01-08T11:32:58.449-0500 I CONTROL  [repl writer worker 15] 
 0x10753064a 0x1074dd87e 0x1074ca954 0x1072f543a 0x10730ca19 0x10731c8bd 0x10731c1d0 0x10731d7e4 0x107323331 0x1073300fe 0x1073228d1 0x1073227f5 0x106ebdfb8 0x106ebdd68 0x10700c272 0x10700ca6b 0x1071afce4 0x1071b03d8 0x1070e221c 0x1072217b5 0x1072802b6 0x107284bd7 0x1074d4079 0x107566e31 0x7fff875d12fc 0x7fff875d1279 0x7fff875cf4b1
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"106DB1000","o":"77F64A"},{"b":"106DB1000","o":"72C87E"},{"b":"106DB1000","o":"719954"},{"b":"106DB1000","o":"54443A"},{"b":"106DB1000","o":"55BA19"},{"b":"106DB1000","o":"56B8BD"},{"b":"106DB1000","o":"56B1D0"},{"b":"106DB1000","o":"56C7E4"},{"b":"106DB1000","o":"572331"},{"b":"106DB1000","o":"57F0FE"},{"b":"106DB1000","o":"5718D1"},{"b":"106DB1000","o":"5717F5"},{"b":"106DB1000","o":"10CFB8"},{"b":"106DB1000","o":"10CD68"},{"b":"106DB1000","o":"25B272"},{"b":"106DB1000","o":"25BA6B"},{"b":"106DB1000","o":"3FECE4"},{"b":"106DB1000","o":"3FF3D8"},{"b":"106DB1000","o":"33121C"},{"b":"106DB1000","o":"4707B5"},{"b":"106DB1000","o":"4CF2B6"},{"b":"106DB1000","o":"4D3BD7"},{"b":"106DB1000","o":"723079"},{"b":"106DB1000","o":"7B5E31"},{"b":"7FFF875CE000","o":"32FC"},{"b":"7FFF875CE000","o":"3279"},{"b":"7FFF875CE000","o":"14B1"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc5-pre-", "gitVersion" : "301928ace8cade016113fa2ef46dd5b607a00990", "uname" : { "sysname" : "Darwin", "release" : "14.0.0", "version" : "Darwin Kernel Version 14.0.0: Fri Sep 19 00:26:44 PDT 2014; root:xnu-2782.1.97~2/RELEASE_X86_64", "machine" : "x86_64" }, "somap" : [ { "path" : "/Users/skot/src/github/mongo/mongo/mongod", "machType" : 2, "b" : "106DB1000", "buildId" : "E4E2FBC033EA356DB336EF64D5591241" }, { "path" : "/usr/lib/libSystem.B.dylib", "machType" : 6, "b" : "7FFF880B9000", "buildId" : "DA954461EC6A3DF085516FC810627627" }, { "path" : "/usr/lib/libc++.1.dylib", "machType" : 6, "b" : "7FFF9031C000", "buildId" : "1B9530FD989B3174BB1CBDC159501710" }, { "path" : "/usr/lib/system/libcache.dylib", "machType" : 6, "b" : "7FFF90A48000", "buildId" : "45E9A2E799C436B2BEE30C4E11614AD1" }, { "path" : "/usr/lib/system/libcommonCrypto.dylib", "machType" : 6, "b" : "7FFF91C4A000", "buildId" : "D381EBC669D831D380845A80A32CB748" }, { "path" : "/usr/lib/system/libcompiler_rt.dylib", "machType" : 6, "b" : "7FFF903CB000", "buildId" : "BF8FC133EE103DA69B9092039E28678F" }, { "path" : "/usr/lib/system/libcopyfile.dylib", "machType" : 6, "b" : "7FFF8BBF6000", "buildId" : "0C68D3A6ACDD3EF3991ACC82C32AB836" }, { "path" : "/usr/lib/system/libcorecrypto.dylib", "machType" : 6, "b" : "7FFF90B10000", "buildId" : "E178980139853949B7366B3378873301" }, { "path" : "/usr/lib/system/libdispatch.dylib", "machType" : 6, "b" : "7FFF8DA0A000", "buildId" : "502CF32B669B3709886208188225E4F0" }, { "path" : "/usr/lib/system/libdyld.dylib", "machType" : 6, "b" : "7FFF9327E000", "buildId" : "19FAF435C16533749DEFD7BBA7D61DB6" }, { "path" : "/usr/lib/system/libkeymgr.dylib", "machType" : 6, "b" : "7FFF8CF09000", "buildId" : "77845842DE703CC5BD01C3D14227CED5" }, { "path" : "/usr/lib/system/liblaunch.dylib", "machType" : 6, "b" : "7FFF8CE2A000", "buildId" : "8A9889248BE735FEBF7D322E90EFE49E" }, { "path" : "/usr/lib/system/libmacho.dylib", "machType" : 6, "b" : "7FFF93300000", "buildId" : "126CA2EDDE91308F8881B9DAEC3C63B6" }, { "path" : "/usr/lib/system/libquarantine.dylib", "machType" : 6, "b" : "7FFF8630B000", "buildId" : "DC0416272D92361CBABFA869A5C72293" }, { "path" : "/usr/lib/system/libremovefile.dylib", "machType" : 6, "b" : "7FFF8C693000", "buildId" : "3485B5F46CE83C628DFD8736ED6E8531" }, { "path" : "/usr/lib/system/libsystem_asl.dylib", "machType" : 6, "b" : "7FFF87993000", "buildId" : "F153AC5B0542356E88C820A62CA704E2" }, { "path" : "/usr/lib/system/libsystem_blocks.dylib", "machType" : 6, "b" : "7FFF88C0B000", "buildId" : "9615D10AFCA73BE4AA1A1B195DACE1A1" }, { "path" : "/usr/lib/system/libsystem_c.dylib", "machType" : 6, "b" : "7FFF908FE000", "buildId" : "C185E86274243210B5286B822577A4B8" }, { "path" : "/usr/lib/system/libsystem_configuration.dylib", "machType" : 6, "b" : "7FFF83FF5000", "buildId" : "9FBA1CE497D0347EA44393ED94512E92" }, { "path" : "/usr/lib/system/libsystem_coreservices.dylib", "machType" : 6, "b" : "7FFF8D7DF000", "buildId" : "41B7C5785A5331C8A96FC73E030B0938" }, { "path" : "/usr/lib/system/libsystem_coretls.dylib", "machType" : 6, "b" : "1087A7000", "buildId" : "EBBF7EF680D83F8F825CB412BD6D22C0" }, { "path" : "/usr/lib/system/libsystem_dnssd.dylib", "machType" : 6, "b" : "7FFF91C41000", "buildId" : "62B70ECAE40D3C63896E7F00EC386DDB" }, { "path" : "/usr/lib/system/libsystem_info.dylib", "machType" : 6, "b" : "7FFF8D7EB000", "buildId" : "B85A85D585303A93B0C34DEC41F79478" }, { "path" : "/usr/lib/system/libsystem_kernel.dylib", "machType" : 6, "b" : "7FFF855D9000", "buildId" : "93E0E0A975B63904BB4E4BC7C05F4B6B" }, { "path" : "/usr/lib/system/libsystem_m.dylib", "machType" : 6, "b" : "7FFF83AFB000", "buildId" : "1E12AB456D9636D0A226F24D9FB0D9D6" }, { "path" : "/usr/lib/system/libsystem_malloc.dylib", "machType" : 6, "b" : "7FFF83ADE000", "buildId" : "19BCC25757173502A71F95D65AFA861B" }, { "path" : "/usr/lib/system/libsystem_network.dylib", "machType" : 6, "b" : "7FFF8CEC9000", "buildId" : "C0B2313D47BE38A9BEE62634A4F5E14B" }, { "path" : "/usr/lib/system/libsystem_networkextension.dylib", "machType" : 6, "b" : "7FFF8CE23000", "buildId" : "29AB225BD7FB30ED960065D44B9A9442" }, { "path" : "/usr/lib/system/libsystem_notify.dylib", "machType" : 6, "b" : "7FFF846DB000", "buildId" : "61147800F3203DAA850CBADF33855F29" }, { "path" : "/usr/lib/system/libsystem_platform.dylib", "machType" : 6, "b" : "7FFF8EFC0000", "buildId" : "64E34079D7123D669CE2418624A5C040" }, { "path" : "/usr/lib/system/libsystem_pthread.dylib", "machType" : 6, "b" : "7FFF875CE000", "buildId" : "26B1897F0CD330F3B55A37CB45062D73" }, { "path" : "/usr/lib/system/libsystem_sandbox.dylib", "machType" : 6, "b" : "7FFF87FBF000", "buildId" : "DB9962EF889831CC9B87E01F8CE74C9D" }, { "path" : "/usr/lib/system/libsystem_secinit.dylib", "machType" : 6, "b" : "7FFF8ABE4000", "buildId" : "581DAD0F6B633A48B63B917AF799ABAA" }, { "path" : "/usr/lib/system/libsystem_stats.dylib", "machType" : 6, "b" : "7FFF8BE1D000", "buildId" : "1DB0443659743F1686CC5FF5F390339C" }, { "path" : "/usr/lib/system/libsystem_trace.dylib", "machType" : 6, "b" : "7FFF8DBB4000", "buildId" : "A9E6B7D8C3273742AC5486C94218B1DF" }, { "path" : "/usr/lib/system/libunc.dylib", "machType" : 6, "b" : "7FFF87213000", "buildId" : "5676F7EAC1DF329FB006D2C3022B7D70" }, { "path" : "/usr/lib/system/libunwind.dylib", "machType" : 6, "b" : "7FFF8BBD7000", "buildId" : "BE7E51A0B6EA3A549CCA9D88F683A6D6" }, { "path" : "/usr/lib/system/libxpc.dylib", "machType" : 6, "b" : "7FFF91BF0000", "buildId" : "9437C02EA07B38C891CB299FAA63083D" }, { "path" : "/usr/lib/libobjc.A.dylib", "machType" : 6, "b" : "7FFF86ACF000", "buildId" : "3B60CD9074A23A5D9686B0772159792A" }, { "path" : "/usr/lib/libauto.dylib", "machType" : 6, "b" : "7FFF8C64C000", "buildId" : "A260789BD4D8316A9490254767B8A5F1" }, { "path" : "/usr/lib/libc++abi.dylib", "machType" : 6, "b" : "7FFF8A0DF000", "buildId" : "88A22A0F87C63002BFBAAC0F2808B8B9" }, { "path" : "/usr/lib/libDiagnosticMessagesClient.dylib", "machType" : 6, "b" : "7FFF8ABE6000", "buildId" : "2EE8E4365CDC34C599595BA218D507FB" } ] }}
 mongod(_ZN5mongo15printStackTraceERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEE+0x3A) [0x10753064a]
 mongod(_ZN5mongo10logContextEPKc+0x10E) [0x1074dd87e]
 mongod(_ZN5mongo15invariantFailedEPKcS1_j+0x1B4) [0x1074ca954]
 mongod(_ZN5mongo3dur23closingFileNotificationEv+0x9A) [0x1072f543a]
 mongod(_ZN5mongo17DurableMappedFileD2Ev+0xE9) [0x10730ca19]
 mongod(_ZN5mongo19MmapV1ExtentManager9_addAFileEPNS_16OperationContextEib+0x43D) [0x10731c8bd]
 mongod(_ZN5mongo19MmapV1ExtentManager13_createExtentEPNS_16OperationContextEib+0xE0) [0x10731c1d0]
 mongod(_ZN5mongo19MmapV1ExtentManager14allocateExtentEPNS_16OperationContextEbib+0x74) [0x10731d7e4]
 mongod(_ZN5mongo17RecordStoreV1Base19increaseStorageSizeEPNS_16OperationContextEib+0x41) [0x107323331]
 mongod(_ZN5mongo19SimpleRecordStoreV111allocRecordEPNS_16OperationContextEib+0x28E) [0x1073300fe]
 mongod(_ZN5mongo17RecordStoreV1Base13_insertRecordEPNS_16OperationContextEPKcib+0xA1) [0x1073228d1]
 mongod(_ZN5mongo17RecordStoreV1Base12insertRecordEPNS_16OperationContextEPKcib+0xA5) [0x1073227f5]
 mongod(_ZN5mongo10Collection15_insertDocumentEPNS_16OperationContextERKNS_7BSONObjEb+0x58) [0x106ebdfb8]
 mongod(_ZN5mongo10Collection14insertDocumentEPNS_16OperationContextERKNS_7BSONObjEb+0x88) [0x106ebdd68]
 mongod(_ZN5mongo11UpdateStage8doInsertEv+0x622) [0x10700c272]
 mongod(_ZN5mongo11UpdateStage4workEPm+0x9B) [0x10700ca6b]
 mongod(_ZN5mongo12PlanExecutor7getNextEPNS_7BSONObjEPNS_8RecordIdE+0x94) [0x1071afce4]
 mongod(_ZN5mongo12PlanExecutor11executePlanEv+0x58) [0x1071b03d8]
 mongod(_ZN5mongo6updateEPNS_16OperationContextEPNS_8DatabaseERKNS_13UpdateRequestEPNS_7OpDebugE+0x63C) [0x1070e221c]
 mongod(_ZN5mongo4repl21applyOperation_inlockEPNS_16OperationContextEPNS_8DatabaseERKNS_7BSONObjEbb+0x14C5) [0x1072217b5]
 mongod(_ZN5mongo4repl8SyncTail9syncApplyEPNS_16OperationContextERKNS_7BSONObjEb+0x736) [0x1072802b6]
 mongod(_ZN5mongo4repl14multiSyncApplyERKNSt3__16vectorINS_7BSONObjENS1_9allocatorIS3_EEEEPNS0_8SyncTailE+0xB7) [0x107284bd7]
 mongod(_ZN5mongo10threadpool6Worker4loopERKNSt3__112basic_stringIcNS2_11char_traitsIcEENS2_9allocatorIcEEEE+0x79) [0x1074d4079]
 mongod(_ZN5boost12_GLOBAL__N_112thread_proxyEPv+0xB1) [0x107566e31]
 libsystem_pthread.dylib(_pthread_body+0x83) [0x7fff875d12fc]
 libsystem_pthread.dylib(_pthread_body+0x0) [0x7fff875d1279]
 libsystem_pthread.dylib(thread_start+0xD) [0x7fff875cf4b1]
-----  END BACKTRACE  -----
2015-01-08T11:32:58.450-0500 I -        [repl writer worker 15] 
 
***aborting after invariant() failure



 Comments   
Comment by Githook User [ 04/Mar/15 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-17388/SERVER-16776 If closing unopened file, do not check for journal writes

(cherry picked from commit a9f240048fe27d925c0ad1798c1bf29ce59f0acc)
Branch: v3.0
https://github.com/mongodb/mongo/commit/e1adb14bb593e22203d82018f4ba78c77aa289b3

Comment by Githook User [ 27/Feb/15 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-17388/SERVER-16776 If closing unopened file, do not check for journal writes
Branch: master
https://github.com/mongodb/mongo/commit/a9f240048fe27d925c0ad1798c1bf29ce59f0acc

Comment by Githook User [ 16/Jan/15 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-16776 Shutdown should not interruput file creations
Branch: master
https://github.com/mongodb/mongo/commit/83056450de5203e8e14a16bf31856d82d84ebb87

Comment by Kaloian Manassiev [ 08/Jan/15 ]

Happens because the check for no journal writes for files that are closing blindly checks that there are no writes at all instead of checking if there are no writes for the file that's being closed.

The fix would be to either remove this assertion altogether or to make sure closingFileNotification take into account which file is being closed.

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

If you apply the smoke diff you might be able to repro running this:

smoke.py --continue-on-failure --small-oplog-rs  jstests/core/find_and_modify5.js

NOTE: small-oplog-rs is broken without this patch and I'm still working on it.

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