-
Type:
Bug
-
Status: Resolved
-
Priority:
Minor
-
Resolution: Fixed
-
Affects Version/s: None
-
Component/s: Streams
-
Tags:
-
Team:PLATFORM
-
Sprint:nxplatform #101, nxplatform #102, nxplatform #103
-
Story Points:5
This problem has been observed only once, according to MongoDB support the cursor was not closed on server side, this means that our code has called a cursor close and try to get new results after that.
The CursorService used by the scroller should be investigated.
java.lang.IllegalStateException: Cursor has been closed at com.mongodb.internal.operation.QueryBatchCursor.doHasNext(QueryBatchCursor.java:169) ~[mongodb-driver-core-4.7.2.jar:?] at com.mongodb.internal.operation.QueryBatchCursor$ResourceManager.execute(QueryBatchCursor.java:417) ~[mongodb-driver-core-4.7.2.jar:?] at com.mongodb.internal.operation.QueryBatchCursor.hasNext(QueryBatchCursor.java:154) ~[mongodb-driver-core-4.7.2.jar:?] at com.mongodb.client.internal.MongoBatchCursorAdapter.hasNext(MongoBatchCursorAdapter.java:54) ~[mongodb-driver-sync-4.7.2.jar:?] at org.nuxeo.ecm.core.api.CursorResult.hasNext(CursorResult.java:71) ~[nuxeo-core-api-2021.45.8.jar:?] at org.nuxeo.ecm.core.api.CursorService.scroll(CursorService.java:137) ~[nuxeo-core-api-2021.45.8.jar:?] at org.nuxeo.ecm.core.storage.mongodb.MongoDBConnection.scroll(MongoDBConnection.java:912) ~[nuxeo-core-storage-mongodb-2021.45.8.jar:?]
Observed timeline:
21:58:30 Bulk command record read by scroller computation
22:01:22 BBC detected
bulk/scrollerPool-00,in:38,inCheckpoint:38,out:38,lastRead:1699045110705,lastTimer:0,wm:222697240744951809,loop:12456,checkpoint
BBC: 56e5576f-6506-4546-ba60-b021ac241808 (Big Bulk Command) detected, scrolling more than 50000 items:
org.nuxeo.ecm.core.bulk.message.BulkCommand@26352fca[
action=migration, batchSize=25, batchTransactionTimeout=0, bucketSize=100, externalScroller=false, genericScroller=false, id=56e5576f-6506-4546-ba60-b021ac241808,
params={migrationId=blob-keys-migration, migrationStep=empty-to-populated},
query=SELECT * FROM Document, Relation WHERE ecm:blobKeys IS NULL
queryLimit=<null>,repository=default,scroller=<null>,username=system].
00:21:00.704
IllegalStateException: Cursor has been closed
bulk/scrollerPool-00,in:38,inCheckpoint:38,out:38,lastRead:1699045110705,lastTimer:0,wm:222697240744951809,loop:12456,checkpoint
The query returns more than 50k (BBC detection threshold) but less than 1m (flush downstream threshold not traced).
Mongodb was saturated on IOPS (doing an idx fullscan of 170m docs) the query has been traced as slow query and completes few millis before the cursor error:
{"t":{"$date":"2023-11-03T23:21:00.195+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn208271","msg":"Slow query","attr":{"type":"command","ns":"nuxeo.default","appName":"Nuxeo","command":{"getMore":3557687348126376507,"collection":"default","batchSize":200,"$db":"nuxeo","$clusterTime":{"clusterTime":{"$timestamp":{"t":1699045395,"i":2}},"signature":{"hash":{"$binary":{"base64":"***","subType":"0"}},"keyId":7263563826736398354}},"lsid":{"id":{"$uuid":"13199715-e5ff-421f-aac9-7da31176e388"}}},
"originatingCommand":{"find":"default","filter":{"$and":[{"ecm:blobKeys":null},{"ecm:primaryType":"$in":"TemplateRoot",...]}}]},"projection":"ecm:id":1.0},"batchSize":200,"maxTimeMS":172798000,"$db":"nuxeo","$clusterTime":{"clusterTime":{"$timestamp":{"t":1699045265,"i":23}},"signature":{"hash":{"$binary":{"base64":"1D+/ehPGoCOLrtyi808KbgGO/xw=","subType":"0"}},"keyId":7263563826736398354}},"lsid":{"id":{"$uuid":"13199715-e5ff-421f-aac9-7da31176e388"}}},
"planSummary":"IXSCAN{ecm:primaryType:1","cursorid":3557687348126376507,"keysExamined":170843622,"docsExamined":170843622,"fromMultiPlanner":true,"numYields":501374,"nreturned":200,"reslen":15316,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":501375}},"ReplicationStateTransition":{"acquireCount":{"w":501375}},"Global":{"acquireCount":{"r":501375}},"Database":{"acquireCount":{"r":501375}},"Collection":{"acquireCount":{"r":501375}},"Mutex":{"acquireCount":{"r":1}}},
"storage":{"data":{"bytesRead":1086409504996,"timeReadingMicros":7768809875}},"protocol":"op_msg","durationMillis":8264881}}
