[SERVER-40685] Mongos often fails transactions that use "snapshot" with SnapshotTooOld Created: 16/Apr/19  Updated: 05/Nov/19  Resolved: 17/May/19

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.1.11
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Shane Harvey Assignee: Dianna Hohensee (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File PYTHON-1796.py    
Issue Links:
Depends
depends on SERVER-36956 Replace the statistic that dynamicall... Closed
is depended on by CSHARP-2629 Remove workaround for SERVER-40685 Closed
Problem/Incident
causes PYTHON-1796 Transaction tests that use readConcer... Closed
Related
related to CDRIVER-3301 Unskip txn tests with readConcern=sna... Closed
is related to PYTHON-1901 Avoid using readConcern snapshot in s... Closed
is related to CSHARP-2601 Fix consistently failing convenient a... Closed
is related to SERVER-41472 Create a workload to demonstrate the ... Closed
is related to RUBY-1942 Avoid using readConcern snapshot in s... Closed
Operating System: ALL
Steps To Reproduce:
  1. Start a sharded cluster
  2. Still to be determined: Do an unknown sequence of operations that causes the cluster to be in a "bad state". I was only able to repro the issue after running the entire driver test suite against the cluster.
  3. Run PYTHON-1796.py
Sprint: Storage NYC 2019-05-20, Sharding 2019-05-06
Participants:
Linked BF Score: 45

 Description   

Various driver transaction spec tests are failing on latest sharded clusters. The one commonality between the failures is that they all use read concern "snapshot" and they all fail with SnapshotTooOld on the first operation in the transaction. Was there a recent change in how "snapshot" works?

Although this issue fails consistently in Evergreen, creating a standalone repro has proven difficult. When starting a fresh sharded cluster the attached repro (PYTHON-1796.py) succeeds. However if I run the entire driver test suite against the cluster first, then the repro starts failing consistently with SnapshotTooOld. Here's an example evergreen failure from today:
https://evergreen.mongodb.com/task/mongo_python_driver_tests_python_version_supports_openssl_110_test_ssl__auth_ssl~auth_ssl_python_version_requires_openssl_102_plus~3.7_test_latest_sharded_cluster_ea8941ef5d3f60a227cb89021ef7d65d7b06c6e1_19_04_16_21_00_56

And here's the repro failing:

$ python PYTHON-1796.py
First transaction command failed: {'ok': 0.0, 'errmsg': 'Transaction 060cae38-7be3-4240-babe-65739200884c:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27019 during a transaction :: caused by :: Read timestamp Timestamp(1555453221, 10) is older than the oldest available timestamp.', 'code': 239, 'codeName': 'SnapshotTooOld', 'operationTime': Timestamp(1555453221, 11), '$clusterTime': {'clusterTime': Timestamp(1555453221, 11), 'signature': {'hash': b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', 'keyId': 0}}, 'errorLabels': ['TransientTransactionError']}
Traceback (most recent call last):
  File "PYTHON-1796.py", line 13, in <module>
    coll.insert_one({'_id': i}, session=s)
  File "/home/ubuntu/mongo-python-driver/pymongo/collection.py", line 694, in insert_one
    session=session),
  File "/home/ubuntu/mongo-python-driver/pymongo/collection.py", line 608, in _insert
    bypass_doc_val, session)
  File "/home/ubuntu/mongo-python-driver/pymongo/collection.py", line 596, in _insert_one
    acknowledged, _insert_command, session)
  File "/home/ubuntu/mongo-python-driver/pymongo/mongo_client.py", line 1342, in _retryable_write
    return self._retry_with_session(retryable, func, s, None)
  File "/home/ubuntu/mongo-python-driver/pymongo/mongo_client.py", line 1295, in _retry_with_session
    return func(session, sock_info, retryable)
  File "/home/ubuntu/mongo-python-driver/pymongo/collection.py", line 591, in _insert_command
    retryable_write=retryable_write)
  File "/home/ubuntu/mongo-python-driver/pymongo/pool.py", line 579, in command
    unacknowledged=unacknowledged)
  File "/home/ubuntu/mongo-python-driver/pymongo/network.py", line 150, in command
    parse_write_concern_error=parse_write_concern_error)
  File "/home/ubuntu/mongo-python-driver/pymongo/helpers.py", line 155, in _check_command_response
    raise OperationFailure(msg % errmsg, code, response)
