cli: logconfig reset panic due to race condition in `cockroach version`

[davepacheco]

Describe the problem

While trying to reproduce #82958, I found a case where cockroach version exited with status 2. Thinking maybe it would be reproducible, I started running that in a loop. I've found two different panics so far. There's this one (in oxidecomputer/omicron#1282):

fatal error: panic while printing panic value

goroutine 1 [running]:
runtime.throw(0x5a32586, 0x20)
        /opt/ooce/go-1.16/src/runtime/panic.go:1117 +0x72 fp=0xc00103f040 sp=0xc00103f010 pc=0x10a9512
runtime.preprintpanics.func1()
        /opt/ooce/go-1.16/src/runtime/panic.go:661 +0x56 fp=0xc00103f068 sp=0xc00103f040 pc=0x10d9a96
runtime.call16(0x0, 0x608e030, 0x0, 0x0)
        /opt/ooce/go-1.16/src/runtime/asm_amd64.s:550 +0x3e fp=0xc00103f088 sp=0xc00103f068 pc=0x10e1abe
runtime.reflectcallSave(0xc00103f1c0, 0x608e030, 0x0, 0x0)
        /opt/ooce/go-1.16/src/runtime/panic.go:877 +0x58 fp=0xc00103f0b8 sp=0xc00103f088 pc=0x10a8ad8
runtime.runOpenDeferFrame(0xc000000180, 0xc0010a8000, 0xc00103f208)
        /opt/ooce/go-1.16/src/runtime/panic.go:851 +0x62d fp=0xc00103f140 sp=0xc00103f0b8 pc=0x10a87ad
panic(0x52cd740, 0x6ee49d0)
        /opt/ooce/go-1.16/src/runtime/panic.go:965 +0x1b9 fp=0xc00103f208 sp=0xc00103f140 pc=0x10a8d59
runtime.panicmakeslicecap(...)
        /opt/ooce/go-1.16/src/runtime/slice.go:31
runtime.makeslice(0x5164c20, 0x0, 0x6f726b636f632fb5, 0x107c0c5)
        /opt/ooce/go-1.16/src/runtime/slice.go:95 +0xe5 fp=0xc00103f238 sp=0xc00103f208 pc=0x10c2125
strings.(*Builder).grow(...)
        /opt/ooce/go-1.16/src/strings/builder.go:68
strings.(*Builder).Grow(...)
        /opt/ooce/go-1.16/src/strings/builder.go:82
strings.Join(0xc0010a4000, 0x18, 0x1a, 0x59bb460, 0x3, 0x52ff600, 0x526d300)
        /opt/ooce/go-1.16/src/strings/strings.go:434 +0x4e7 fp=0xc00103f310 sp=0xc00103f238 pc=0x113d667
gopkg.in/yaml%2ev2.(*TypeError).Error(0xc000800048, 0x526d300, 0xc000800048)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/gopkg.in/yaml.v2/yaml.go:294 +0x59 fp=0xc00103f368 sp=0xc00103f310 pc=0x1b366f9
runtime.preprintpanics(0xc00103f448)
        /opt/ooce/go-1.16/src/runtime/panic.go:667 +0xa9 fp=0xc00103f3c8 sp=0xc00103f368 pc=0x10a7e69
panic(0x526d300, 0xc000800048)
        /opt/ooce/go-1.16/src/runtime/panic.go:1063 +0x552 fp=0xc00103f490 sp=0xc00103f3c8 pc=0x10a90f2
github.com/cockroachdb/cockroach/pkg/util/log/logconfig.DefaultConfig(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/logconfig/config.go:74 +0x105 fp=0xc00103f4f0 sp=0xc00103f490 pc=0x1b3a6c5
github.com/cockroachdb/cockroach/pkg/cli.(*logConfigFlags).reset(0xc000efe900)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/cli/log_flags.go:289 +0x37 fp=0xc00103f800 sp=0xc00103f4f0 pc=0x4d72e57
github.com/cockroachdb/cockroach/pkg/cli.setCliContextDefaults()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/cli/context.go:221 +0x16a fp=0xc00103f820 sp=0xc00103f800 pc=0x4d4478a
github.com/cockroachdb/cockroach/pkg/cli.initCLIDefaults()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/cli/context.go:51 +0x193 fp=0xc00103f8a8 sp=0xc00103f820 pc=0x4d43153
github.com/cockroachdb/cockroach/pkg/cli.init.8()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/cli/flags.go:281 +0x37 fp=0xc00103fce8 sp=0xc00103f8a8 pc=0x4d620d7
runtime.doInit(0x9277c00)
        /opt/ooce/go-1.16/src/runtime/proc.go:6315 +0xec fp=0xc00103fe38 sp=0xc00103fce8 pc=0x10b99ec
runtime.doInit(0x92220c0)
        /opt/ooce/go-1.16/src/runtime/proc.go:6292 +0x72 fp=0xc00103ff88 sp=0xc00103fe38 pc=0x10b9972
runtime.main()
        /opt/ooce/go-1.16/src/runtime/proc.go:208 +0x205 fp=0xc00103ffe0 sp=0xc00103ff88 pc=0x10abd25
runtime.goexit()
        /opt/ooce/go-1.16/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc00103ffe8 sp=0xc00103ffe0 pc=0x10e35a1

goroutine 35 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc000119e10)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 34 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc000119d40)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 36 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc000119ee0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 37 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a000)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 38 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a0d0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 39 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a1a0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 40 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a270)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 41 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a340)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 42 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a410)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 43 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a4e0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 44 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a5b0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 45 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a680)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 46 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a750)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 47 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a820)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 48 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a8f0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 49 [chan receive]:
github.com/klauspost/compress/zstd.(*blockDec).startDecoder(0xc00027a9c0)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:215 +0x149
created by github.com/klauspost/compress/zstd.newBlockDec
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/klauspost/compress/zstd/blockdec.go:118 +0x173

