Google-cloud-php: [Spanner] Query occasionally returns nothing when there should be data

[taka-oyama]

I've been trying to debug this since December last year and haven't had much luck so I'd like to ask for some help.

Environment details

• OS: Debian
• PHP version: 7.2.11
• Package name and version: google/cloud-spanner v1.11.5

When we execute the following query and try to get its rows, sometimes we would get nothing back when it should be returning data.

SELECT * FROM `User` WHERE `userId` = @userId LIMIT 1

We checked GCP Console -> Spanner ->query stats to see if there was some useful info and we found the following. (see arrow)

Total CPU (sec)          1.13
Execution count          8371
Avg latency (sec)   0.001
Avg CPU (sec)           0.000
Avg rows scanned         1.00 <-- 
Avg rows returned        1.00 <--
Avg bytes returned        382

If there was something wrong with the data/query this should show a number lower than 1.00 so I'm thinking this is a bug on the client side.

Since we know the data exists, we added some code that will retry the query if it returns nothing.
After retrying the query, we get data back.

This is really hard for me to debug since it only happens once in a while (like once or twice a day with around 5000 executions) but I'm guessing it has something to do with the retry mechanism.

Specifically, I think the code below might have something to do with it.
https://github.com/googleapis/google-cloud-php/blob/master/Spanner/src/Result.php#L175

Please let me know what you think. Thanks.

[taka-oyama]

Btw, code on our end looks something like below.

$result = $database->execute($query, $options);
$generator = $result->rows();
$rows = iterator_to_array($generator);

[jdpedrie]

I know you may be constrained if the problem is only apparent in production, but are you in a situation where you could enable query profiling and log the result when the case of the query returning empty arises?

$result = $db->execute($sqlString, [
    'queryMode' => Result::MODE_PROFILE
]);

$rows = iterator_to_array($res->rows());
if (!$rows) {
    // replace with something to log the data.
    log($result->stats());
}

If possible, this would show us at the time of execution whether Cloud Spanner is finding the row.

I've contacted the Spanner team to see if they have seen anything similar before. I'll try to setup a test and see if I can duplicate the issue.

[taka-oyama]

Hi, I didn't know queries could be profiled. I will re-test tomorrow with this on.
Thank you!

[taka-oyama]

This error happened again today with the Result::MODE_PROFILE on.
I added some logs to further diagnose the case and I noticed the following.

1. this line was executed once before the empty was returned
2. $result->stats() returned null.
3. iterator_to_array($results->rows()) returned [].

Still not sure what is happening but just a follow up on the issue.

[jdpedrie]

Thanks for that information @taka-oyama. We're investigating this as well and will update you when we find something!

[taka-oyama]

So I edited Result::row() method to look like below...

$bufferedResults = [];
$call = $this->call;
$generator = $call();
$shouldRetry = false;
$didRetry = false;
$backoff = new ExponentialBackoff($this->retries, function (ServiceException $ex) use (&$didRetry) {
    logger()->critical("RETRIED SPANNER QUERY valid check: ".$ex);
    if($ex->getCode() === Grpc\STATUS_UNAVAILABLE) {
        $didRetry = true;
        return true;
    }
    return false;
});

$valid = $backoff->execute([$generator, 'valid']);

if (!$valid && $didRetry) {
    logger()->critical("Valid returned false for some reason");
}

...

and saw that $backoff->execute([$generator, 'valid']); is returning false on the second try.

[taka-oyama]

I saw a few more of these errors today and I'm starting to see a pattern.

It seems like this happens whenever Google\Cloud\Core\Exception\ServiceException: { "message": "Socket closed", "code": 14, "status": "UNAVAILABLE", "details": [] } is returned while processing $backoff->execute([$generator, 'valid']);

[taka-oyama]

Hi, thank you for looking into the issue with priority.
Please let me know if you need any additional information.

[jdpedrie]

Hi @taka-oyama, sorry for the quiet. We're working on this (it's my top priority task) and hopefully will have an answer quite soon.

[jdpedrie]

Hi @taka-oyama, I just opened #1674 to fix this issue. I'm sorry it's taken a while, the simplicity of the fix does not reflect the difficulties in figuring out the problem. :)

Please take a look and let me know what you think!

[taka-oyama]

I understand. Thank you for the fix!
I will patch the code with this fix and try it out today.

[taka-oyama]

We ran the patched version for a whole day and didn't encounter any errors.
I think we'll run it for another day and if nothing happens, we'll close this issue.

[taka-oyama]

I haven't seen any errors for 2 days now.
I think it's good to go!
Thank you!

[taka-oyama]

Oops, should I not close this until it's merged?

[dwsupplee]

@taka-oyama You're good! Thank you for confirming the change. We should be able to get a release out early next week.