[SERVER-60764] Change stream getMore still reports non-zero cursor ID in response including invalidate event Created: 15/Oct/21  Updated: 06/Dec/22

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

Type: Bug Priority: Major - P3
Reporter: Jeremy Mikola Assignee: Backlog - Query Execution
Resolution: Unresolved Votes: 0
Labels: change-streams-improvements
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Assigned Teams:
Query Execution
Operating System: ALL
Participants:

 Description   

While testing the PHP driver against a "latest" server build (5.1.0-alpha-1523-g565f818), I noticed a change in how mongos responds to a getMore on a change stream cursor.

The test in question does the following:

  • creates a collection (not sharded)
  • opens a change stream on that collection
  • drops the collection
  • advances the cursor until an operation is encountered

On 5.0.x and earlier, the final getMore observed in this test reports zero for the cursor ID; however, 5.1.0 still reports a non-zero value. Is that an intentional change? Bypassing mongos to the same test against the replica set shard directly still reports the cursor ID as zero, so this appears to only happen with mongos.

Note: in the logs below, I've omitted some extra fields (e.g. lsid, $clusterTime) to save space.

5.0.2 command log

The following was observed using a sharded cluster (backed by replica sets) running mongodb-linux-x86_64-enterprise-ubuntu2004-5.0.2. On 5.0.2 and earlier server versions, the getMore response including the "drop" and "invalidate" events reports zero as the cursor ID, which signals to the driver that the cursor has been closed on the server side and that no more iteration is possible.

command: {
    "getMore": 5141813473153987695,
    "collection": "WatchFunctionalTest.4e48a302",
    "maxTimeMS": 500,
    "$db": "phplib_test"
}
 
reply: {
    "cursor": {
        "id": 5141813473153987695,
        "ns": "phplib_test.WatchFunctionalTest.4e48a302",
        "nextBatch": [],
        "postBatchResumeToken": {
            "_data": "82616A00BD000000062B0229296E04"
        }
    },
    "ok": 1
}
 
command: {
    "getMore": 5141813473153987695,
    "collection": "WatchFunctionalTest.4e48a302",
    "maxTimeMS": 500,
    "$db": "phplib_test"
}
 
reply: {
    "cursor": {
        "id": 0,
        "ns": "phplib_test.WatchFunctionalTest.4e48a302",
        "nextBatch": [
            {
                "_id": {
                    "_data": "82616A00BD0000000F2B022C0100296E5A10048510AB446C2F471FBF1AF36623B03F1F04"
                },
                "operationType": "drop",
                "clusterTime": {
                    "$timestamp": {
                        "t": 1634336957,
                        "i": 15
                    }
                },
                "ns": {
                    "db": "phplib_test",
                    "coll": "WatchFunctionalTest.4e48a302"
                }
            },
            {
                "_id": {
                    "_data": "82616A00BD0000000F2B022C0100296F5A10048510AB446C2F471FBF1AF36623B03F1F04"
                },
                "operationType": "invalidate",
                "clusterTime": {
                    "$timestamp": {
                        "t": 1634336957,
                        "i": 15
                    }
                }
            }
        ],
        "postBatchResumeToken": {
            "_data": "82616A00BD000000112B0229296E04"
        }
    },
    "ok": 1
}

5.1.0 command log