goroutine 50 [chan receive]:
github.com/cockroachdb/cockroach/pkg/util/log.flushDaemon()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:75 +0x74
created by github.com/cockroachdb/cockroach/pkg/util/log.init.5
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:41 +0x35

goroutine 51 [chan receive]:
github.com/cockroachdb/cockroach/pkg/util/log.signalFlusher()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:98 +0x12c
created by github.com/cockroachdb/cockroach/pkg/util/log.init.5
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:42 +0x4d

goroutine 53 [syscall]:
os/signal.signal_recv(0x0)
        /opt/ooce/go-1.16/src/runtime/sigqueue.go:168 +0xa5
os/signal.loop()
        /opt/ooce/go-1.16/src/os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
        /opt/ooce/go-1.16/src/os/signal/signal.go:151 +0x45

goroutine 117 [chan receive]:
github.com/cockroachdb/cockroach/pkg/util/goschedstats.init.0.func1()
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/goschedstats/runnable.go:165 +0x16b
created by github.com/cockroachdb/cockroach/pkg/util/goschedstats.init.0
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/goschedstats/runnable.go:157 +0x35

goroutine 119 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc00087bd00)
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/go.opencensus.io/stats/view/worker.go:276 +0xcd
created by go.opencensus.io/stats/view.init.0
        /ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/go.opencensus.io/stats/view/worker.go:34 +0x68

and this one:

panic: invalid predicate with signature *fmt.pp != func(*scpb.Column, scplan.Params) bool for *scpb.Column[0]

goroutine 1 [running]:
github.com/cockroachdb/cockroach/pkg/sql/schemachanger/scplan.buildSchemaChangeOpGenFunc(0x703b2a0, 0x0, 0xc000e0aff0, 0xc000e0b050, 0xc000e08c18)
	/ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/sql/schemachanger/scplan/declarative.go:171 +0xd93
github.com/cockroachdb/cockroach/pkg/sql/schemachanger/scplan.buildSchemaChangePlanner(0xc000e0ab40, 0xc000e0ab40)
	/ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/sql/schemachanger/scplan/declarative.go:60 +0x125
github.com/cockroachdb/cockroach/pkg/sql/schemachanger/scplan.init()
	/ws/gc/cockroach/cache/gopath/src/github.co

These are presumably two different issues and if you want me to file a second one, let me know.

To Reproduce

Just run cockroach version in a loop unti it exits. At first, I just did:

for ((i = 0; ; i++)) { echo "ATTEMPT $i"; cockroach version || break; }

Now I'm using this:

#!/bin/bash

# attempt to reproduce failure from `cockroach version`

# specifies a specific `cockroach` binary
export PATH="$HOME/tools/cockroachdb-v21.2.9/bin:$PATH"

date +%FT%TZ > start_time
which cockroach > which_cockroach

for ((i = 0; ; i++)) {
	echo "ATTEMPT $i"
	echo $i > attempt_number
	cockroach version > stdout 2>stderr
	rv=$?
	if [[ $rv -ne 0 ]]; then
		echo $rv > exit_status
		echo "exited with status $rv";
		break;
	fi
}

Unfortunately in both cases a bug caused me to lose the status code but I've fixed the above script to avoid that.

Both tries took a few days and on the order of a million iterations. More precisely, the second one took just over 53h and 1.4M iterations.

Expected behavior

This should run indefinitely without issue.

Environment:

$ cockroach version
Build Tag:        v21.2.9
Build Time:       2022/04/28 04:02:42
Distribution:     OSS
Platform:         illumos amd64 (x86_64-pc-solaris2.11)
Go Version:       go1.16.10
C Compiler:       gcc 10.3.0
Build Commit ID:  11787edfcfc157a0df951abc34684e4e18b3ef20
Build Type:       release

This is on helios helios-1.0.21004.

Additional context

I'm not that worried about a very rare panic in cockroach version. I wanted to see how reproducible this was because we've been chasing some other thing that looks like memory corruption (see #82958) and I'd hoped it might be related.

Jira issue: CRDB-17219

[blathers-crl]

Hello, I am Blathers. I am here to help you get the issue triaged.

Hoot - a bug! Though bugs are the bane of my existence, rest assured the wretched thing will get the best of care here.

I have CC'd a few people who may be able to assist you:

• @cockroachdb/sql-queries (found keywords: plan)
• @cockroachdb/bulk-io (found keywords: export)
• @nicktrav (commented on crash in Go runtime after port_getn returned EINVAL #82958)
• @knz (commented on crash in Go runtime after port_getn returned EINVAL #82958)

If we have not gotten back to your issue within a few business days, you can try the following:

• Join our community slack channel and ask on #cockroachdb.
• Try find someone from here if you know they worked closely on the area and CC them.

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

[blathers-crl]

cc @cockroachdb/bulk-io

[stevendanna]

The second panic looks like it would be of interest to @cockroachdb/sql-schema

[nicktrav]

cc @knz for triage for the CLI / Logging panic (edit: woops, you were already cc'd).

[knz]

the 2nd panic does indeed look like a SQL schema issue. @davepacheco would you mind filing it separately and cc-ing me on it?

We'll handle the first one separately. Thanks for your report.