roachtest: synctest failed on Pebble

[petermattis]

Seen while running roachtests on #48145

./nemesis on: Restricting random IO restricted to specific syscalls and 1% error probability
F200508 19:38:32.692326 5518 vendor/github.com/cockroachdb/pebble/version_set.go:413  MANIFEST flush failed: write /mnt/data1/cockroach/faulty/0/MANIFEST-000001: no message of desired type
goroutine 5518 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x7756e01, 0xed647ac38, 0x0, 0x855980)
        /go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xb8
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x7753800, 0xc000000004, 0x6c9f77b, 0x33, 0x19d, 0xc00004b730, 0x66)
        /go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:212 +0xbcd
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x4d274c0, 0xc000ab05a0, 0x4, 0x3, 0x44487ba, 0x19, 0xc000267cf0, 0x1, 0x1)
        /go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x2c9
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x4d274c0, 0xc000ab05a0, 0x2, 0xc000000004, 0x44487ba, 0x19, 0xc000267cf0, 0x1, 0x1)
        /go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.FatalfDepth(...)
        /go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:166
github.com/cockroachdb/cockroach/pkg/storage.pebbleLogger.Fatalf(...)
        /go/src/github.com/cockroachdb/cockroach/pkg/storage/pebble.go:372
github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*versionSet).logAndApply.func1(0xc0001c4a88, 0xc0007f6aa0, 0xc00092a2a0, 0xc000d75b78, 0xc000d75b58, 0x0, 0xe49, 0xe4d, 0x156c, 0x4d65180, ...)
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/version_set.go:413 +0x387
github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*versionSet).logAndApply(0xc0001c4a88, 0x156c, 0xc0007f6aa0, 0xc0008065d0, 0x4d65180, 0xc000010488, 0xc000d75d60, 0x0, 0x0)
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/version_set.go:436 +0x1ba
github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*DB).flush1(0xc0001c4900, 0x77a5d50, 0x77a5d50)
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/compaction.go:986 +0x698
github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*DB).flush.func1(0x4d274c0, 0xc000806570)
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/compaction.go:896 +0x88
runtime/pprof.Do(0x4d274c0, 0xc000806570, 0xc000289880, 0x1, 0x1, 0xc0006effb8)
        /usr/local/go/src/runtime/pprof/runtime.go:37 +0xf8
github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*DB).flush(0xc0001c4900)
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/compaction.go:893 +0x89
created by github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble.(*DB).maybeScheduleFlush
        /go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/compaction.go:889 +0x177

The no message of desired type is a strange error message.

Given the error injection that synctest performs, a crash here does not seem unexpected. Hmm, this is not running cockroach normally, but running cockroach debug synctest. Perhaps that isn't compatible with Pebble. I'm not seeing any facility to catch log fatals.

Jira issue: CRDB-4311

[blathers-crl]

Hi @petermattis, I've guessed the C-ategory of your issue and suitably labeled it. Please re-label if inaccurate.

While you're here, please consider adding an A- label to help keep our repository tidy.

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

[jbowens]

There might've been some code drift since May when we skipped it, because charybdefs fails to build now. I'll look into that first.

I found two main areas when a filesystem error is considered unrecoverable in Pebble:

Writing & syncing the WAL:
https://github.com/cockroachdb/pebble/blob/ab86f22f23654074bdabc162487fb346f9b52e6d/db.go#L556-L560

logAndApply:
https://github.com/cockroachdb/pebble/blob/ab86f22f23654074bdabc162487fb346f9b52e6d/version_set.go#L429-L461

We can add a facility to catch Logger.Fatalf calls. When one occurs, I think we'll need to not just swallow the error but close and reopen the engine to recover.

[jbowens]

I'm not sure if I have a bug in my adaptation of the test or there's a real issue here, but using the adapted test I can consistently produce a disk stall that seemingly never recovers. The stalled goroutine stack trace looks something like:

