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

… event

Manual backport of the following commits (combined):
8e1f5be
6e93b33

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");

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

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 );