-
Type:
Bug
-
Resolution: Fixed
-
Priority:
Major - P3
-
Affects Version/s: None
-
Component/s: None
-
None
-
(copied to CRM)
-
3
-
Storage - Ra 2020-11-02, Storage - Ra 2020-11-16, Storage - Ra 2020-11-30, Storage - Ra 2020-12-14, Storage - Ra 2020-12-28, Storage - Ra 2021-05-17, Storage - Ra 2021-05-31, Storage - Ra 2021-06-14, Storage - Ra 2021-06-28, Storage - Ra 2021-07-12, Storage - Ra 2021-07-26
-
v5.0, v4.4
In a recent build failure, MongoDB hit an error when trying to perform a rollback to stable due to active transactions running in the system.
Some debugging information was posted on the original build failure which showed that the transaction was doing a search_near at "read uncommitted" which corresponds to a history store operation. My hunch is that this is a transaction that is created by an eviction thread doing some history store work and it happens to be running concurrently to a rollback_to_stable thread from a MongoDB application thread.
MongoDB log:
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 I ROLLBACK 23991 [BackgroundSync] "Rolling back to the stable timestamp","attr":{"stableTimestamp":{"$timestamp":{"t":1594775434,"i":5}},"initialDataTimestamp":{"$timestamp":{"t":1594775432,"i":1}}}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 E STORAGE 22435 [BackgroundSync] "WiredTiger error","attr":{"error":22,"message":"[1594775434:929642][92130:0x7f949a9a1700], txn rollback_to_stable: __rollback_to_stable_check, 972: rollback_to_stable illegal with active transactions: Invalid argument"}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F - 23093 [BackgroundSync] "Fatal assertion","attr":{"msgid":31049,"error":"UnrecoverableRollbackError: Error rolling back to stable. Err: Invalid argument","file":"src/mongo/db/repl/storage_interface_impl.cpp","line":1258}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F - 23094 [BackgroundSync] "\n\n***aborting after fassert() failure\n\n"
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.935+0000 d22030| 2020-07-15T01:10:34.929+00:00 F CONTROL 4757800 [BackgroundSync] "Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}
[js_test:rollback_recovery_commit_transaction_before_stable_timestamp] 2020-07-15T01:10:34.939+0000 d22032| 2020-07-15T01:10:34.938+00:00 I REPL 21079 [BackgroundSync] "bgsync - stopReplProducer fail point enabled. Blocking until fail point is disabled."
Debugging information:
[js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I STORAGE 22430 [BackgroundSync] "WiredTiger message","attr":{"message":"Transaction state of active sessions:"}
[js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I STORAGE 22430 [BackgroundSync] "WiredTiger message","attr":{"message":"ID: 0, pinned ID: 4554, metadata pinned ID: 4551, name: EMPTY"}
[js_test:upgrade_downgrade_cluster] 2020-07-01T08:26:23.541+0000 c20278| 2020-07-01T08:26:23.541+00:00 I STORAGE 22430 [BackgroundSync] "WiredTiger message","attr":{"message":"transaction id: 0, mod count: 0, snap min: 4551, snap max: 4554, snapshot count: 1, commit_timestamp: (1593591983, 1), durable_timestamp: (1593591983, 1), first_commit_timestamp: (1593591983, 1), prepare_timestamp: (0, 0), pinned_durable_timestamp: (1593591983, 1), read_timestamp: (0, 0), checkpoint LSN: [0][0], full checkpoint: false, rollback reason: , flags: 0x00000408, isolation: WT_ISO_SNAPSHOT"}
- causes
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- duplicates
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- is related to
-
-
- Closed
-
-
-
- Closed
-
- related to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-