SERVER-15111 Treat corruption of final journal section as an expected event

Manual backport of the following commits (combined):
8e1f5beabfad09c790e46826e8b3c7dcc5070d8d
6e93b33179e71abce820e534b3d32f1e593f71ca

7 files changed, 139 insertions, 138 deletions

diff --git a/jstests/dur/checksum.js b/jstests/dur/checksum.js
new file mode 100644
index 00000000000..1270e337a87
--- /dev/null
+++ b/jstests/dur/checksum.js
@@ -0,0 +1,89 @@
+// Test checksum validation of journal files.
+
+var testname = "dur_checksum";
+var path = MongoRunner.dataPath + testname;
+
+if (0) {
+    // This is used to create the prototype journal file.
+    jsTest.log("Just creating prototype journal, not testing anything");
+    var conn = startMongodEmpty("--port", 30001, "--dbpath", path, "--dur");
+    var db = conn.getDB("test");
+
+    // each insert is in it's own commit.
+    db.foo.insert({a: 1});
+    db.runCommand({getlasterror:1, j:1})
+
+    db.foo.insert({a: 2});
+    db.runCommand({getlasterror:1, j:1})
+
+    stopMongod(30001, /*signal*/9);
+
+    jsTest.log("Journal file left at " + path + "/journal/j._0");
+    quit();
+    // A hex editor must be used to replace the checksums of specific journal sections with
+    // "0BADC0DE 1BADC0DE 2BADC0DE 3BADCD0E"
+}
+
+function startMongodWithJournal() {
+    return startMongodNoReset("--port", 30001,
+                              "--dbpath", path,
+                              "--dur",
+                              "--smallfiles",
+                              "--durOptions", 1 /*DurDumpJournal*/);
+}
+
+
+jsTest.log("Starting with good.journal to make sure everything works");
+resetDbpath(path);
+mkdir(path + '/journal');
+copyFile("jstests/libs/dur_checksum_good.journal", path + "/journal/j._0");
+var conn = startMongodWithJournal();
+var db = conn.getDB('test');
+assert.eq(db.foo.count(), 2);
+stopMongod(30001);
+
+
+// dur_checksum_bad_last.journal is good.journal with the bad checksum on the last section.
+jsTest.log("Starting with bad_last.journal");
+resetDbpath(path);
+mkdir(path + '/journal');
+copyFile("jstests/libs/dur_checksum_bad_last.journal", path + "/journal/j._0");
+conn = startMongodWithJournal();
+var db = conn.getDB('test');
+assert.eq(db.foo.count(), 1); // 2nd insert "never happened"
+stopMongod(30001);
+
+
+// dur_checksum_bad_first.journal is good.journal with the bad checksum on the prior section.
+// This means there is a good commit after the bad one. We currently ignore this, but a future
+// version of the server may be able to detect this case.
+jsTest.log("Starting with bad_first.journal");
+resetDbpath(path);
+mkdir(path + '/journal');
+copyFile("jstests/libs/dur_checksum_bad_first.journal", path + "/journal/j._0");
+conn = startMongodWithJournal();
+var db = conn.getDB('test');
+assert.eq(db.foo.count(), 0); // Neither insert happened.
+stopMongod(30001);
+
+// If we detect an error in a non-final journal file, that is considered an error.
+jsTest.log("Starting with bad_last.journal followed by good.journal");
+resetDbpath(path);
+mkdir(path + '/journal');
+copyFile("jstests/libs/dur_checksum_bad_first.journal", path + "/journal/j._0");
+copyFile("jstests/libs/dur_checksum_good.journal", path + "/journal/j._1");
+
+exitCode = runMongoProgram("mongod",
+                           "--port", 30001,
+                           "--dbpath", path,
+                           "--dur",
+                           "--smallfiles",
+                           "--durOptions", 1 /*DurDumpJournal*/
+                                         + 2 /*DurScanOnly*/);
+
+assert.eq(exitCode, 100 /*EXIT_UNCAUGHT*/);
+
+// TODO Possibly we could check the mongod log to verify that the correct type of exception was
+// thrown.  But that would introduce a dependency on the mongod log format, which we may not want.
+
+jsTest.log("SUCCESS checksum.js");
diff --git a/jstests/dur/md5.js b/jstests/dur/md5.js
deleted file mode 100644
index 107476e9704..00000000000
--- a/jstests/dur/md5.js
+++ /dev/null
@@ -1,101 +0,0 @@
-/**
- * Test md5 validation of journal file.
- * This test is dependent on the journal file format and may require an update if the format changes,
- * see comments near fuzzFile() below.
- */
-
-var debugging = false;
-var testname = "dur_md5";
-var step = 1;
-var conn = null;
-
-function log(str) {
-    print();
-    if(str)
-        print(testname+" step " + step++ + " " + str);
-    else
-        print(testname+" step " + step++);
-}
-
-/** Changes here may require updating the byte index of the md5 hash, see File comments below. */
-function work() {
-    log("work");
-    var d = conn.getDB("test");
-    d.foo.insert({ _id: 3, x: 22 });
-    d.foo.insert({ _id: 4, x: 22 });
-    d.a.insert({ _id: 3, x: 22, y: [1, 2, 3] });
-    d.a.insert({ _id: 4, x: 22, y: [1, 2, 3] });
-    d.a.update({ _id: 4 }, { $inc: { x: 1} });
-    
-    // try building an index.  however, be careful as object id's in system.indexes would vary, so we do it manually:
-    d.system.indexes.insert({ _id: 99, ns: "test.a", key: { x: 1 }, name: "x_1", v: 0 });
-    
-    //    d.a.update({ _id: 4 }, { $inc: { x: 1} });
-    //    d.a.reIndex();
-    
-    // assure writes applied in case we kill -9 on return from this function
-    d.getLastError(); 
-    
-    log("endwork");
-}
-
-if( debugging ) { 
-    // mongod already running in debugger
-    conn = db.getMongo();
-    work();
-    sleep(30000);
-    quit();
-}
-
-log();
-
-var path = "/data/db/" + testname+"dur";
-
-log();
-conn = startMongodEmpty("--port", 30001, "--dbpath", path, "--dur", "--smallfiles", "--durOptions", 8);
-work();
-
-// wait for group commit.
-printjson(conn.getDB('admin').runCommand({getlasterror:1, fsync:1}));

