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

WiredTiger unable to start if crash leaves 0-length journal file

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 3.0.1, 3.1.0
    • Affects Version/s: 3.0.0
    • Component/s: WiredTiger
    • Fully Compatible
    • ALL

      Issue Status as of Mar 10, 2015

      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.

            Assignee:
            sue.loverso@mongodb.com Susan LoVerso
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: