ISSUE SUMMARY
When attempting to start a MongoDB instance with the WiredTiger storage engine that has journaling enabled, if the journal is 0-length, the mongod will refuse to start. This condition is triggered by some unclean mongod shutdowns/crashes.
USER IMPACT
mongod may fail to start following unexpected termination if the journal file is 0-length.
WORKAROUNDS
Ensure that MongoDB always shuts down cleanly.
AFFECTED VERSIONS
v3.0.0
FIX VERSION
The fix is included in the 3.0.1 production release.
RESOLUTION DETAILS
WiredTiger now fsyncs journal files before closing a pre-allocated log file or after writing the header on a non-preallocated log file to avoid ending up with a zero-length log file.
Original description
Per strace, the following sequence is used to create a WiredTigerLog file:
16:33:19.755622 open("db3/journal/WiredTigerTmplog.0000000001", O_RDWR|O_CREAT, 0666) = 12 16:33:19.755817 fcntl(12, F_GETFD) = 0 16:33:19.755984 fcntl(12, F_SETFD, FD_CLOEXEC) = 0 16:33:19.756155 fstat(12, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0 16:33:19.756355 pwrite(12, "\200\0\0\0\3447\217\243\0\0\0\0\0\0\0\0d\20\20\0\1\0\0\0\0\0@\6\0\0\0\0"..., 128, 0) = 128 16:33:19.756571 ftruncate(12, 128) = 0 16:33:19.756759 close(12) = 0 16:33:19.756938 rename("db3/journal/WiredTigerTmplog.0000000001", "db3/journal/WiredTigerLog.0000000001") = 0
Similar sequence for WiredTigerPreplog file:
16:33:19.763381 open("db3/journal/WiredTigerTmplog.0000000001", O_RDWR|O_CREAT, 0666) = 13 16:33:19.763515 fcntl(13, F_GETFD) = 0 16:33:19.763699 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 16:33:19.763876 fstat(13, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0 16:33:19.764046 pwrite(13, "\200\0\0\0\3447\217\243\0\0\0\0\0\0\0\0d\20\20\0\1\0\0\0\0\0@\6\0\0\0\0"..., 128, 0) = 128 16:33:19.764212 ftruncate(13, 128) = 0 16:33:19.764431 fallocate(13, 01, 128, 104857600) = 0 16:33:19.767897 close(13) = 0 16:33:19.768120 rename("db3/journal/WiredTigerTmplog.0000000001", "db3/journal/WiredTigerPreplog.0000000001") = 0
Since the file was not fsync'ed before being closed, the file is vulnerable to being left in an inconsistent state if the node crashes - for example, on reboot the file could be found to exist but to be of 0 length. If this happens recovery fails:
2015-03-02T14:36:40.076-0500 W - [initandlisten] Detected unclean shutdown - /data/wiredTiger/mongod.lock is not empty. 2015-03-02T14:36:40.076-0500 W STORAGE [initandlisten] Recovering data from the last clean checkpoint. 2015-03-02T14:36:40.076-0500 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), 2015-03-02T14:36:41.495-0500 E STORAGE [initandlisten] WiredTiger (-31802) [1425325001:495898][1276:0x7f2a4ce27b60]: journal/WiredTigerLog.0000000006 read error: failed to read 128 bytes at offset 0: WT_ERROR: non-specific WiredTiger error 2015-03-02T14:36:41.506-0500 I - [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error 2015-03-02T14:36:41.509-0500 I STORAGE [initandlisten] exception in initAndListen: 28595 -31802: WT_ERROR: non-specific WiredTiger error, terminating 2015-03-02T14:36:41.509-0500 I CONTROL [initandlisten] dbexit: rc: 100
I believe the correct fix is to fsync the file after writing the header but before closing it, similar to SERVER-17204.
- is related to
-
SERVER-17152 WiredTiger file corrupted during power cycle test
-
- Closed
-
-
-
- Closed
-
- related to
-
-
- Closed
-