spanner: session being used after not found error

[leonsinc]

Client

cloud.google.com/go/spanner v1.40.0

Environment

alpine:3.16.3 Docker on GKE

Go Environment
go version:
go version go1.19.3 linux/amd64

go env:
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.19.3"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build2445852997=/tmp/go-build -gno-record-gcc-switches"

Code
We create a bare-bones default client using the default client config:

dbFullPath := "projects/" + project + "/instances/" + instance + "/databases/" + dbName
clt, err := spanner.NewClient(context.Background(), dbFullPath,
        option.WithCredentialsFile(credentialsFile))

Expected behavior

We expect that the spanner client manages the sessions and handles any errors with sessions not being found by retrying the call with a session that does exist.

Actual behavior

Periodically we see logs from cloud.google.com/go/spanner/session.go saying that there has been an error preparing a session because it hasn't been found.
logf(hc.pool.sc.logger, "Failed to prepare session, error: %v", serr) is the source of the log.
Then at some point in the future, often several hours, a client transaction fails because the session is not found and the session id matches the session that had a preparation failure earlier.
We also see the not found error independent of the failing to prepare error so it is possible they are not linked. It is very often the same one or two session IDs showing up in the logs multiple times in a day.

Logs

2022/12/11 10:21:32 Failed to prepare session, error: spanner: code = "NotFound", desc = "Session not found: projects/project/instances/instance/databases/database/sessions/session id"

15:00:21 spanner: code = "NotFound", desc = "Session not found: projects/project/instances/instance/databases/database/sessions/the same session id"

Additional context

We noticed that we were running close to the 10k limit on active sessions per node and have trimmed some of the clients that were sitting there with the default 100 minimum sessions open and not using them. This seems to have stopped the issue from occurring for now but we would like to know the root cause.

[rahul2393]

Hello @leonsinc
Can you please update the Go client library to 1.42.0 we release a fix related to "Session not found" errors check #7163, Let us know if issue still persists.

[rahul2393]

Closing this since not reproducible in >=v1.42.0