-

-log("kill -9");
-
-// kill the process hard
-stopMongod(30001, /*signal*/9);
-
-// journal file should be present, and non-empty as we killed hard
-
-// Bit flip the first byte of the md5sum contained within the opcode footer.

-// This ensures we get an md5 exception instead of some other type of exception.

-var file = path + "/journal/j._0";

-

-// if test fails, uncomment these "cp" lines to debug:

-// run("cp", file, "/tmp/before");

-

-// journal header is 8192

-// jsectheader is 20

-// so a little beyond that

-fuzzFile(file, 8214+8);

-

-// run("cp", file, "/tmp/after");
-
-log("run mongod again recovery should fail");
-
-// 100 exit code corresponds to EXIT_UNCAUGHT, which is triggered when there is an exception during recovery.
-// 14 is is sometimes triggered instead due to SERVER-2184
-exitCode = runMongoProgram( "mongod", "--port", 30002, "--dbpath", path, "--dur", "--smallfiles", "--durOptions", /*9*/13 );

-

-if (exitCode != 100 && exitCode != 14) {

-    print("\n\n\nFAIL md5.js expected mongod to fail but didn't? mongod exitCode: " + exitCode + "\n\n\n");

-    // sleep a little longer to get more output maybe

-    sleep(2000);

-    assert(false);

-}
-
-// TODO Possibly we could check the mongod log to verify that the correct type of exception was thrown.  But
-// that would introduce a dependency on the mongod log format, which we may not want.

-

-print("SUCCESS md5.js");

-

-// if we sleep a littler here we may get more out the mongod output logged

-sleep(500);