goroutine 1096 [IO wait]:
internal/poll.runtime_pollWait(0x7f0819ec3ec0, 0x77, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc001c740d8, 0x77, 0x1, 0x7fdb, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitWrite(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).Write(0xc001c740c0, 0xc00190e02d, 0x25, 0x7fdb, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:276 +0x2a9
os.(*File).write(...)
	/usr/local/go/src/os/file_unix.go:276
os.(*File).Write(0xc000e8a610, 0xc00190e02d, 0x25, 0x7fdb, 0xc00009fc18, 0x509156, 0x46f7da)
	/usr/local/go/src/os/file.go:153 +0x77
github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).Write.func1()
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/vfs/disk_health.go:92 +0x63
github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).timeDiskOp(0xc000f5a800, 0xc00009fc98)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/vfs/disk_health.go:123 +0xbd
github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).Write(0xc000f5a800, 0xc00190e02d, 0x25, 0x7fdb, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/vfs/disk_health.go:91 +0xab
github.com/cockroachdb/pebble/vfs.(*syncingFile).Write(0xc001c74120, 0xc00190e02d, 0x25, 0x7fdb, 0x3, 0x0, 0xc001b20540)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/vfs/syncing_file.go:81 +0x6c
github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushPending(0xc000415400, 0xc00190e02d, 0x25, 0x7fdb, 0xc001d9a200, 0x0, 0x10, 0x100000002, 0x4148500, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/internal/record/log_writer.go:471 +0x215
github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushLoop(0xc000415400, 0x584ade0, 0xc001a48150)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/internal/record/log_writer.go:426 +0x2b3
runtime/pprof.Do(0x584ade0, 0xc001a48150, 0xc00043e4e0, 0x1, 0x1, 0xc0015fcfb8)
	/usr/local/go/src/runtime/pprof/runtime.go:37 +0xf8
github.com/cockroachdb/pebble/internal/record.NewLogWriter.func2(0xc000415400)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/internal/record/log_writer.go:314 +0x89
created by github.com/cockroachdb/pebble/internal/record.NewLogWriter
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/cockroachdb/pebble/internal/record/log_writer.go:313 +0x2cd

I haven't been able to produce these stalls with the charbydefs disabled, which makes me think this is not a real disk stall caused by high write volume.

I tried using strace, finding the last opened .log file and then finding its last write syscall to that file descriptor:

[pid 32686] write(8, "\25\203\314\177\32\0\5I\36\0\0(\36\0\0\0\0\0\0\1\0\0\0\1\4\367\36(\0\7pa"..., 37 <unfinished ...>
[pid 32427] write(1, "7719\n", 5 <unfinished ...>
[pid 32421] <... nanosleep resumed> NULL) = 0
[pid 32678] <... nanosleep resumed> NULL) = 0
[pid 32689] <... nanosleep resumed> NULL) = 0
[pid 32678] nanosleep({0, 20000},  <unfinished ...>
[pid 32689] futex(0xc0004dd648, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 32427] <... write resumed> )       = 5
[pid 32421] nanosleep({0, 20000},  <unfinished ...>
[pid 32686] <... write resumed> )       = -1 EAGAIN (Resource temporarily unavailable)

The rest of the strace is futex syscalls until the my introspection code times out and prints the stack trace and kills the test. It seems suspicious that the errno here is EAGAIN.

[jbowens]

This program also hangs.

package main

import (
	"os"
)

func main() {
	f, err := os.Create("/faulty/foo")
	must(err)
	b := []byte("bar")
	for i := 0; i < 100_000_000; i++ {
		_, _ = f.Write(b)
	}
	must(f.Close())
}

func must(err error) {
	if err != nil {
		panic(err)
	}
}

write(3, "bar", 3)                      = 3
write(3, "bar", 3)                      = 3
futex(0x4eb958, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0x4eb858, FUTEX_WAKE_PRIVATE, 1)  = 1
write(3, "bar", 3)                      = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(4, [], 128, 0, NULL, 3)     = 0
epoll_pwait(4,

RocksDB does not use non-blocking IO, whereas Go does, right? It seems like there's no real issue here, other than that we need charybdefs to not return specifically EAGAIN.

[petermattis]

RocksDB does not use non-blocking IO, whereas Go does, right? It seems like there's no real issue here, other than that we need charybdefs to not return specifically EAGAIN.

I thought non-blocking IO on file descriptors wasn't a useful thing. Perhaps the issue is that the Go runtime always retries system calls on EAGAIN. I agree with your conclusion that changing charybdefs to not return EAGAIN will likely fix the issue.

[jbowens]

Perhaps the issue is that the Go runtime always retries system calls on EAGAIN.

If that's the case, I wonder if any distributed file systems might ever return EAGAIN causing the Go runtime to deadlock itself waiting for a non-blocking IO event that's never coming. Could any of the never-ending disk stalls we've seen in the wild have been caused by the filesystem returning EAGAIN confusing the Go runtime?

[petermattis]

Could any of the never-ending disk stalls we've seen in the wild have been caused by the filesystem returning EAGAIN confusing the Go runtime?

Possibly. Maybe. I thought we had evidence they were due to threads being stuck in the kernel forever.

[itsbilal]

Possibly. Maybe. I thought we had evidence they were due to threads being stuck in the kernel forever.

Can confirm - in some of those cases, the Go runtime wasn't involved at all. We saw fsync()s getting stuck deep in RocksDB.

[nicktrav]

@jbowens @itsbilal - is this something we should triage again to see if it's still relevant?

[jbowens]

I think the action item here is to first get scylladb/charybdefs#24 across the line (or change the roachtest to use our own fork). Not sure on relative priority here.

[srosenberg]

Drive-by comment (came across while looking for examples of failure-injection in roachtests)... seems that a simple stopgap is to intercept error_inject (via LD_PRELOAD) and filter out the unwanted injection, i.e., error code.

[nicktrav]

Linking this to #80986. If we remove charybdefs in favor of dmsetup for the disk stall test, the only other test that uses charybdefs is synctest.

We'll need to make a call as to whether to keep this test around (and land the fix to charybdefs) or re-write to use dmsetup (might be tricky, as from what I could tell it only supports a fixed delay).

[kenliu-crl]

manually reviewed and brought up to date

[sumeerbhola]

@jbowens, here is my current understanding. Please correct where mistaken.

• we have the changes we need in charybdefs in our fork https://github.com/cockroachdb/charybdefs/tree/crl, to not return EAGAIN.
• Your changes in jbowens@810ee5b are not merged. It is possible that it may be sufficient to fix the Fatalf issue.
• Any Pebble-level correctness issues with sync are already tested in a more fine-grained manner with NewStrictMem which came much after synctest, so arguably synctest is more of a filesystem test now, so questionable value to fix and maintain.

btw, I am confused by the generation logic

cockroach/pkg/cli/debug_synctest.go

Lines 90 to 102 in b3c64ee

	dir := filepath.Join(args[0], strconv.Itoa(generation))
	curLastSeq, err := runSyncer(ctx, dir, lastSeq, nem)
	if err != nil {
	return err
	}
	lastSeq = curLastSeq
	if curLastSeq == 0 {
	if ctx.Err() != nil {
	// Clean shutdown.
	return nil
	}
	// RocksDB dir got corrupted.
	generation++

. Since generation decides the directory for the DB, aren't we opening an empty DB each time, so the previous writes won't be seen. I must be missing something obvious.

[jbowens]

we have the changes we need in charybdefs in our fork https://github.com/cockroachdb/charybdefs/tree/crl, to not return EAGAIN.

Yeah, that's right.

Your changes in jbowens@810ee5b are not merged. It is possible that it may be sufficient to fix the Fatalf issue.

Oh wow, I've completely forgotten about that. Yeah, they might be sufficient.

Any Pebble-level correctness issues with sync are already tested in a more fine-grained manner with NewStrictMem which came much after synctest, so arguably synctest is more of a filesystem test now, so questionable value to fix and maintain.

Yeah, I think that's true. Relatedly, we have #96670 tracking better EAR VFS crash testing.

In #102492 we stopped using charybdefs for disk stall roachtests because it was flaky during setup and teardown, so +1 to "questionable value to fix and maintain".

Since generation decides the directory for the DB, aren't we opening an empty DB each time, so the previous writes won't be seen. I must be missing something obvious.

It looks like it intends for clean non-corrupted databases to exit with ctx.Err() != nil which will avoid incrementing generation.

[sumeerbhola]

Thanks for the responses. I am going to delete this test.