spanner: timeout / context canceled during getting session

[ericwenn]

Client

Spanner

Environment

Managed Cloud Run

Description
Since upgrading spanner library to v1.43.0 we have started seeing intermittent timeout/context canceled issues when getting sessions, with error message:

timeout / context canceled during getting session.
Enable SessionPoolConfig.TrackSessionHandles if you suspect a session leak to get more information about the checked out sessions.

After this happens once the Spanner client is unable to get any sessions, which means all requests to our service times out after 10s (our configured request deadline), until the instance is restarted.

^Traces from when issue happens, until instance is manually restarted (~4:20 - 4:30).

Looking at the traces does not add more information for debugging. The only culprit is cloud.google.com/go/spanner.Query (9974.995 ms) which seems to block everything.

We have not been able to reproduce this issue consistently, it seems to happen randomly every 1-2 days.

---

When we noticed this first we rolled back to v1.42.0 and have not seen this issue on that version (running in production for ~1 week).

Looking at recent issues in this repository we tried to bump to the unreleased version based on the fix for this issue, but still saw the issues on that commit.

Judging from changes between v1.42.0 and v.1.43.0 these changes seem to be the culprit, but I'm not sure of that.

[rahul2393]

Hello @ericwenn
Can you help with your sessionConfig values, and what type of load distribution you have read:write ratio to help us replicate the issue.

[ericwenn]

We are using the default sessionConfig (ie spanner.NewClient(ctx, "[name]")).
Load distribution is mainly reads.

[rahul2393]

Thanks for quick answer, do you have QPS numbers with 1 client

[ericwenn]

Avg 1 QPS

[jzelinskie]

We've got some reports (mentioned in GitHub above) from folks using v1.42.0

[ericwenn]

@rahul2393 any ideas on this?

[rahul2393]

Hello @ericwenn We are trying to replicate the issue at our end with session config having min/max=1 session, will update here if we find anything.

Feel free to share any code you have to help replicate quickly.

[ericwenn]

Thanks for update. We have unfortunately not be able to replicate this issue consistently.

[ericwenn]

Hello @rahul2393,
After enabling tracking of session handles and waiting for the issue to re-appear we managed to track this down, and likely fix it.

We were opening a ReadOnlyTransaction without closing it after we're done. We are deploying that fix right now, and will keep an eye out.
Everything I said above regarding a specific version being at fault is likely wrong then, since we introduced the broken transaction at around the same time we bumped spanner client.

Off-topic: Do you have any ideas on how to systematically prevent these type of issues, for example when running tests not allowing the spanner client to have open sessions when it is shut down (or similar)?

[rahul2393]

Nice @ericwenn, I think that's the reason I am not able to replicate the issue before because I was closing them in my replication code.

Currently we don't have a way, need to check in other languages if they are handling the scenario.
@olavloite any suggestions? One solution can be to maintain a client state & deferring any operation if its shutting down.

[rahul2393]

@ericwenn Closing this ticket since you already found the issue, will create another ticket for preventing client to open sessions when it is shut down.
Feel free to open this if you feel this issue need more investigation.
Thanks