[SERVER-34204] Tailable cursor fails on getMore against a sharded cluster Created: 30/Mar/18  Updated: 29/Oct/23  Resolved: 30/Apr/18

Status: Closed
Project: Core Server
Component/s: Querying, Sharding
Affects Version/s: None
Fix Version/s: 3.6.8, 4.0.0-rc0

Type: Bug Priority: Critical - P2
Reporter: Jeffrey Yemin Assignee: Charlie Swanson
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
is depended on by JAVA-2830 Re-enable tests after SERVER-34204 is... Closed
Duplicate
is duplicated by SERVER-33701 Change streams can send getMores with... Closed
is duplicated by SERVER-34509 lsid-related error on getMore command... Closed
Problem/Incident
causes PYTHON-1533 Test Failure - test_change_stream.Tes... Closed
Related
related to SERVER-32064 A logical session id should be includ... Closed
is related to SERVER-36212 getMore should not enforce that sessi... Closed
is related to SERVER-33367 Enforce a cursor is iterated in a tra... Closed
is related to SERVER-35084 change_stream_enforce_max_time_ms_on_... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.6
Sprint: Query 2018-04-23, Query 2018-05-07
Participants:

 Description   

A getMore command on tailable cursor fails against a sharded cluster with error code 50737 and the error message

Cannot run getMore on cursor 64893492584, which was created in session 3ef6563a-9883-4ba8-8fa2-d42cca34030b - 47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=, without an lsid'.

The sequence of commands and responses were:

{ "find" : "test", "filter" : { }, "tailable" : true, "awaitData" : true, "$db" : "test", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1522368868, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } }, "lsid" : { "id" : { "$binary" : "PvZWOpiDS6iPotQsyjQDCw==", "$type" : "04" } } }
{ "cursor" : { "firstBatch" : [{ "_id" : { "$oid" : "5abd7f7b8ed66ff6dbf0dd10" } }, { "_id" : { "$oid" : "5abd7f988ed66ff6dbf0dd11" } }], "id" : { "$numberLong" : "6209935563551417631" }, "ns" : "test.test" }, "ok" : 1.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1522368868, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } }, "operationTime" : { "$timestamp" : { "t" : 1522368865, "i" : 1 } } }
 
{ "getMore" : { "$numberLong" : "6209935563551417631" }, "collection" : "test", "$db" : "test", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1522368868, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } }, "lsid" : { "id" : { "$binary" : "PvZWOpiDS6iPotQsyjQDCw==", "$type" : "04" } } }
{ "cursor" : { "id" : { "$numberLong" : "6209935563551417631" }, "ns" : "test.test", "nextBatch" : [] }, "ok" : 1.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1522368870, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } }, "operationTime" : { "$timestamp" : { "t" : 1522368870, "i" : 1 } } }
 
{ "getMore" : { "$numberLong" : "6209935563551417631" }, "collection" : "test", "$db" : "test", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1522368870, "i" : 1 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } }, "lsid" : { "id" : { "$binary" : "PvZWOpiDS6iPotQsyjQDCw==", "$type" : "04" } } }

In some cases it fails on the second getMore, in some cases the third, but otherwise the behavior appears consistent.

The collection is capped with otherwise default values. In particular, the collection itself is not sharded (not even sure you can created a sharded capped collection...)

You can see from the commands that the query executes in a session.

Reproduced on a sharded cluster with two shards (each a single member replica set) with MongoDB Enterprise version 3.7.3-198-g8f75de8 on OS X, but it started appearing in Evergreen some time after 2/19.



 Comments   
Comment by Githook User [ 22/Aug/18 ]

Author:

{'name': 'Charlie Swanson', 'email': 'charlie.swanson@mongodb.com', 'username': 'cswanson310'}

Message: SERVER-34204 Always pass non-null opCtx when scheduling getMores in ARM

(cherry picked from commit a43fe9ae73752fbd98107cef5421341fe291ab32)
Branch: v3.6
https://github.com/mongodb/mongo/commit/e1f4285c2f918c70e52ac99e5285d1179c04d2a0

Comment by David Storch [ 26/Jul/18 ]

jack.mulrow, thanks for raising this. We're going to look into whether this can be backprted to 3.6. In addition, we think it may be worthwhile to gate getMore logical session id checks behind featureCompatibilityVersion: SERVER-36212.

Comment by Jack Mulrow [ 18/Jul/18 ]

I ran into this when backporting SERVER-32064 to 4.0 because the last-stable mongos suite (which uses a 3.6 mongos and 3.6 and 4.0 shards) can hit this problem, even though getMores don't verify session ids in 3.6. I had to blacklist a few change streams tests from that suite, so I'm requesting a 3.6 backport to allow re-enabling the tests at some point.

Comment by Githook User [ 01/May/18 ]

Author:

{'email': 'charlie.swanson@mongodb.com', 'name': 'Charlie Swanson', 'username': 'cswanson310'}

Message: SERVER-34204 Always pass non-null opCtx when scheduling getMores in ARM
Branch: master
https://github.com/mongodb/mongo/commit/a43fe9ae73752fbd98107cef5421341fe291ab32

Comment by Githook User [ 30/Apr/18 ]

Author:

{'email': 'charlie.swanson@mongodb.com', 'username': 'cswanson310', 'name': 'Charlie Swanson'}

Message: SERVER-34204 Always pass non-null opCtx when scheduling getMores in ARM
Branch: master
https://github.com/mongodb/mongo/commit/a43fe9ae73752fbd98107cef5421341fe291ab32

Comment by Charlie Swanson [ 30/Mar/18 ]

This is because we can schedule a getMore after receiving the response from a previous getMore. If the response comes in at a time between client getMores we will not have an OperationContext associated with the AsyncResultsMerger, so there will be no session id attached to any scheduled commands.

I believe this is where the problematic getMore is being sent, from within the response handler from a previous getMore.

async_results_merger.cpp

562
    // If the cursor is tailable and we just received an empty batch, the next return value should
563
    // be boost::none in order to indicate the end of the batch. We do not ask for the next batch if
564
    // the cursor is tailable, as batches received from remote tailable cursors should be passed
565
    // through to the client as-is.
566
    // (Note: tailable cursors are only valid on unsharded collections, so the end of the batch from
567
    // one shard means the end of the overall batch).
568
    if (_params->tailableMode == TailableMode::kTailable && !remote.hasNext()) {
569
        invariant(_remotes.size() == 1);
570
        _eofNext = true;
571
    } else if (!remote.hasNext() && !remote.exhausted() && _lifecycleState == kAlive) {
572
        // If this is normal or tailable-awaitData cursor and we still don't have anything buffered
573
        // after receiving this batch, we can schedule work to retrieve the next batch right away.
574
        remote.status = _askForNextBatch(lk, remoteIndex);
575
    }
576
}

Comment by Tess Avitabile (Inactive) [ 30/Mar/18 ]

My guess is that the mongos is not always attaching the lsid for the getMores it sends to the shard.

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