[CDRIVER-3770] Extra getMore is sent when a tailable cursor receives an empty initial batch Created: 05/Aug/20  Updated: 15/Apr/22

Status: Backlog
Project: C Driver
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Kevin Albertson Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
is depended on by PHPC-1409 Rewinding cursor should never invoke ... Blocked

 Description   

Discovered in PHPC-1409. I was able to reproduce this behavior with a test program.

1. Create a capped collection in the shell and insert a document. (Note, creating a tailable/awaitData to an empty capped collection appears to always return a closed id=0 cursor)

db.createCollection("capped", {capped: true, size: 10000})
db.capped.insert({x:1})

2. Create a tailable/awaitData cursor in libmongoc with a filter matching nothing in the capped collection.
3. Iterate once with mongoc_cursor_next.

APM events show the extra getMore.

2020/08/05 13:24:12.0356: [64909]:    DEBUG:       mongoc: begin: first call to mongoc_cursor_next
2020/08/05 13:24:12.0359: [64909]:    DEBUG:       mongoc: command_started: { "find" : "capped", "filter" : { "match_nothing" : { "$numberInt" : "1" } }, "tailable" : true, "awaitData" : true, "$db" : "test", "$readPreference" : { "mode" : "primaryPreferred" }, "lsid" : { "id" : { "$binary" : { "base64": "ha69vxrBQfqNXR6p70xcYA==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType" : "00" } }, "keyId" : { "$numberLong" : "0"} } } }
2020/08/05 13:24:12.0360: [64909]:    DEBUG:       mongoc: command_succeeded: { "cursor" : { "firstBatch" : [  ], "id" : { "$numberLong" : "171857474237404106"}, "ns" : "test.capped" }, "ok" : { "$numberDouble" : "1.0" }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType" : "00" } }, "keyId" : { "$numberLong" : "0"} } }, "operationTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } } }
2020/08/05 13:24:12.0449: [64909]:    DEBUG:       mongoc: command_started: { "getMore" : { "$numberLong" : "171857474237404106"}, "collection" : "capped", "$db" : "test", "$readPreference" : { "mode" : "primaryPreferred" }, "lsid" : { "id" : { "$binary" : { "base64": "ha69vxrBQfqNXR6p70xcYA==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType" : "00" } }, "keyId" : { "$numberLong" : "0"} } } }
2020/08/05 13:24:13.0454: [64909]:    DEBUG:       mongoc: command_succeeded: { "cursor" : { "nextBatch" : [  ], "id" : { "$numberLong" : "171857474237404106"}, "ns" : "test.capped" }, "ok" : { "$numberDouble" : "1.0" }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType" : "00" } }, "keyId" : { "$numberLong" : "0"} } }, "operationTime" : { "$timestamp" : { "t" : 1596648251, "i" : 1 } } }
2020/08/05 13:24:13.0454: [64909]:    DEBUG:       mongoc: end: first call to mongoc_cursor_next


Generated at Wed Feb 07 21:18:58 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.