ccl/sqlproxyccl: TestDirectoryConnect failed

[cockroach-teamcity]

ccl/sqlproxyccl.TestDirectoryConnect failed with artifacts on release-23.1 @ 624d9dea7f1296af60d16bbb45cc9d1259b3a1be:

Fatal error:

panic: test timed out after 4m55s

Stack:

goroutine 42056 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

* created by github.com/cockroachdb/pebble.(*tableCacheShard).init
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:314 +0xef
* 
* goroutine 34864 [chan receive, 2 minutes]:
* github.com/cockroachdb/pebble.(*tableCacheShard).releaseLoop.func1({0x7439140, 0xc00ac98510})
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:324 +0x9f
* runtime/pprof.Do({0x74390d0?, 0xc00022a000?}, {{0xc000166a00?, 0xc0050fb180?, 0xc0050fb1d0?}}, 0xc00207c7a8)
* 	GOROOT/src/runtime/pprof/runtime.go:40 +0xa3
* github.com/cockroachdb/pebble.(*tableCacheShard).releaseLoop(0x0?)
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:322 +0x58
* created by github.com/cockroachdb/pebble.(*tableCacheShard).init
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:314 +0xef
* 
* goroutine 34746 [select]:
* github.com/cockroachdb/cockroach/pkg/util/admission.initWorkQueue.func2()
* 	github.com/cockroachdb/cockroach/pkg/util/admission/work_queue.go:388 +0x86
* created by github.com/cockroachdb/cockroach/pkg/util/admission.initWorkQueue
* 	github.com/cockroachdb/cockroach/pkg/util/admission/work_queue.go:385 +0x33f
* 
* goroutine 34741 [select, 2 minutes]:
* github.com/cockroachdb/cockroach/pkg/util/log.(*fileSink).gcDaemon(0xc00772b2b0, {0x7439098, 0xc001cd79c0})
* 	github.com/cockroachdb/cockroach/pkg/util/log/file_log_gc.go:25 +0x7f
* created by github.com/cockroachdb/cockroach/pkg/util/log.ApplyConfig
* 	github.com/cockroachdb/cockroach/pkg/util/log/flags.go:306 +0x10aa
* 
* goroutine 34737 [sleep]:
* time.Sleep(0x4c4b40)
* 	GOROOT/src/runtime/time.go:195 +0x135
* github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Quiesce(0xc00790b080, {0x74390d0?, 0xc00022a000})
* 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:584 +0x1a5
* github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Stop(0xc00790b080, {0x74390d0, 0xc00022a000})
* 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:526 +0x11d
* github.com/cockroachdb/cockroach/pkg/ccl/sqlproxyccl.TestDirectoryConnect(0xc006f49380)
* 	github.com/cockroachdb/cockroach/pkg/ccl/sqlproxyccl/proxy_handler_test.go:1447 +0xc8f
* testing.tRunner(0xc006f49380, 0x6204ef8)
* 	GOROOT/src/testing/testing.go:1446 +0x10b
* created by testing.(*T).Run
* 	GOROOT/src/testing/testing.go:1493 +0x35f
* 
* goroutine 34794 [chan receive, 2 minutes]:
* github.com/cockroachdb/pebble.(*tableCacheShard).releaseLoop.func1({0x7439140, 0xc008f172f0})
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:324 +0x9f
* runtime/pprof.Do({0x74390d0?, 0xc00022a000?}, {{0xc000166a00?, 0xc003d2d810?, 0xc006d235b0?}}, 0xc0015c97a8)
* 	GOROOT/src/runtime/pprof/runtime.go:40 +0xa3
* github.com/cockroachdb/pebble.(*tableCacheShard).releaseLoop(0xc0084aa720?)
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:322 +0x58
* created by github.com/cockroachdb/pebble.(*tableCacheShard).init
* 	github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/table_cache.go:314 +0xef
* 
*

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/sql-foundations @cockroachdb/server

This test on roachdash | Improve this report!

Jira issue: CRDB-29014

[jeffswenson]

This was fixed on master by #101864.

[jeffswenson]

The change I thought fixed this was already back ported before this flake.

[jeffswenson]

WIP work on deflaking the test is contained in #106549. I stumbled on another bug that shows up once every 1k attempts under --stress.

The main symptoms are:

1. The test times out with zero failed connection attempts (the connection is stuck).
2. The sql proxy is blocked on this line

   cockroach/pkg/ccl/sqlproxyccl/backend_dialer.go

   Line 60 in 2eac0f0

   if _, err = io.ReadFull(conn, response); err != nil {

   .
3. There is no stack in the sql server that suggests the sql server accepted the connection.

I suspect the root cause is the tenant directory cache contains a stale entry for the tenant and something (probably the new sql server's http server but could be something outside the test harness) is listening on the port. This causes the tcp dial to succeed but connection setup gets stuck during the negotiation phase because the recipient does not understand the postgres tls negotiation protocol. There is a time out inside the sql proxy for dialing a connection, but there is no time out for negotiating ssl.