test_paginated_single_column_descending is flaky

[ahl]

See: https://buildomat.eng.oxide.computer/wg/0/details/01FQF2458RQ7G2VFKJRVBRRZK9/rdBWzehf1zRLzuNhI9iAokOFh33iGAWV7WqKZQNhv4eh5F4g/01FQF24K9BW4YFS4YKB2P2SMD2

3154 | 2021-12-21T18:24:03.885Z | ---- db::pagination::test::test_paginated_single_column_descending stdout ----
-- | -- | --
3155 | 2021-12-21T18:24:03.891Z | log file: "/tmp/omicron_nexus-af7cc18609452f5b-test_paginated_single_column_descending.3657.7.log"
3156 | 2021-12-21T18:24:03.896Z | note: configured to log to "/tmp/omicron_nexus-af7cc18609452f5b-test_paginated_single_column_descending.3657.7.log"
3157 | 2021-12-21T18:24:03.902Z | thread 'db::pagination::test::test_paginated_single_column_descending' panicked at 'called `Result::unwrap()` on an `Err` value: Exited', /work/oxidecomputer/omicron/test-utils/src/dev/mod.rs:119:42
3158 | 2021-12-21T18:24:03.908Z | note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[davepacheco]

FWIW, this seems to affect many tests (presumably all of them) that create a test database.

[davepacheco]

We're blowing the assertion here in setup_database():

118     info!(&log, "cockroach command line: {}", starter.cmdline());
119     let database = starter.start().await.unwrap();

We're unexpectedly getting CockroachStartError::Exited while trying to start CockroachDB. That variant is only used here:

omicron/test-utils/src/dev/db.rs

Line 335 in 2e6586b

CockroachStartError::Exited,

At this point, we've forked cockroach and we're waiting for it to write out its listen-url file. But instead, it exits.

I think this may be a slightly different failure mode than we saw last week but I'm not positive.

[davepacheco]

Of course, we'd like to know what cockroachdb emitted to stdout and stderr when this happened. Those outputs are redirected to files in the temporary directory. While we go out of our way to preserve the temporary directory in the case where we timed out waiting for CockroachDB, we don't do that when CockroachDB just exits. I'm fixing this in #545.

[davepacheco]

With #545 (really, from commit f6b7da2 in that PR), I attempted to repro this using:

$ for (( i = 0; ; i++ )) { echo "attempt: $(( i + 1 ))"; cargo test -p omicron-nexus || break; }
...
failures:

---- integration_tests::instances::test_instances_delete_fails_when_running_succeeds_when_stopped stdout ----
log file: "/dangerzone/omicron_tmp/test_all-b54c2bba3f34f365-test_instances_delete_fails_when_running_succeeds_when_stopped.18213.18.log"
note: configured to log to "/dangerzone/omicron_tmp/test_all-b54c2bba3f34f365-test_instances_delete_fails_when_running_succeeds_when_stopped.18213.18.log"
thread 'integration_tests::instances::test_instances_delete_fails_when_running_succeeds_when_stopped' panicked at 'called `Result::unwrap()` on an `Err` value: Exited', /home/dap/omicron/test-utils/src/dev/mod.rs:119:42
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    integration_tests::instances::test_instances_delete_fails_when_running_succeeds_when_stopped

test result: FAILED. 39 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 8.84s

error: test failed, to rerun pass '-p omicron-nexus --test test_all'

It took 54 attempts. I wasn't tracking time, but it was less than an hour.

$ echo $i
54

If we follow the log file:

$ bunyan /dangerzone/omicron_tmp/test_all-b54c2bba3f34f365-test_instances_delete_fails_when_running_succeeds_when_stopped.18213.18.log
[2021-12-22T10:49:30.022977969-08:00]  INFO: test_instances_delete_fails_when_running_succeeds_when_stopped/18213 on ivanova: cockroach temporary directory: /dangerzone/omicron_tmp/.tmp1nmMP7
[2021-12-22T10:49:30.023336787-08:00]  INFO: test_instances_delete_fails_when_running_succeeds_when_stopped/18213 on ivanova: cockroach: copying from seed directory
[2021-12-22T10:49:30.040381468-08:00]  INFO: test_instances_delete_fails_when_running_succeeds_when_stopped/18213 on ivanova: cockroach command line: cockroach start-single-node --insecure --http-addr=:0 --store /dangerzone/omicron_tmp/.tmp1nmMP7/data --listen-addr 127.0.0.1:0 --listening-url-file /dangerzone/omicron_tmp/.tmp1nmMP7/listen-url

