title: Mongo possible data corruption returning secondary to replica set
body: <p>I am trying to understand the source of some data corruption that occurred around the same time a secondary was returned to a replica set.</p>
  
  <p>We have a production replica set with 4 nodes - 3 data carrying nodes and an arbiter.</p>
  
  <p>I took a secondary (call it <code>X</code>) out of the production replica set and used it to seed a new test replica set for some performance benchmarking. After seeding the new replica set, I put <code>X</code> back into the production replica set. Within about 10 hours we had complaints from customers that they had lost around 2 days of data. <code>X</code> had been out of production for 2 days as well. So we are wondering if re-introducing <code>X</code> caused some data reversion.</p>
  
  <p>The timings line up very closely and we haven't been able to find any plausible alternative theory - hence this post.</p>
  
  <p>The odd thing is that only <em>some</em> mongo collections were "reverted". Our database seems to be a mix of the primary and <code>X</code>.</p>
  
  <hr>
  
  <p>In more detail this is what I did:</p>
  
  <ul>
  <li>ran <code>rs.remove(X)</code></li>
  <li>removed all replica set info from its <code>mongod.conf</code></li>
  <li>restarted <code>X</code></li>
  <li>connected to the <code>local</code> database and ran <code>db.dropDatabase()</code> to clean out the production replica set info</li>
  <li>reinstated replica info in <code>mongod.conf</code> but with a new replica set name</li>
  <li>restarted <code>X</code></li>
  <li>brought up 3 empty mmapv1 nodes and an arbiter and connected them to <code>X</code> in the new replica set</li>
  <li>let them replicate for about 48 hours</li>
  <li>ran <code>rs.stepDown()</code> and <code>rs.remove(X)</code></li>
  <li>removed all replica set info from its <code>mongod.conf</code></li>
  <li>like above, connected and dropped the <code>local</code> database</li>
  <li>reinstated replica info in <code>mongod.conf</code> but with the production replica set name</li>
  <li>used <code>rs.add(X)</code> to add <code>X</code> back into the production replica set</li>
  </ul>
  
  <p>To clarify - no new data was added to <code>X</code> when it was the primary in the test replica set.</p>
  
  <hr>
  
  <p>Here's some info which might be relevant:</p>
  
  <p>All nodes are mmapv1 running mongo 3.2.7.</p>
  
  <p>After <code>X</code> was removed from the production replica set, it's entry for the production primary in <code>/etc/hosts</code> accidentally got deleted. It was able to communicate directly with the other secondary and arbiter but not the primary. There were lots of heartbeat error logs.</p>
  
  <p>I found these logs which seem to indicate that <code>X</code>'s data got dropped when it re-entered the production replica set:</p>
  
  <pre><code>2017-01-13T10:00:59.497+0000 I REPL     [ReplicationExecutor] syncing from: (other secondary)
  2017-01-13T10:00:59.552+0000 I REPL     [rsSync] initial sync drop all databases 
  2017-01-13T10:00:59.554+0000 I STORAGE  [rsSync] dropAllDatabasesExceptLocal 3 
  2017-01-13T10:00:59.588+0000 I JOURNAL  [rsSync] journalCleanup... 
  2017-01-13T10:00:59.588+0000 I JOURNAL  [rsSync] removeJournalFiles
  </code></pre>
  
  <p>Prior to all this, developers had also been reporting issues that the primary was sometimes unresponsive under higher loads. These are some errors from the reactivemongo driver:</p>
  
  <pre><code>No primary node is available!
  The primary is unavailable, is there a network problem?
  not authorized for query on [db]:[collection]
  </code></pre>
  
  <p>The nodes are on aws: the primary runs on an <code>m3.xlarge</code>, the secondaries on <code>m3.large</code> and the arbiter on <code>m3.medium</code>.</p>
  
  <p>About 30 hours after we got customer complaints, our replica set held an election and <code>X</code> became the primary. These are the logs:</p>
  
  <pre><code>2017-01-15T16:00:33.332+0000 I REPL     [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms 
  2017-01-15T16:00:33.333+0000 I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected 
  2017-01-15T16:00:33.347+0000 I REPL     [ReplicationExecutor] dry election run succeeded, running for election 
  2017-01-15T16:00:33.370+0000 I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 2 
  2017-01-15T16:00:33.370+0000 I REPL     [ReplicationExecutor] transition to PRIMARY 
  2017-01-15T16:00:33.502+0000 I REPL     [rsSync] transition to primary complete; database writes are now permitted
  </code></pre>
  
  <p>This happened before I realized the <code>/etc/hosts</code> file was broken on <code>X</code>.</p>
  
  <p>I also found a lot of these errors in the logs when replicating one very large collection (260 million documents):</p>
  
  <pre><code>2017-01-13T13:01:35.576+0000 E REPL     [repl writer worker 9] update of non-mod failed: { ts: Timestamp 1484301755000|10, t: 1, h: -7625794279778931676, v: 2, op: "u", ns: ...
  </code></pre>
  
  <p>This is a different collection though to the one which got corrupted.</p>