The following was observed using a sharded cluster (backed by replica sets) running mongodb-linux-x86_64-enterprise-ubuntu2004-5.1.0-alpha-1523-g565f818. Here, the second response with a "drop" and "invalidate" events still includes a cursor ID. This suggests that the cursor is still alive on the server side, despite the "invalidate" event (presumably, there's no reason for the driver or application to iterate beyond an "invalidate" event).

command: {
    "getMore": 3138377033263876049,
    "collection": "WatchFunctionalTest.4e48a302",
    "maxTimeMS": 500,
    "$db": "phplib_test"
}
 
reply: {
    "cursor": {
        "id": 3138377033263876049,
        "ns": "phplib_test.WatchFunctionalTest.4e48a302",
        "nextBatch": [],
        "postBatchResumeToken": {
            "_data": "826169FFC1000000112B0229296E04"
        }
    },
    "ok": 1
}
 
command: {
    "getMore": 3138377033263876049,
    "collection": "WatchFunctionalTest.4e48a302",
    "maxTimeMS": 500,
    "$db": "phplib_test"
}
 
reply: {
    "cursor": {
        "id": 3138377033263876049,
        "ns": "phplib_test.WatchFunctionalTest.4e48a302",
        "nextBatch": [
            {
                "_id": {
                    "_data": "826169FFC1000000192B022C0100296E5A1004F465544733ED4D40BF461DA4C87B53E504"
                },
                "operationType": "drop",
                "clusterTime": {
                    "$timestamp": {
                        "t": 1634336705,
                        "i": 25
                    }
                },
                "ns": {
                    "db": "phplib_test",
                    "coll": "WatchFunctionalTest.4e48a302"
                }
            },
            {
                "_id": {
                    "_data": "826169FFC1000000192B022C0100296F5A1004F465544733ED4D40BF461DA4C87B53E504"
                },
                "operationType": "invalidate",
                "clusterTime": {
                    "$timestamp": {
                        "t": 1634336705,
                        "i": 25
                    }
                }
            }
        ],
        "postBatchResumeToken": {
            "_data": "826169FFC1000000192B022C0100296F5A1004F465544733ED4D40BF461DA4C87B53E504"
        }
    },
    "ok": 1
}



 Comments   
Comment by Jeremy Mikola [ 22/Oct/21 ]

Do the drivers introspect the contents of each change stream message to check whether it's an invalidate? Or did you mean that the user application might stop issuing getMore when they see an invalidate?

I'm not aware of any drivers introspecting documents returned by a change stream. At the very least, that doesn't seem to be discussed in the specification.

I was assuming that an application would stop iterating the change stream after an "invalidate" event. Applications don't have any direct knowledge of when a getMore might be issued. Drivers do so as needed during iteration. If an application simply stops iterating after encountering an "invalidate" event, I expect they might destroy the change stream object and then a driver might issue a killCursors command in an attempt to clean up the cursor (presumed alive because the last seen ID was non-zero). That is generally how drivers handle cursor cleanup for other query cursors. Granted, this isn't really specified anywhere to my knowledge, as we don't have a dedicated cursor spec (Find, getMore and killCursors commands may be the closest thing, but it doesn't really discuss cleanup).

Comment by Bernard Gorman [ 22/Oct/21 ]

I don't expect drivers would have any reason to issue another getMore after an invalidate event

Do the drivers introspect the contents of each change stream message to check whether it's an invalidate? Or did you mean that the user application might stop issuing getMore when they see an invalidate?

a user initiates a change stream, gets an invalidate, and then never issues another getMore, thereby "leaking" cursor resources that will accumulate and never be cleaned up? Or do you think that the periodic cursor reaper would clean up those exhausted change stream cursors?

Change stream cursors are treated just like any other cursor, so the periodic reaper would clean them up once the session expires.

Comment by Kyle Suarez [ 22/Oct/21 ]

Thanks for the further context jmikola, we're going to keep this ticket open for another round of discussion at the next triage.

bernard.gorman, do you see this scenario as a plausible risk: a user initiates a change stream, gets an invalidate, and then never issues another getMore, thereby "leaking" cursor resources that will accumulate and never be cleaned up? Or do you think that the periodic cursor reaper would clean up those exhausted change stream cursors?

Comment by Jeremy Mikola [ 22/Oct/21 ]

kyle.suarez: thanks for confirming. I don't expect drivers would have any reason to issue another getMore after an invalidate event, so I imagine the cursor would either remain open until mongos decides to kill it or the change stream object in the driver gets destroyed and a killCursors is executed (since the last seen cursor ID would have been non-zero). I suppose we can just punt on this for now and revisit if this proves problematic any any driver down the line.

FWIW, The particular PHPLIB test that prompted this ticket was just testing that our driver frees internal resources when the cursor is closed (and we were using an "invalidate" even to trigger that). In this case, the cursor remains open so we're just skipping the test on mongos 5.1+.

Comment by Kyle Suarez [ 22/Oct/21 ]

jmikola, this is a change to the invalidation mechanism that came in from the $changeStream optimization project. As of 5.1, we do not necessarily close the cursor on the same getMore that delivered the invalidate event. The actual cursor closing should occur on the subsequent getMore.

Unless this is causing an actual problem, we are inclined to keep this behavior. CC bernard.gorman

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