it points us to the temporary directory:

$ ls -l /dangerzone/omicron_tmp/.tmp1nmMP7/
total 10
-rw-r--r--   1 dap      staff       8976 Dec 22 10:49 cockroachdb_stderr
-rw-r--r--   1 dap      staff          0 Dec 22 10:49 cockroachdb_stdout
drwxr-xr-x   4 dap      staff         18 Dec 22 10:49 data/

Finally we have some stderr!

$ cat /dangerzone/omicron_tmp/.tmp1nmMP7/cockroachdb_stderr 
runtime: marked free object in span 0xfffffc7feea2b2a0, elemsize=208 freeindex=1 (bad use of unsafe.Pointer? try -d=checkptr)
0xc000c16000 alloc marked  
0xc000c160d0 free  unmarked
0xc000c161a0 free  unmarked
0xc000c16270 free  unmarked
0xc000c16340 alloc unmarked
0xc000c16410 free  unmarked
0xc000c164e0 free  unmarked
0xc000c165b0 free  marked   zombie
000000c000c165b0:  0000000000000000  0000000000000000 
000000c000c165c0:  0000000000000000  0000000000000000 
000000c000c165d0:  0000000000000000  0000000000000000 
000000c000c165e0:  0000000000000000  0000000000000000 
000000c000c165f0:  0000000000000000  0000000000000000 
000000c000c16600:  0000000000000000  0000000000000000 
000000c000c16610:  0000000000000000  0000000000000000 
000000c000c16620:  0000000000000000  0000000000000000 
000000c000c16630:  0000000000000000  0000000000000000 
000000c000c16640:  0000000000000000  0000000000000000 
000000c000c16650:  0000000000000000  0000000000000000 
000000c000c16660:  0000000000000000  0000000000000000 
000000c000c16670:  0000000000000000  0000000000000000 
0xc000c16680 alloc marked  
0xc000c16750 alloc marked  
0xc000c16820 alloc unmarked
0xc000c168f0 free  unmarked
0xc000c169c0 alloc marked  
0xc000c16a90 free  marked   zombie
000000c000c16a90:  0000000000000000  0000000000000000 
000000c000c16aa0:  0000000000000000  0000000000000000 
000000c000c16ab0:  0000000000000000  0000000000000000 
000000c000c16ac0:  0000000000000000  0000000000000000 
000000c000c16ad0:  0000000000000000  0000000000000000 
000000c000c16ae0:  0000000000000000  0000000000000000 
000000c000c16af0:  0000000000000000  0000000000000000 
000000c000c16b00:  0000000000000000  0000000000000000 
000000c000c16b10:  0000000000000000  0000000000000000 
000000c000c16b20:  0000000000000000  0000000000000000 
000000c000c16b30:  0000000000000000  0000000000000000 
000000c000c16b40:  0000000000000000  0000000000000000 
000000c000c16b50:  0000000000000000  0000000000000000 
0xc000c16b60 free  unmarked
0xc000c16c30 free  marked   zombie
000000c000c16c30:  0000000000000000  0000000000000000 
000000c000c16c40:  0000000000000000  0000000000000000 
000000c000c16c50:  0000000000000000  0000000000000000 
000000c000c16c60:  0000000000000000  0000000000000000 
000000c000c16c70:  0000000000000000  0000000000000000 
000000c000c16c80:  0000000000000000  0000000000000000 
000000c000c16c90:  0000000000000000  0000000000000000 
000000c000c16ca0:  0000000000000000  0000000000000000 
000000c000c16cb0:  0000000000000000  0000000000000000 
000000c000c16cc0:  0000000000000000  0000000000000000 
000000c000c16cd0:  0000000000000000  0000000000000000 
000000c000c16ce0:  0000000000000000  0000000000000000 
000000c000c16cf0:  0000000000000000  0000000000000000 
0xc000c16d00 free  unmarked
0xc000c16dd0 free  unmarked
0xc000c16ea0 free  marked   zombie
000000c000c16ea0:  0000000000000000  0000000000000000 
000000c000c16eb0:  0000000000000000  0000000000000000 
000000c000c16ec0:  0000000000000000  0000000000000000 
000000c000c16ed0:  0000000000000000  0000000000000000 
000000c000c16ee0:  0000000000000000  0000000000000000 
000000c000c16ef0:  0000000000000000  0000000000000000 
000000c000c16f00:  0000000000000000  0000000000000000 
000000c000c16f10:  0000000000000000  0000000000000000 
000000c000c16f20:  0000000000000000  0000000000000000 
000000c000c16f30:  0000000000000000  0000000000000000 
000000c000c16f40:  0000000000000000  0000000000000000 
000000c000c16f50:  0000000000000000  0000000000000000 
000000c000c16f60:  0000000000000000  0000000000000000 
0xc000c16f70 alloc marked  
0xc000c17040 free  marked   zombie
000000c000c17040:  0000000000000000  0000000000000000 
000000c000c17050:  0000000000000000  0000000000000000 
000000c000c17060:  0000000000000000  0000000000000000 
000000c000c17070:  0000000000000000  0000000000000000 
000000c000c17080:  0000000000000000  0000000000000000 
000000c000c17090:  0000000000000000  0000000000000000 
000000c000c170a0:  0000000000000000  0000000000000000 
000000c000c170b0:  0000000000000000  0000000000000000 
000000c000c170c0:  0000000000000000  0000000000000000 
000000c000c170d0:  0000000000000000  0000000000000000 
000000c000c170e0:  0000000000000000  0000000000000000 
000000c000c170f0:  0000000000000000  0000000000000000 
000000c000c17100:  0000000000000000  0000000000000000 
0xc000c17110 alloc unmarked
0xc000c171e0 free  marked   zombie
000000c000c171e0:  0000000000000000  0000000000000000 
000000c000c171f0:  0000000000000000  0000000000000000 
000000c000c17200:  0000000000000000  0000000000000000 
000000c000c17210:  0000000000000000  0000000000000000 
000000c000c17220:  0000000000000000  0000000000000000 
000000c000c17230:  0000000000000000  0000000000000000 
000000c000c17240:  0000000000000000  0000000000000000 
000000c000c17250:  0000000000000000  0000000000000000 
000000c000c17260:  0000000000000000  0000000000000000 
000000c000c17270:  0000000000000000  0000000000000000 
000000c000c17280:  0000000000000000  0000000000000000 
000000c000c17290:  0000000000000000  0000000000000000 
000000c000c172a0:  0000000000000000  0000000000000000 
0xc000c172b0 alloc unmarked
0xc000c17380 free  unmarked
0xc000c17450 free  unmarked
0xc000c17520 free  unmarked
0xc000c175f0 free  unmarked
0xc000c176c0 free  unmarked
0xc000c17790 free  unmarked
0xc000c17860 free  unmarked
0xc000c17930 free  unmarked
0xc000c17a00 free  unmarked
0xc000c17ad0 free  unmarked
0xc000c17ba0 free  unmarked
0xc000c17c70 free  unmarked
0xc000c17d40 free  unmarked
0xc000c17e10 free  unmarked
0xc000c17ee0 alloc marked  
fatal error: found pointer to free object

