Bug querying with offset

[jacobg]

Sorry I don't have a good repro for you because I'm only repro-ing it on my data, but here is a code that seems to clearly demonstrate a bug:

import time

from google.cloud import datastore


def _create_query(ds_client: datastore.Client) -> datastore.Query:
    query = ds_client.query(kind='my-kind')
    query.add_filter(filter=datastore.query.PropertyFilter('active', '=', True))
    query.add_filter(filter=datastore.query.PropertyFilter('account', '=', 111))
    query.add_filter(filter=datastore.query.PropertyFilter('roles', '=', 'w'))
    query.add_filter(filter=datastore.query.PropertyFilter('labels', '=', 222))
    return query


def run():
    ds_client = datastore.Client(project='my-project')

    start = time.time()
    count = 0
    for entity in _create_query(ds_client).fetch():
        count += 1
    end = time.time()
    print(f'Fetched all {count} entities in {end - start} seconds')
    real_count = count

    for offset in range(0, real_count + 2):
        start = time.time()
        count = 0
        for entity in _create_query(ds_client).fetch(offset=offset):
            count += 1
        end = time.time()
        print(f'Fetched at offset={offset} {count} entities in {end - start} seconds')


if __name__ == '__main__':
    run()

In addition, I added two print statements in google/cloud/datastore/query.py's _next_page while loop:

        while (
            response_pb.batch.more_results == _NOT_FINISHED
            and response_pb.batch.skipped_results < query_pb.offset
        ):
            # We haven't finished processing. A likely reason is we haven't
            # skipped all of the results yet. Don't return any results.
            # Instead, rerun query, adjusting offsets. Datastore doesn't process
            # more than 1000 skipped results in a query.
            old_query_pb = query_pb
            query_pb = query_pb2.Query()
            query_pb._pb.CopyFrom(old_query_pb._pb)  # copy for testability
            query_pb.start_cursor = response_pb.batch.skipped_cursor
            query_pb.offset -= response_pb.batch.skipped_results
            print(f'response_pb.batch.skipped_cursor = {response_pb.batch.skipped_cursor}')
            print(f'response_pb.batch.skipped_results = {response_pb.batch.skipped_results}')

            request = {
                "project_id": self._query.project,
                "partition_id": partition_id,
                "read_options": read_options,
                "query": query_pb,
            }
            helpers.set_database_id_to_request(request, self.client.database)

            response_pb = self.client._datastore_api.run_query(
                request=request,
                **kwargs,
            )

This is the output running the script:

Fetched all 16 entities in 1.7923529148101807 seconds
Fetched at offset=0 16 entities in 1.6426568031311035 seconds
Fetched at offset=1 15 entities in 1.7998042106628418 seconds
Fetched at offset=2 14 entities in 1.525015115737915 seconds
Fetched at offset=3 13 entities in 1.4684479236602783 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=4 12 entities in 1.6105940341949463 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=5 11 entities in 1.4919788837432861 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=6 10 entities in 1.6434409618377686 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=7 9 entities in 1.6705551147460938 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=8 8 entities in 1.490036964416504 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=9 7 entities in 1.263127088546753 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=10 6 entities in 1.1788661479949951 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
Fetched at offset=11 5 entities in 1.3047678470611572 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
Fetched at offset=12 4 entities in 1.4790778160095215 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xb4\xa6\x81\xd3\x84\xc7\x88\t\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b''
response_pb.batch.skipped_results = 0
Fetched at offset=13 15 entities in 2.0598793029785156 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xb4\xa6\x81\xd3\x84\xc7\x88\t\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b''
response_pb.batch.skipped_results = 0
Fetched at offset=14 14 entities in 2.045603036880493 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xb4\xa6\x81\xd3\x84\xc7\x88\t\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b''
response_pb.batch.skipped_results = 0
Fetched at offset=15 13 entities in 2.3071401119232178 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xb4\xa6\x81\xd3\x84\xc7\x88\t\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b''
response_pb.batch.skipped_results = 0
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=16 12 entities in 2.1022279262542725 seconds
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xcd\x9e\x8d\xc1\xf7\xb4\xcf\x06\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\x9c\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xda\xc7\xf2\xf9\xab\xbe\xab\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\x80\x80\xf0\xde\xf1\xc5\xdc\x08\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xb4\xa6\x81\xd3\x84\xc7\x88\t\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 1
response_pb.batch.skipped_cursor = b''
response_pb.batch.skipped_results = 0
response_pb.batch.skipped_cursor = b'\n7\x121j\x0cs~my-projectr!\x0b\x12\x14my_kind\x18\xdb\x81\x83\x8c\xb5\x91\xe4\x03\x0c\x18\x00 \x00'
response_pb.batch.skipped_results = 3
Fetched at offset=17 11 entities in 1.9469151496887207 seconds

