spanner: nil pointer exception in session.go

[arhea]

Client

Spanner 1.53.0

Environment

• GKE Container
• gcr.io/distroless/static-debian11 base image
• running as nonroot

Go Environment

go version go1.21.4 linux/amd64

Screenshots

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x14fdc72]

goroutine 79 [running]:
cloud.google.com/go/spanner.(*session).getID(0xc151a28709c51d48?)
	/home/runner/go/pkg/mod/cloud.google.com/go/[email protected]/session.go:341 +0x32
cloud.google.com/go/spanner.(*sessionPool).getLongRunningSessionsLocked(0xc000e83ba0)
	/home/runner/go/pkg/mod/cloud.google.com/go/[email protected]/session.go:734 +0x5f3
cloud.google.com/go/spanner.(*sessionPool).removeLongRunningSessions(0xc000e83ba0)
	/home/runner/go/pkg/mod/cloud.google.com/go/[email protected]/session.go:759 +0x45
cloud.google.com/go/spanner.(*healthChecker).maintainer(0xc000888400)
	/home/runner/go/pkg/mod/cloud.google.com/go/[email protected]/session.go:1517 +0x297
created by cloud.google.com/go/spanner.newHealthChecker in goroutine 1
	/home/runner/go/pkg/mod/cloud.google.com/go/[email protected]/session.go:1324 **+0x136"**

Additional context

Started after upgrading to 1.53.0

[toga4]

Hi, we are facing the same issue and have detected panic in our production environment.

An effective workaround seems to be either downgrading to v1.52.0 or configuring the SessionPoolConfig as follows, ensuring that the problematic processes do not execute as they would in v1.52.0.

spannerClient, err := spanner.NewClientWithConfig(ctx, "projects/.../instances/.../databases/...",
    spanner.ClientConfig{
        SessionPoolConfig: spanner.SessionPoolConfig{
            MaxOpened: spanner.DefaultSessionPoolConfig.MaxOpened,
            MinOpened: spanner.DefaultSessionPoolConfig.MinOpened,
            MaxIdle:   spanner.DefaultSessionPoolConfig.MaxIdle,
            InactiveTransactionRemovalOptions: spanner.InactiveTransactionRemovalOptions{
                ActionOnInactiveTransaction: spanner.NoAction, // or spanner.Close, if you'd like to enable long running transaction clean up
            },
        },
    },
)

[toga4]

The issue seems to be related to the following process, which logs the possibility of a session leak:

google-cloud-go/spanner/session.go

Lines 729 to 744 in 5d5e547

	if (p.ActionOnInactiveTransaction == Warn || p.ActionOnInactiveTransaction == WarnAndClose) && !sh.isSessionLeakLogged {
	if p.ActionOnInactiveTransaction == Warn {
	if sh.stack != nil {
	logf(p.sc.logger, "session %s checked out of pool at %s is long running due to possible session leak for goroutine: \n%s", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339), sh.stack)
	} else {
	logf(p.sc.logger, "session %s checked out of pool at %s is long running due to possible session leak for goroutine: \nEnable SessionPoolConfig.TrackSessionHandles to get stack trace associated with the session", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339))
	}
	sh.isSessionLeakLogged = true
	} else if p.ActionOnInactiveTransaction == WarnAndClose {
	if sh.stack != nil {
	logf(p.sc.logger, "session %s checked out of pool at %s is long running and will be removed due to possible session leak for goroutine: \n%s", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339), sh.stack)
	} else {
	logf(p.sc.logger, "session %s checked out of pool at %s is long running and will be removed due to possible session leak for goroutine: \nEnable SessionPoolConfig.TrackSessionHandles to get stack trace associated with the session", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339))
	}
	}
	}

In this section, sh.session.getID() is used to retrieve the ID from the session in sessionHandler but it appears that in some cases the session may be nil (it seems that the session has already been recycled or destroyed).