runtime stack:
runtime.throw(0x517963a, 0x1c)
	/opt/ooce/go-1.16/src/runtime/panic.go:1117 +0x72
runtime.(*mspan).reportZombies(0xfffffc7feea2b2a0)
	/opt/ooce/go-1.16/src/runtime/mgcsweep.go:614 +0x376
runtime.(*mspan).sweep(0xfffffc7feea2b2a0, 0x0, 0x0)
	/opt/ooce/go-1.16/src/runtime/mgcsweep.go:442 +0x8dc
runtime.(*mcentral).uncacheSpan(0x8d734b8, 0xfffffc7feea2b2a0)
	/opt/ooce/go-1.16/src/runtime/mcentral.go:214 +0xcb
runtime.(*mcache).releaseAll(0xfffffc7fef03ab38)
	/opt/ooce/go-1.16/src/runtime/mcache.go:276 +0x136
runtime.(*mcache).prepareForSweep(0xfffffc7fef03ab38)
	/opt/ooce/go-1.16/src/runtime/mcache.go:310 +0x46
runtime.gcMarkTermination.func4.1(0xc00009e800)
	/opt/ooce/go-1.16/src/runtime/mgc.go:1766 +0x2f
runtime.forEachP(0x57b1170)
	/opt/ooce/go-1.16/src/runtime/proc.go:1499 +0x11b
