[SERVER-71691] Error 5643004 when using $setWindowFields in a facet Created: 30/Nov/22  Updated: 29/Oct/23  Resolved: 09/Jan/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 5.0.13, 6.0.3
Fix Version/s: 5.0.15, 6.0.4, 6.3.0-rc0, 6.2.0-rc6

Type: Bug Priority: Major - P3
Reporter: Gianluca Nitti Assignee: Alyssa Clark
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Assigned Teams:
Query Execution
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v6.2, v6.0, v5.0
Steps To Reproduce:

The following is the most minimal example I've been able to set up which shows the bug.

I have the following collection:

sometestdb> db.densifyDateExample.find()
[
  { _id: 'a', d: ISODate("2022-10-28T22:00:00.000Z") },
  { _id: 'b', d: ISODate("2022-10-29T22:00:00.000Z") },
  { _id: 'c', d: ISODate("2022-10-30T23:00:00.000Z") },
  { _id: 'd', d: ISODate("2022-10-31T23:00:00.000Z") },
  { _id: 'e', d: ISODate("2022-11-01T23:00:00.000Z") },
  { _id: 'f', d: ISODate("2022-11-02T23:00:00.000Z") }
] 

The following pipeline results in the error:

db.densifyDateExample.aggregate({
    "$facet": {
        "facet1": [{
            "$setWindowFields": {
                "output": {
                    "prevId": {
                        "$shift": {
                            "by": -1,
                            "default": null,
                            "output": "$_id"
                        }
                    }
                },
                "sortBy": {
                    "_id": 1
                }
            }
        }],
        "facet2": [{
            "$group": {
                "_id": {
                    $hour: "$d"
                }
            }
        }]
    }
})

With the server log file containing:

{"t":{"$date":"2022-11-30T09:40:35.681+01:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn22","msg":"Slow query","attr":{"type":"command","ns":"sometestdb.densifyDateExample","appName":"mongosh 1.2.3","command":{"explain":{"aggregate":"densifyDateExample","pipeline":[{"$facet":{"facet1":[{"$setWindowFields":{"output":{"prevId":{"$shift":{"by":-1,"default":null,"output":"$_id"}}},"sortBy":{"_id":1}}}],"facet2":[{"$group":{"_id":{"$hour":"$d"}}}]}}],"cursor":{}},"verbosity":"allPlansExecution","lsid":{"id":{"$uuid":"39dd7c2f-2e49-40ae-aeda-b696ba5d8993"}},"$db":"sometestdb"},"planSummary":"COLLSCAN","numYields":0,"queryHash":"17830885","queryFramework":"classic","ok":0,"errMsg":"Requested document not in SpillableCache. Expected range was 0--1 but got 0","errName":"Location5643004","errCode":5643004,"reslen":166,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":2}}},"storage":{},"remote":"127.0.0.1:57374","protocol":"op_msg","durationMillis":282}}
 

The following pipelines both return the expected result without errors:

db.densifyDateExample.aggregate({
    "$facet": {
        "facet1": [{
            "$setWindowFields": {
                "output": {
                    "prevId": {
                        "$shift": {
                            "by": -1,
                            "default": null,
                            "output": "$_id"
                        }
                    }
                },
                "sortBy": {
                    "_id": 1
                }
            }
        }]
    }
}) 

db.densifyDateExample.aggregate({
    "$facet": {
        "facet2": [{
            "$group": {
                "_id": {
                    $hour: "$d"
                }
            }
        }]
    }
}) 

I'm using MongoDB 6.0.3-29-g3568ba7 on CentOS 7.

Sprint: QE 2023-01-09, QE 2023-01-23
Participants:

 Description   

When running an aggregation pipeline with a $facet stage where one of the sub-pipelines contains a $setWindowFields stage, the execution fails with the following error:

MongoServerError: PlanExecutor error during aggregation :: caused by :: Requested document not in SpillableCache. Expected range was 0--1 but got 0 

The server log file reports the error code 5643004 (see "steps to reproduce" for more detail). If one of the two facets is removed,everything works as expected.



 Comments   
Comment by Gianluca Nitti [ 17/Jan/23 ]

Hello, I just tried my use cases on MongoDB server version: 6.0.4-rc0-4-g92f6cdf (as shown in mongosh) and everything now works properly regardless of facets order.

Thanks for fixing.

Comment by Githook User [ 10/Jan/23 ]

Author:

{'name': 'Alyssa Wagenmaker', 'email': 'alyssa.wagenmaker@mongodb.com', 'username': 'awagenmaker'}

Message: SERVER-71691 handle paused execution in setWindowFields
Branch: v6.2
https://github.com/mongodb/mongo/commit/35832bd3cbfba591689688af6589558432a6bc85

Comment by Githook User [ 09/Jan/23 ]

Author:

{'name': 'Alyssa Wagenmaker', 'email': 'alyssa.wagenmaker@mongodb.com', 'username': 'awagenmaker'}

Message: SERVER-71691 handle paused execution in setWindowFields
Branch: v5.0
https://github.com/mongodb/mongo/commit/1af5a0c2ef50aaecc32ff165fb90b69020ad9964

Comment by Githook User [ 09/Jan/23 ]

Author:

{'name': 'Alyssa Wagenmaker', 'email': 'alyssa.wagenmaker@mongodb.com', 'username': 'awagenmaker'}

Message: SERVER-71691 handle paused execution in setWindowFields
Branch: v6.0
https://github.com/mongodb/mongo/commit/9634296064c60f12d3d8055fbb101109143967a5

Comment by Githook User [ 06/Jan/23 ]

Author:

{'name': 'Alyssa Wagenmaker', 'email': 'alyssa.wagenmaker@mongodb.com', 'username': 'awagenmaker'}

Message: SERVER-71691 handle paused execution in setWindowFields
Branch: master
https://github.com/mongodb/mongo/commit/4544c162b4b60ac383d94d2ffba33f373dd2571b

Comment by Alyssa Clark [ 05/Jan/23 ]

This is caused by $setWindowFields not accounting for the possibility of execution being temporarily paused due to the other pipeline still needing to process results from the input source shared by the two. It only hits this case when it is before another pipeline, hence why the other pipeline's existence and ordering mattered. As a fix, the window pipeline stage needs to be able to detect execution being paused and propagate that state to its caller.

Comment by Chris Kelly [ 22/Dec/22 ]

Hi Gianluca,

Thanks for your report! I was able to reproduce this issue on 5.0.13 and 6.0.3.

  • It appears to rely on $setWindowFIelds being the first facet. The error does not appear if it's the 2nd facet instead.
  • It appears to behave this way regardless of what is passed in to the 2nd facet thereafter.

I'll pass this on to the relevant team to take a look.

 

Christopher

Comment by Gianluca Nitti [ 30/Nov/22 ]

This seems to be the same problem reported in this discussion, which got no follow-up: https://www.mongodb.com/community/forums/t/group-and-sum-add-all-greater-than/181319

 

Indeed, also in my example shown above exchanging the order of the facets (facet2 before facet1) solves the issue, however a) I believe this is still a problem (the order of facets should not be relevant - the documentation for $facet says "These sub-pipelines are completely independent of one another") and b) I have more complex examples where the pipeline fails no matter what the order of the facets is.

Generated at Thu Feb 08 06:19:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.