It seems what happens is that if the while loop that skips results based on offset reaches the end of the actual resultset, then the response returns empty cursor. In that case, what the code should do is realize there are no results and immediately return. However, what the code does instead is move on to run the full query again for one more iteration, then exit the while loop, and fetch and return all the remaining results.

Am I understanding that correctly?

[jacobg]

Actually, maybe the backend is returning no cursor and 0 skipped results before it got through all the results it needs to offset.

It seems to repro when querying on multiple properties, with at least one of them being a list property. It seems to work correctly, if not querying any list property, or if only querying on one list property and nothing else.

Could that mean a backend bug, possibly when querying a list with an offset using zig-zag merge?

[daniel-sanche]

Hey Jacob, just to make sure I'm understanding this right:

• the bug starts in your log at Fetched at offset=13 15 entities, because we'd expect offset+number returned to equal 16. All the previous lines do, but 13 and higher don't.
• You only see this issue when querying against multiple properties, at least one of which is a list
  Is that right?

How did you encounter this bug in your real code? Were you just seeing more results than you were expecting when passing in an offset value?

I can try to build a test case that reproduces this, just want to make sure I'm understanding it first

[jacobg]

Hi @daniel-sanche , Thanks for the reply.

1. Yes, your explanation of the offset issue is correct.
2. Yes, it seems to only occur with a list property and an additional property, when used with offset.

This bug was seen on live data in our project. I wrote a script to create a new kind with some similar form of data, but the bug did not reproduce. It seems to suggest that perhaps it requires a larger amount of data that is not returned in the query in order to expose the bug. My thinking is maybe it has to do with zig-zag merge along with offsets?

I also filed Google Cloud Support case # 52190476. Since you work for Google, I can send you the specific project id, kind, and filter property names that have this issue.

[daniel-sanche]

Ok, interesting. Yeah I just tried to write a system test to reproduce it, but nothing is showing up there. But we do have very limited data in that test project.

I'll keep trying to reproduce, but if you have bandwidth to help narrow it down:

1. If you can help find a minimal reproducible sample, that would help a lot
2. If you're comfortable working with protos, another thing you could try is re-writing your sample to target the autogenerated protobuf API directly. This should tell us if the bug is in the backend, or somewhere in the hand-written library code.
3. Adding some logs into that same protobuf client could also give us some hints about what's going on. It could be useful to print all the request protos there before they're sent, and/or the responses returned

[jacobg]

Hi @daniel-sanche,

I just realized the GCP Console allows GQL queries with an OFFSET, so I tested there, and it produces the correct result! So maybe this is a python-datastore bug?

I posted the test details onto the GCP Support ticket.

[jacobg]

Here is the same test written node.js and it returns the correct result. So this really looks like a python-datastore bug.

const {Datastore} = require('@google-cloud/datastore')

const datastore = new Datastore({ projectId: 'my-project' })

async function runTest () {
    const query = datastore.createQuery('my-kind')
        .filter('active', '=', true)
        .filter('account', '=', 111)
        .filter('roles', '=', 'w')
        .filter('labels', '=', 222)
        .offset(13)
    const [entities, info] = await query.run()
    console.log(`Returned ${entities.length} entities`)
}

runTest()

This code prints the following.

Returned 1 entities

Note there are currently 14 total entities (i.e., without offset). The Python script above currently returns 11 entities with offset of 13.

[jacobg]

So comparing the python implementation to node.js implementation, there is a noticeable difference on the use of the start cursor for skipping offset results.

In node.js, it uses the response's endCursor to set the next startCursor:

        query.start(info.endCursor!).offset(offset - resp.batch.skippedResults);

https://github.com/googleapis/nodejs-datastore/blob/574427a89f8ea126ce76c1732770e247e83f1514/src/request.ts#L1063

But in python, it instead uses the skipped_cursor:

            query_pb.start_cursor = response_pb.batch.skipped_cursor

python-datastore/google/cloud/datastore/query.py

Line 828 in 7fd218b

query_pb.start_cursor = response_pb.batch.skipped_cursor

In the proto file:
https://github.com/googleapis/nodejs-datastore/blob/main/protos/google/datastore/v1/query.proto
those properties are defined as follows:

  // A cursor that points to the position after the last skipped result.
  // Will be set when `skipped_results` != 0.
  bytes skipped_cursor = 3;

  // A cursor that points to the position after the last result in the batch.
  bytes end_cursor = 4;

It seems logically we should use end_cursor since the client is figuring out on its own how much to skip.

And indeed, when monkey patching the python datastore client code to use end_cursor instead of skipped_cursor, it produces the correct result! Does this seem like the exact bug and fix?

[jacobg]

That code was added trying to fix another offset bug over 4 years ago. Perhaps it wasn't a fully correct fix?
#18

[daniel-sanche]

Thanks for your detailed findings this is very helpful! My initial impression is that this does seem like the likely root cause. We'll take a look at this, add some more tests, and make sure this is addressed in the next release.