runtime.gcMarkTermination.func4()
	/opt/ooce/go-1.16/src/runtime/mgc.go:1765 +0x2d
runtime.systemstack(0xfffffc7fe4610000)
	/opt/ooce/go-1.16/src/runtime/asm_amd64.s:379 +0x73
runtime.mstart()
	/opt/ooce/go-1.16/src/runtime/proc.go:1246

goroutine 11 [running]:
runtime.systemstack_switch()
	/opt/ooce/go-1.16/src/runtime/asm_amd64.s:339 fp=0xc00010cd50 sp=0xc00010cd48 pc=0xf50f80
runtime.gcMarkTermination(0x3fed9bbad1c05669)
	/opt/ooce/go-1.16/src/runtime/mgc.go:1764 +0x41f fp=0xc00010cf08 sp=0xc00010cd50 pc=0xefcd1f
runtime.gcMarkDone()
	/opt/ooce/go-1.16/src/runtime/mgc.go:1623 +0x275 fp=0xc00010cf60 sp=0xc00010cf08 pc=0xefc835
runtime.gcBgMarkWorker()
	/opt/ooce/go-1.16/src/runtime/mgc.go:2045 +0x2ab fp=0xc00010cfe0 sp=0xc00010cf60 pc=0xefd94b
runtime.goexit()
	/opt/ooce/go-1.16/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc00010cfe8 sp=0xc00010cfe0 pc=0xf52e61
created by runtime.gcBgMarkStartWorkers
	/opt/ooce/go-1.16/src/runtime/mgc.go:1835 +0x37

goroutine 1 [runnable, locked to thread]:
github.com/aws/aws-sdk-go/aws/endpoints.init()
	/ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/vendor/github.com/aws/aws-sdk-go/aws/endpoints/defaults.go:173 +0x67fac

goroutine 18 [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.6
	/ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:41 +0x35

goroutine 19 [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.6
	/ws/gc/cockroach/cache/gopath/src/github.com/cockroachdb/cockroach/pkg/util/log/log_flush.go:42 +0x4d

goroutine 66 [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 29 [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:91 +0x128
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:79 +0x35

Yowza. I wonder if CockroachDB is finding something invalid about its on-disk state -- if there was something not quite safe about #493.

[smklein]

Update here after a day of debugging, here's my theory:

1. Somehow, constructing the seed directory is done in a way that leaves a temporary directory (/tmp/crdb-base/cockroach-tempXXX/) around.
2. The ABSOLUTE PATH to this directory exists in temp-dirs-record.txt
3. /tmp/crdb-base is copied elsewhere, during a cargo test invocation
4. When cockroach is started from the "new" location, it still contains temp-dirs-record.txt, which points to temporary directory in crdb-base. Cockroachdb attempts to clean up this temporary directory...
5. ... and this is where bugs manifest. If someone else tries copying from crdb-base at the same time, they might read_dir something being concurrently deleted. Alternatively, they may attempt to process that temporary directory concurrently, which could plausibly result in corruption.

This can be tested manually with:

$ cargo build -p omicron-nexus --tests
$ ls -d $(cat /tmp/crdb-base/temp-dirs-record.txt)  # This will exist
$ cargo test -p omicron-nexus db::pagination
$ ls -d $(cat /tmp/crdb-base/temp-dirs-record.txt)  # This will no longer exist

[smklein]

(apologies for fat-fingering tab+enter, this issue is definitely not closed yet)

[smklein]

I've found sources from CRDB devs indicating that:

Data directories should be movable:

moving data should work as you describe. A data directory isn’t tied to its location or the underlying file system (well, shouldn’t be and we’ve never seen any bugs with that regard in our testing).

Absolute paths in CRDB probably shouldn't exist

(some issue) is likely because we're using an absolute path somewhere. This shouldn't happen as this makes it impossible to move the data directories.