pymongo.errors.OperationFailure: Transaction 060cae38-7be3-4240-babe-65739200884c:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27019 during a transaction :: caused by :: Read timestamp Timestamp(1555453221, 10) is older than the oldest available timestamp.

I can reproduce this on the latest version:
db version v4.1.10-94-ga654dcf
git version: a654dcf592ea7ed65426a0de96b4079ff4fc6716



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

Author:

{'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}

Message: test: skip broken transaction tests until SERVER-40685 is fixed
Branch: master
https://github.com/mongodb/node-mongodb-native/commit/4075b4462e57ac63fa6da39dc5b06922c8b9e3e9

Comment by Githook User [ 03/Nov/19 ]

Author:

{'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}

Message: test: skip broken transaction tests until SERVER-40685 is fixed
Branch: NODE-2274/unified-failover-server-loss
https://github.com/mongodb/node-mongodb-native/commit/060b90f18ee4bdde88b082184fc195e44b0dc79f

Comment by Githook User [ 03/Nov/19 ]

Author:

{'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}

Message: test: skip broken transaction tests until SERVER-40685 is fixed
Branch: NODE-2274/unified-failover-server-loss
https://github.com/mongodb/node-mongodb-native/commit/471b1d04a96d2b50447ff1fdd76b253be14f94ad

Comment by Githook User [ 03/Nov/19 ]

Author:

{'username': 'mbroadst', 'email': 'mbroadst@mongodb.com', 'name': 'Matt Broadstone'}

Message: test: skip broken transaction tests until SERVER-40685 is fixed
Branch: NODE-2274/unified-failover-server-loss
https://github.com/mongodb/node-mongodb-native/commit/78acb682a8a1ee9e109e10495c47573edf399414

Comment by Githook User [ 29/Jul/19 ]

Author:

{'name': 'Oleg Pudeyev', 'email': '39304720+p-mongo@users.noreply.github.com', 'username': 'p-mongo'}

Message: RUBY-1868 skip tests on server 4.2 that fail due to SERVER-40685 (#1465)
Branch: 2.10-stable
https://github.com/mongodb/mongo-ruby-driver/commit/495d92412c2e5f1230b0e6a5bc5db368e3ba4f72

Comment by Githook User [ 26/Jul/19 ]

Author:

{'name': 'Oleg Pudeyev', 'username': 'p-mongo', 'email': '39304720+p-mongo@users.noreply.github.com'}

Message: RUBY-1868 skip tests on server 4.2 that fail due to SERVER-40685 (#1465)
Branch: master
https://github.com/mongodb/mongo-ruby-driver/commit/80647682794f3e1e5e28024f81d796450712f14f

Comment by Dianna Hohensee (Inactive) [ 11/Jul/19 ]

So I've spoken with Aly about this, and we've determined the best course of action would be for one of you to file a HELP ticket and assign it to Aly. She has all the context to sort out what's going on, from where errors are coming and can help sort out what to do about them.

One thing that's clearly weird about the error message is that it says "a non-retryable snapshot error" when SnapshotTooOld errors ("Read timestamp Timestamp(1562100752, 11) is older than the oldest available timestamp") were intended to be retryable transient transaction errors. So that seems like one thing that will need to be fixed on the mongodb side.

Comment by Bernie Hackett [ 11/Jul/19 ]

My mistake. The failures for Python started on 7/2, not 6/27. This seems to only be happening with 4.3.x (latest at the time of the test run). This version worked fine on 6/27:

 [2019/06/27 21:48:18.393] db version v4.3.0-396-g9dbbb44
 [2019/06/27 21:48:18.393] git version: 9dbbb4457fe9b55175303b9f08249e4bd7df3875
 [2019/06/27 21:48:18.393] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013

This version started the failures on 7/2:

 [2019/07/02 16:42:36.889] db version v4.3.0-443-gd9c06a3
 [2019/07/02 16:42:36.889] git version: d9c06a3b01175bc277a85052a6cc3fcfb2bdebc4
 [2019/07/02 16:42:36.889] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013

I can't pinpoint the version any better since there were no commits to PyMongo between those two days.

The error message:

[2019/07/02 16:53:24.589] OperationFailure: Transaction d0d37161-b81d-453b-ac0f-6d3de0bf893f:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Read timestamp Timestamp(1562100752, 11) is older than the oldest available timestamp.

Comment by Dianna Hohensee (Inactive) [ 11/Jul/19 ]

behackett, dmitry.lukyanov, can you specify what mongo commit you were using for those tests? So July 2nd and 4th for Dmitry, and 6/26 for Bernie.

I made a change to the snapshot window size controls (which can affect the success of transactions ops run through a mongos with 'snapshot' read concern) that was committed on July 1st. We have not seen any new test failures on our end, but I want to rule out or in whether those changes had an affect on the Drivers.

Comment by Bernie Hackett [ 10/Jul/19 ]

I'm seeing this in PyMongo's tests since 6/26. What change needs to be made in drivers?

Comment by Dmitry Lukyanov (Inactive) [ 08/Jul/19 ]

>Perhaps we could change them all to majority without reducing driver's test coverage in a significant way.

not sure that we can do it since some tests validate exactly correctness of using `snapshot` option.

NOTE:

Comment by Jeffrey Yemin [ 08/Jul/19 ]

dmitry.lukyanov on which operations are the snapshot test options specified? Perhaps we could change them all to majority without reducing driver's test coverage in a significant way.

Comment by Dmitry Lukyanov (Inactive) [ 08/Jul/19 ]

milkie, as we discussed a little bit in the SERVER-41532, I'm also faced with the error from this ticket on the `latest sharded` environments (in tests which use the `snapshot` read concern level).

https://evergreen.mongodb.com/task_log_raw/dot_net_driver_unsecure_tests__version~latest_os~windows_64_topology~sharded_cluster_auth~noauth_ssl~nossl_test_patch_385bb3b0be82ba8c053580acf86d327738a13a37_5d233951d6d80a40ea856b2b_19_07_08_12_38_58/0?type=T#L2281

Exception message:

System.Exception : Unexpected exception was thrown. [2019/07/08 08:58:59.221] ---- MongoDB.Driver.MongoCommandException : Command   insert failed: Transaction fc7eb662-2ba1-4a57-90d3-39a579b72cee:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27217 during a transaction :: caused by :: Read timestamp Timestamp(1562590739, 13) is older than the oldest available timestamp..

NOTE: When I replaced all `snapshot` test options on `majority`, all tests have passed.

Could you please advise how can I solve/work around this error?

cc: rstam
cc: jeff.yemin

Comment by Eric Milkie [ 26/Jun/19 ]

Until SERVER-39704 is complete, drivers will need to either build-in retries for this specific error, or should adjust their test framework to avoid this error. We can work together on crafting a way to avoid this error if you still have tests that are failing.

Comment by Robert Stam [ 25/Jun/19 ]

I'm still getting this error when using `4.2.0-rc1`.

System.Exception : Unexpected exception was thrown.
---- MongoDB.Driver.MongoCommandException : Command insert failed: Transaction 36bac0a6-4be1-4b1c-8aa3-9da030e03c81:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27019 during a transaction :: caused by :: Read timestamp Timestamp(1561471969, 142) is older than the oldest available timestamp..

The command was an `insert` command.

 

Comment by Dianna Hohensee (Inactive) [ 07/Jun/19 ]

rstam I would be interested in what command you were trying to run that caused that "Read timestamp Timestamp(1559767078, 78) is older than the oldest available timestamp" error.

I know that transaction commands through mongos do not currently retry transient transaction errors (SERVER-39704), but your error says non-retryable, which I would not expect to be attached to a command response.

Comment by Jeffrey Yemin [ 05/Jun/19 ]

And if it is expected, can you suggest any workarounds for automated driver tests that are encountering this issue.

Comment by Robert Stam [ 05/Jun/19 ]

dianna.hohensee I just got this error today when running the C# driver test suite:

System.Exception : Unexpected exception was thrown.
---- MongoDB.Driver.MongoCommandException : Command insert failed: Transaction 8d460683-3914-4520-8eaf-d2d2b81054bc:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27019 during a transaction :: caused by :: Read timestamp Timestamp(1559767078, 78) is older than the oldest available timestamp..

If this ticket is closed would you expect a client to still see this error?

 

Comment by Robert Stam [ 05/Jun/19 ]

milkie pointed out to me that if you look far enough to the right in the error message that this is actually a different error.

I've created a new SERVER ticket for the new error:

SERVER-41532

Comment by Eric Milkie [ 05/Jun/19 ]

rstam I don't think that error is related to this ticket? That error response can result from trying to read at a point-in-time that is too close to a DDL operation time (such as a drop or create index).

Comment by Robert Stam [ 05/Jun/19 ]

dianna.hohensee I just encountered this error today using server version 4.1.11-165-g1c9d985.

"Command insert failed: Transaction 3a15840d-e673-4fb1-b4a8-dad5bef4231f:1 was aborted on statement 0 due to: a non-retryable snapshot error :: caused by :: Encountered error from localhost:27019 during a transaction :: caused by :: Unable to read from a snapshot due to pending collection catalog changes; please retry the operation. Snapshot timestamp is Timestamp(1559738408, 3). Collection minimum is Timestamp(1559738412, 8)."

Comment by Shane Harvey [ 23/May/19 ]

I can confirm that the python driver has not hit this issue since this ticket was closed. Thanks!

Comment by Dianna Hohensee (Inactive) [ 23/May/19 ]

shane.harvey, could you get confirmation that the problem seen by the python driver has been resolved? I want to make sure this is all set for RC0.

Comment by Dianna Hohensee (Inactive) [ 17/May/19 ]

SERVER-36956 has been committed. I believe this problem should now be resolved.

Previously, any cache pressure would prevent the snapshot window size from increasing, as well as decrease the size down to zero. The cache pressure metric was also not reliable, as Randolph pointed out above.

Now, SnapshotTooOld errors always cause the window size to increase (up the to max setting, which is configurable and defaults to 5 seconds), regardless of cache pressure. Also, instead of using the cache lookaside score to determine cache pressure, we are tracking writes to the cache overflow table (WT lookaside table, persisted on disk).

Comment by Eric Milkie [ 07/May/19 ]

I linked a ticket in our backlog that will be replacing the current scoring statistic with something better.

Comment by Randolph Tan [ 07/May/19 ]

Here's what I found while investigating the build failure. It looks like the cache lookaside score we used to determine whether WT cache is under pressure gets to a high number, and the startPeriodicThreadToDecreaseSnapshotHistoryCachePressure thread starts to decrease the snapshot window from the default of 5 seconds to eventually 0 seconds. The score doesn't appear to go down even after committing transactions. After discussing with keith.bostic and louis.williams, it appears that the score is updated during eviction and it is possible for the score to remain at a high value even though it is no longer under pressure. Sending to storage team to re-evaluate the heuristics to use in the snapshot history cache pressure thread.

Comment by Siyuan Zhou [ 03/May/19 ]

This issue has been causing lots of failures in BF-12756 and BF-12986? matthew.saltz kaloian.manassiev, it would be great if we could prioritize the fix.

Comment by Dianna Hohensee (Inactive) [ 19/Apr/19 ]

This lists and explains all the controls (server parameters) for the history window https://github.com/mongodb/mongo/blob/master/src/mongo/db/snapshot_window_options.h

There are also serverStatus fields in the 'wiredtiger' section that will show you what the current settings are of those options at runtime, as described in this comment https://jira.mongodb.org/browse/SERVER-31767?focusedCommentId=1875613&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-1875613

Basically, we have a targetSnapshotHistoryWindowInSeconds server parameter setting that we use when going to set the oldest timestamp: the oldest timestamp lags the stable timestamp by 'targetSnapshotHistoryWindowInSeconds' seconds. The targetSnapshotHistoryWindowInSeconds will move between 0 and maxTargetSnapshotHistoryWindowInSeconds depending on cache pressure and and SnapshotTooOld cmd errors. We have a periodic task to check for cache pressure and decrease the target window size if found; and we catch SnapshotTooOld errors from commands to prompt increases of targetSnapshotHistoryWindowInSeconds – if there's no cache pressure.

We were not sure what the default settings should be for the server parameters, so that might be worth altering and seeing if the problem persists. It's also possible that our cache pressure gauge is having trouble: if the snapshot window is 0 in your repro and refuses to increase, that might be the problem.

Comment by Kaloian Manassiev [ 19/Apr/19 ]

dianna.hohensee, can you remind us how long was the default history window that WT keeps around and how is this configured?

I am thinking there are two possibilities:

  • MongoS somehow selects a very old timestamp for the snapshot read
  • The test is too heavy and somehow we exceed the WT history window

I am putting this on the sharding team's backlog, because it looks like legitimate problem with using sharded transactions.

Generated at Thu Feb 08 04:55:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.