[SERVER-77810] UnknownError from watching Change Stream with --verbose=v and large $match filter Created: 05/Jun/23  Updated: 29/Oct/23  Resolved: 05/Jul/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 7.1.0-rc0

Type: Bug Priority: Major - P3
Reporter: Jian Guan Assignee: Romans Kasperovics
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File go.mod     File go.sum     File main.go    
Issue Links:
Issue split
Related
related to SERVER-50761 Create a passthrough suite for fuzzin... Closed
Assigned Teams:
Query Execution
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

1. Start mongod of any version with --verbose flag. For example:

mongod --dbpath xxx --logpath xxx --port 27017 --verbose=v

2. Run the attached Go script. This Go script attempts to watch a change stream with a pipeline filtering 50,000 collections.

The output of the repro script should show UnknownError.

Sprint: QE 2023-06-26, QE 2023-07-10
Participants:

 Description   

An UnknownError is returned from mongod started with verbosity level set explicitly and using Go driver as client instead of `BSONObjectTooLarge`. It is reproducible on v6.0.6 and other versions.

We expect an error similar to

(BSONObjectTooLarge) BSONObj size: 20078112 (0x1325E20) is invalid. Size must be between 0 and 16793600(16MB) First element: aggregate: 1

But the actual error we see is

(UnknownError) assertion src/mongo/util/hex.cpp:113



 Comments   
Comment by Githook User [ 04/Jul/23 ]

Author:

{'name': 'Romans Kasperovics', 'email': 'romans.kasperovics@mongodb.com', 'username': 'romanskas'}

Message: SERVER-77810 Ensure the correct exception in OpMsg::parse()
Branch: master
https://github.com/mongodb/mongo/commit/ac94a93ebda383431bc77ceb15dfa1bcb660d4ef

Comment by Bernard Gorman [ 06/Jun/23 ]

This issue seems to actually be induced by the --verbose flag. Without that flag, I get the BSONObjectTooLarge exception as expected:

$ go run main.go
(BSONObjectTooLarge) BSONObj size: 20078112 (0x1325E20) is invalid. Size must be between 0 and 16793600(16MB) First element: aggregate: 1

But when I restart the replset with --verbose=v, I hit the UnknownError:

$ go run main.go
(UnknownError) assertion src/mongo/util/hex.cpp:113

Note: this is a MONGO_verify assertion failure.

So it seems likely that we’re hitting some limit in the logging subsystem. It's also possible that this doesn't have anything to do with change streams specifically, but could be induced by any sufficiently large filter with the same characteristics as this one.

Interestingly, I tried rewriting the reproducer in Javascript and running it through both mongosh and mongo, but wasn't able to hit the UnknownError in either case. In the former case, trying this with 50k namespaces actually caused mongosh to throw a different (internal) exception:

RangeError: offset is out of bounds

Trying with 40k namespaces produced an error when we try to grow the buffer beyond 64MB:

MongoServerError: Failed to optimize pipeline :: caused by :: BufBuilder attempted to grow() to 67108878 bytes, past the 64MB limit.

The mongo shell, meanwhile, failed to even convert the request into a BSONObj with 50k namespaces:

Error: Converting from JavaScript to BSON failed: Object size 18878075 exceeds limit of 16793600 bytes.

With 40k namespaces, mongo hit the max BSON size limit while optimizing the pipeline:

Failed to optimize pipeline :: caused by :: BufBuilder attempted to grow() to 67108865 bytes, past the 64MB limit.

But again, no UnknownError. So this appears to be some strange interplay between the --verbose=v flag and the command being submitted by the Go driver.

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