[SERVER-30864] Query from system.profile errors when executed on the same mongod Created: 28/Aug/17 Updated: 29/Sep/17 Resolved: 13/Sep/17 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Aggregation Framework, Diagnostics |
| Affects Version/s: | 3.4.7, 3.5.12 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Henrik Ingo (Inactive) | Assignee: | David Storch |
| Resolution: | Cannot Reproduce | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Operating System: | ALL | ||||||||||||
| Participants: | |||||||||||||
| Description |
|
Short version: I successfully execute an aggregation framework query, which is logged into system.profile. Copy pasting the pipeline from system.profile back into the mongo shell, and executing against the same mongod instance, fails with various errors. Example error:
The aggregation pipeline originally comes from the tpch test suite of sqlproxy. I will post a more detailed repro in a dev-only comment. |
| Comments |
| Comment by Henrik Ingo (Inactive) [ 15/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
It appears that mongo shell not supporting the extended json strict mode is actually documented feature: https://docs.mongodb.com/manual/reference/mongodb-extended-json/#input-in-strict-mode I'm waiting for more info from drivers people to understand why / what to expect. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Henrik Ingo (Inactive) [ 15/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Followup for the ns bug: | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Henrik Ingo (Inactive) [ 13/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi David I've figured out what the problem is. If you simply launch a mysql shell, copy paste the SQL query into it, then open a mongo shell and do db.system.profile.find(), it will give you the format that works. (In that sense, this SERVER ticket can indeed be closed as cannot reproduce.) The problematic format
...is returned when using the generate_tpch_agg_queries.py script. It seems the python driver serializes the returned BSON differently from the mongo shell. And in particular, the format returned by the python driver is not useable as a mongodb query. At least not if copy pasted into a shell. An interesting question is whether the captured query would work if used over the python driver? I can take it upon myself to find a driver person and file whatever ticket should be filed based on this finding. IMO a user should be able to expect that the same mongodb query (in json) works in the shell as well as all drivers. I also figured out the other errors I have mentioned in this ticket. nreturned The value of nreturned in your above system.profile snippet was 101, but mongosqld actually returned 460 rows. This is because there is an additional getMore entry in the system.profile, where the additional 359 documents are returned. So this matches up. ns The ns field in your above snippet has the value tpch.mongo_supplier. This is wrong. If you do db.mongo_supplier.aggregate() with the above pipeline, it will return zero documents. The correct collection is mongo_part. Note that this bug reproduces also if you simply execute the pipeline with db.mongo_part.aggregate(), it will record mongo_supplier in the system.profile. You don't need mongosqld to reproduce. The getMore entry correctly has tpch.mongo_part as the namespace. I will file a new SERVER ticket about the ns issue tomorrow, if you don't do it today. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Storch [ 13/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I am closing this ticket as Cannot Reproduce, since I am not able to generate such a log entry when running TPC-H query 1 against the denormalized dataset. I tried with several versions of mongod and mongosqld but could not reproduce the issue. I've left some details below of the steps I took:
The query succeeds and appears to generate a valid profile entry. On 3.4.5, here was the output from the profiler:
I can also successfully run the profiled command against the server using the mongo shell. henrik.ingo, if you have further guidance on how to reproduce this issue, feel free to re-open the ticket. ryan.chipman, one thing I did notice is that the mongosqld logs appear to contain the invalid $regex format noted by Henrik. The very same query which produced the profile entry above contains this invalid $match in the logs:
Perhaps there is a sqlproxy issue at play here? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Henrik Ingo (Inactive) [ 11/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
If this thread isn't helpful, please arrange a conf call with me so we can walk through it. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ian Whalen (Inactive) [ 08/Sep/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
henrik.ingo going through this with the Query team and wondering if you have an easy way to reproduce this? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Henrik Ingo (Inactive) [ 29/Aug/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Ah, I see. Here's the output of "query 1", which is the query failing with the regex, as output when running generate_tpch_agg_queries.py:
It goes on for quite a while. Also, if you look at the full system.profile record in tpch.js, you'll see that it returned 101 records, as well as examined even more, took a number of locks, etc.
Finally, I should re-iterate that also the queries that don't result in a parse error, nevertheless return 0 documents. Hence I suspect those queries are wrong as well, compared to what was executed, when the query did return records. The expected number of records of course is what is recorded in nreturned key in the system.profile entry. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Storch [ 29/Aug/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
henrik.ingo, I'm not sure that this quite answers my question. The profiler entry certainly contains an invalid query, though currently there is no data to support that the query which generated this profiler entry was not itself invalid. Do you have any evidence which proves that the query issued from mongosqld to mongod succeeded, despite generating an invalid profile entry? My current hypothesis is that the query which generated the profiler entry itself failed with "$regex has to be a string". | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Henrik Ingo (Inactive) [ 29/Aug/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
david.storch The full query is attached in tpch.query2.js. It's one of the queries - the second - I've gotten as a result of using the script from you, in the linked (and non-public) ticket. Specifically, I tried executing mongosqld against mongod 3.4.7 and then verified that the same 3.4.7 could not execute the query that it itself had logged into system.profile. It seems that other versions of mongod have the same issue, but for the purpose of filing this bug, I was extra pedantic about checking with 3.4.7. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by David Storch [ 29/Aug/17 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I'm re-opening this issue, since it doesn't look like a duplicate of
This should instead be written like so:
henrik.ingo, could you help me understand how to reproduce this problem? Specifically, could you provide the MongoDB query which caused this profiler entry to be generated? That should help us spot the problem. |