server: use of closed network connection when quiescing

[renatolabs]

During a (likely unrelated to this failure) roachtest, a node is stopped gracefully and restarted with a new binary. In the process of terminating the node, the following panic was observed:

@server/server_http.go:227 ⋮ [T1,n1] 280  close tcp ‹[::]:26258›: ‹use of closed network connection›
@server/server_http.go:227 ⋮ [T1,n1] 280 !goroutine 150 [running]:
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x1)
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0x89
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000816420, {{{0xc00b004a20, 0x24}, {0x0, 0x0}, {0x5a5ba7a, 0x1}, {0x5a5ba7a, 0x1}}, 0x174c0a264829ca96, ...})
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/log/clog.go:262 +0x97
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x6ee4260, 0xc000e0ef00}, 0x2, 0x4, 0x1, 0x0?, {0x59891a6, 0x2}, {0xc001671f10, 0x1, ...})
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x645
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/log.loggerOps.Fatalf(...)
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1378
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/server.startHTTPService.func1({0x6ee4260, 0xc000e0ef00})
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/server/server_http.go:227 +0xbf
@server/server_http.go:227 ⋮ [T1,n1] 280 !github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
@server/server_http.go:227 ⋮ [T1,n1] 280 !created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
@server/server_http.go:227 ⋮ [T1,n1] 280 ! github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

For reference, this happened while running a roachtest that has not been merged to master yet [1], but it's quite likely this crash is unrelated to that. A similar failure has also been observed in a different roachtest [2], although we don't see the same panic logs in that case [2].

Apologies for the lack of artifacts here; I have them but they are too large for a GitHub attachment. I can upload them somewhere as needed.

@cockroachdb/obs-inf-prs @cockroachdb/server

[1] #96991
[2] #98436

Jira issue: CRDB-25308

[blathers-crl]

Hi @dhartunian, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[dhartunian]

@knz can you check my understanding here.

First, it seems like the error here doesn't need to call Fatalf. Other places where we close connections in response to shouldQuiesce we log a warning:

cockroach/pkg/server/server_sql.go

Lines 1671 to 1683 in 311c452

	waitQuiesce := func(ctx context.Context) {
	<-stopper.ShouldQuiesce()
	// NB: we can't do this as a Closer because (*Server).ServeWith is
	// running in a worker and usually sits on accept() which unblocks
	// only when the listener closes. In other words, the listener needs
	// to close when quiescing starts to allow that worker to shut down.
	if err := unixLn.Close(); err != nil {
	log.Ops.Warningf(ctx, "closing unix socket: %v", err)
	}
	if err := socketLock.Unlock(); err != nil {
	log.Ops.Warningf(ctx, "removing unix socket lock: %v", err)
	}
	}

Second, connManager.Serve() will itself close the connection in a defer. If we don't want to downgrade the log to a Warningf, then is there a way to guarantee that the connection isn't closed during quiesce? Should I check in advance of closing it? That seems odd too.

[knz]

This can be a warning.

[nicktrav]

I hit this again in a manual roachtest run as part of #97428.

  |   | Error: ERROR: result is ambiguous: error=ba: Put [/Table/112/1/-4732293137230184541/0,/Min), EndTxn(parallel commit) [/Table/112/1/-4732293137230184541/0], [txn: 428b963d], [can-forward-ts] RPC error: grpc: error reading from server: read tcp 10.142.0.54:51128->10.142.0.102:26257: use of closed network connection [code 14/Unavailable] [propagate] (SQLSTATE 40003)
  |   | COMMAND_PROBLEM: ssh verbose log retained in ssh_075738.008347902_n10_cockroach-workload-r.log: exit status 1