diff --git a/jstests/libs/dur_checksum_bad_first.journal b/jstests/libs/dur_checksum_bad_first.journal
new file mode 100644
index 00000000000..687317844a7
--- /dev/null
+++ b/jstests/libs/dur_checksum_bad_first.journal
diff --git a/jstests/libs/dur_checksum_bad_last.journal b/jstests/libs/dur_checksum_bad_last.journal
new file mode 100644
index 00000000000..7dd98e2c97b
--- /dev/null
+++ b/jstests/libs/dur_checksum_bad_last.journal
diff --git a/jstests/libs/dur_checksum_good.journal b/jstests/libs/dur_checksum_good.journal
new file mode 100644
index 00000000000..d76790d2451
--- /dev/null
+++ b/jstests/libs/dur_checksum_good.journal
diff --git a/src/mongo/db/dur_recover.cpp b/src/mongo/db/dur_recover.cpp
index 717bdcf0e5a..58dacff5f71 100644
--- a/src/mongo/db/dur_recover.cpp
+++ b/src/mongo/db/dur_recover.cpp
@@ -49,6 +49,15 @@ using namespace mongoutils;
 
 namespace mongo {
 
+    /**
+     * Thrown when a journal section is corrupt. This is considered OK as long as it occurs while
+     * processing the last file. Processing stops at the first corrupt section.
+     *
+     * Any logging about the nature of the corruption should happen before throwing as this class
+     * contains no data.
+     */
+    class JournalSectionCorruptException {};
+
     namespace dur {
 
         struct ParsedJournalEntry { /*copyable*/
@@ -112,9 +121,10 @@ namespace mongo {
                 verify( doDurOpsRecovering );
                 bool ok = uncompress((const char *)compressed, compressedLen, &_uncompressed);
                 if( !ok ) { 
-                    // it should always be ok (i think?) as there is a previous check to see that the JSectFooter is ok
+                    // We check the checksum before we uncompress, but this may still fail as the
+                    // checksum isn't foolproof.
                     log() << "couldn't uncompress journal section" << endl;
-                    msgasserted(15874, "couldn't uncompress journal section");
+                    throw JournalSectionCorruptException();
                 }
                 const char *p = _uncompressed.c_str();
                 verify( compressedLen == _h.sectionLen() - sizeof(JSectFooter) - sizeof(JSectHeader) );
@@ -162,7 +172,11 @@ namespace mongo {
                         _lastDbName = (const char*) _entries->pos();
                         const unsigned limit = std::min((unsigned)Namespace::MaxNsLen, _entries->remaining());
                         const unsigned len = strnlen(_lastDbName, limit);
-                        massert(13533, "problem processing journal file during recovery", _lastDbName[len] == '\0');
+                        if (_lastDbName[len] != '\0') {
+                            log() << "problem processing journal file during recovery";
+                            throw JournalSectionCorruptException();
+                        }
+
                         _entries->skip(len+1); // skip '\0' too
                         _entries->read(lenOrOpCode); // read this for the fall through
                     }
@@ -357,10 +371,15 @@ namespace mongo {
             scoped_lock lk(_mx);
             RACECHECK
 
-            /** todo: we should really verify the checksum to see that seqNumber is ok?
-                      that is expensive maybe there is some sort of checksum of just the header 
-                      within the header itself
-            */
+            // Check the footer checksum before doing anything else.
+            if (_recovering) {
+                verify( ((const char *)h) + sizeof(JSectHeader) == p );
+                if (!f->checkHash(h, len + sizeof(JSectHeader))) {
+                    log() << "journal section checksum doesn't match";
+                    throw JournalSectionCorruptException();
+                }
+            }
+
             if( _recovering && _lastDataSyncedFromLastRun > h->seqNumber + ExtraKeepTimeMs ) {
                 if( h->seqNumber != _lastSeqMentionedInConsoleLog ) {
                     static int n;
@@ -403,14 +422,6 @@ namespace mongo {
                 entries.push_back(e);
             }
 
-            // after the entries check the footer checksum
-            if( _recovering ) {
-                verify( ((const char *)h) + sizeof(JSectHeader) == p );
-                if( !f->checkHash(h, len + sizeof(JSectHeader)) ) { 
-                    msgasserted(13594, "journal checksum doesn't match");
-                }
-            }
-
             // got all the entries for one group commit.  apply them:
             applyEntries(entries);
         }
@@ -429,20 +440,20 @@ namespace mongo {
                     JHeader h;
                     br.read(h);
 
-                    /* [dm] not automatically handled.  we should eventually handle this automatically.  i think:
-                       (1) if this is the final journal file
-                       (2) and the file size is just the file header in length (or less) -- this is a bit tricky to determine if prealloced
-                       then can just assume recovery ended cleanly and not error out (still should log).
-                    */
-                    uassert(13537, 
-                        "journal file header invalid. This could indicate corruption in a journal file, or perhaps a crash where sectors in file header were in flight written out of order at time of crash (unlikely but possible).", 
-                        h.valid());
+                    if (!h.valid()) {
+                        log() << "Journal file header invalid. This could indicate corruption, or "
+                              << "an unclean shutdown while writing the first section in a journal "
+                              << "file.";
+                        throw JournalSectionCorruptException();
+                    }
 
                     if( !h.versionOk() ) {
                         log() << "journal file version number mismatch got:" << hex << h._version                             
                             << " expected:" << hex << (unsigned) JHeader::CurrentVersion 
                             << ". if you have just upgraded, recover with old version of mongod, terminate cleanly, then upgrade." 
                             << endl;
+                        // Not using JournalSectionCurruptException as we don't want to ignore
+                        // journal files on upgrade.
                         uasserted(13536, str::stream() << "journal version number mismatch " << h._version);
                     }
                     fileId = h.fileId;
@@ -473,7 +484,12 @@ namespace mongo {
                     killCurrentOp.checkForInterrupt(false);
                 }
             }
-            catch( BufReader::eof& ) {
+            catch (const BufReader::eof&) {
+                if( cmdLine.durOptions & CmdLine::DurDumpJournal )
+                    log() << "ABRUPT END" << endl;
+                return true; // abrupt end
+            }
+            catch (const JournalSectionCorruptException&) {
                 if( cmdLine.durOptions & CmdLine::DurDumpJournal )
                     log() << "ABRUPT END" << endl;
                 return true; // abrupt end
diff --git a/src/mongo/shell/shell_utils_extended.cpp b/src/mongo/shell/shell_utils_extended.cpp
index 2808bab7688..d852893270b 100644
--- a/src/mongo/shell/shell_utils_extended.cpp
+++ b/src/mongo/shell/shell_utils_extended.cpp
@@ -183,22 +183,19 @@ namespace mongo {
         }
 
         /**
-         * @param args - [ name, byte index ]
-         * In this initial implementation, all bits in the specified byte are flipped.
+         * @param args - [ source, destination ]
+         * copies file 'source' to 'destination'. Errors if the 'destination' file already exists.
          */
-        BSONObj fuzzFile(const BSONObj& args, void* data) {
-            uassert( 13619, "fuzzFile takes 2 arguments", args.nFields() == 2 );
-            scoped_ptr< File > f( new File() );
-            f->open( args.getStringField( "0" ) );
-            uassert( 13620, "couldn't open file to fuzz", !f->bad() && f->is_open() );
+        BSONObj copyFile(const BSONObj& args, void* data) {
+            uassert(13619, "copyFile takes 2 arguments", args.nFields() == 2);
 
-            char c;
-            f->read( args.getIntField( "1" ), &c, 1 );
-            c = ~c;
-            f->write( args.getIntField( "1" ), &c, 1 );
+            BSONObjIterator it(args);
+            const std::string source = it.next().str();
+            const std::string destination = it.next().str();
+
+            boost::filesystem::copy_file(source, destination);
 
             return undefinedReturn;
-            // f close is implicit
         }
 
         BSONObj getHostName(const BSONObj& a, void* data) {
@@ -212,7 +209,7 @@ namespace mongo {
         void installShellUtilsExtended( Scope& scope ) {
             scope.injectNative( "getHostName" , getHostName );
             scope.injectNative( "removeFile" , removeFile );
-            scope.injectNative( "fuzzFile" , fuzzFile );
+            scope.injectNative( "copyFile" , copyFile );
             scope.injectNative( "listFiles" , listFiles );
             scope.injectNative( "ls" , ls );
             scope.injectNative( "pwd", pwd );