[SERVER-42925] idempotency tests have oplog visiblity issues Created: 20/Aug/19  Updated: 29/Oct/23  Resolved: 04/Oct/19

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: 4.3.1, 4.2.2

Type: Bug Priority: Major - P3
Reporter: Eric Milkie Assignee: Lingzhi Deng
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Related
is related to SERVER-42213 ephemeralForTest cursors need to be m... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.2
Sprint: Repl 2019-09-09, Repl 2019-09-23, Repl 2019-10-07
Participants:
Linked BF Score: 14

 Description   

The MultiApplier reads from the oplog to piece together a multi-document prepared transaction. The code is currently affected by oplog visibility issues, surfaced in an idempotency test. This ticket is to fix those problems.

Original description:
For example, this line:
https://github.com/mongodb/mongo/blob/36aacf391a13eba67648f1cf625fe26515454a70/src/mongo/db/repl/sync_tail_test.cpp#L3072
Attempts to process a prepare and a commit oplog entry in the same batch. By tweaking timing, I can get that test to fail with this error:

2019-08-20T14:18:22.223-0400 F  -        [main] Fatal assertion 31145 IncompleteTransactionHistory: oplog no longer contains the complete write history of this transaction, log with opTime { ts: Timestamp(90, 0), t: 1 } cannot be found at src/mongo/db/transaction_history_iterator.cpp 137

There are several tests in sync_tail_test that attempt to do this. It isn't clear to me why the test is currently passing most of the time. I managed to trigger this failure simply by switching the underlying storage engine from emphemeralForTest to wiredTiger.



 Comments   
Comment by Githook User [ 21/Nov/19 ]

Author:

{'email': 'lingzhi.deng@mongodb.com', 'name': 'Lingzhi Deng', 'username': 'ldennis'}

Message: SERVER-42925 Refactor idempotency tests oplog application and fix oplog visiblity issues
Branch: v4.2
https://github.com/mongodb/mongo/commit/5e1b0d1a69be18eb4f93f01831d9fd9db1b3a516

Comment by Githook User [ 04/Oct/19 ]

Author:

{'name': 'Lingzhi Deng', 'username': 'ldennis', 'email': 'lingzhi.deng@mongodb.com'}

Message: SERVER-42925 Refactor idempotency tests oplog application and fix oplog visiblity issues
Branch: master
https://github.com/mongodb/mongo/commit/d1c6b36bf04dd90ad963ad5dfbfa491de0c88789

Comment by Lingzhi Deng [ 01/Oct/19 ]

After talking to daniel.gottlieb, I think there is no issue in the production batch application since we always update oplog visibility after each batch. In other words, we don't rely on So the fix would be to fix idempotency tests to simulate secondary's behavior.

Comment by Lingzhi Deng [ 24/Sep/19 ]

Yes, I think it would be helpful to have a way to ignore the visibility rules. I was about to open a CR for this which introduces a new read source to skip setting the _oplogVisibleTs. Do you think this is the way to go (kinda hacky?) or do you think it is better to do in the cursor layer as described in SERVER-43412? Is the plan to provide a flag in getCursor so Query code path can set/unset it?

Comment by Dianna Hohensee (Inactive) [ 24/Sep/19 ]

Hi all, Dan.G pointed me at this tickets existence. I just filed SERVER-43412, which still needs to be explored some for viability, but seems like it would help address this issue by providing a code path to ignore oplog visibility rules?

Comment by Eric Milkie [ 27/Aug/19 ]

Now that MMAP is gone, we can probably change the query and storage systems to use OplogHack for both forward and reverse cursors.
We could also consider adding a query flag that tells the query system to simply ignore oplog visibility even for forward cursors, for internal use, but implementing that would be a lot of work.

Comment by Siyuan Zhou [ 27/Aug/19 ]

TransactionHistoryIterator is also needed by change stream so it may have to use OplogHack for performance reasons, which is only for forward cursors.

Comment by Eric Milkie [ 27/Aug/19 ]

Yes, those symptoms helped me discover the problem. It was very subtle, and it is a race, which is why when you add things to slow down the test slightly (like logging), it changes the behavior.

The issue is that the code as written is not waiting for the oplog visibility thread to make the oplog entries visible. Typically, doing a query on the oplog does do this wait for you automatically, but only on primary nodes as per the comment here:
https://github.com/mongodb/mongo/blob/1fa4766c621bd4cfd74319094469eff3a5de3b79/src/mongo/db/query/get_executor.cpp#L299

I think this is actually identifying a problem even in production, although the code in production does so much in between writing a batch to the oplog and processing the next batch that I guess we never encounter it. The way to fix it would be to call waitForAllEarlierOplogWritesToBeVisible() at the end of every batch, although this would needlessly affect performance. A better solution would be to use a reverse-scanning cursor when doing the oplog entry queries in the TransactionHistoryIterator. Unlike forward cursors, reverse cursors skip oplog visiblity rules and can see everything immediately.

Comment by Lingzhi Deng [ 27/Aug/19 ]

Before it calls fillWriterVectors(), it writes all oplog entries to the oplog collection first. I was able to reproduce the issue and it seems that this only happens with the CommitPreparedTransactionIgnoresNamespaceNotFoundErrors test. I am not sure why isn't the prepare oplog entry (inserted by getStorageInterface()->insertDocument) visible to the TransactionHistoryIterator. I tried to do a DBDirectClient find after the insertDocument call and I was able to see the prepare oplog entry. And surprisingly the problem goes away if I do a find first before calling fillWriterVectors(). milkie, do you see anything obviously wrong with the use of getStorageInterface()->insertDocument?

Comment by Eric Milkie [ 26/Aug/19 ]

Before the code gets to runOpPtrsInitialSync, though, it calls fillWriterVectors() on each of the ops that was passed to testOpsAreIdempotent(). It is fillWriterVectors() that, when encountering a commit op, does the search in the oplog for the associated oplog entries. This is the problem.

Comment by Lingzhi Deng [ 26/Aug/19 ]

I don't think idempotency tests prepare and commit in the same batch. testOpsAreIdempotent calls runOpPtrsInitialSync which runs multiSyncApply to apply each operation in its own batch.

Comment by Eric Milkie [ 21/Aug/19 ]

I don't think that commit would fix this problem; I think the test code is still wrong. I am using the head of master branch and by changing the idempotency_test_fixture to use WiredTiger, the unit tests fail 100% with the error seen in the description, so I think it's a still a problem.

Comment by Judah Schvimer [ 21/Aug/19 ]

milkie, do we know if this got fixed in https://github.com/mongodb/mongo/commit/f14d9c4c07e69c2109de0af059123060c73cdd77#diff-cc663e08c6c92a191f0d876b013d382b? The BF seems to have stopped then.

Generated at Thu Feb 08 05:01:47 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.