Test failure in CI build 5137

[tbg]

The following test appears to have failed:

#5137:

c189139591416436.29  127.0.0.1:0  16:58:59.591427  762.703µs  sending Put                   kv/txn_coord_sender.go:361
c189139591416436.29  127.0.0.1:0  16:58:59.591433  3.752µs    ·meta descriptor lookup       kv/dist_sender.go:614
c189139591416436.29  127.0.0.1:0  16:58:59.591439  748.677µs  ·sending RPC                  kv/dist_sender.go:527
c189139591416436.29  127.0.0.1:0  16:58:59.591454  0          ··sending to 127.0.0.1:58334  rpc/send.go:171

panic: test timed out after 30s

goroutine 2326 [running]:
testing.func·008()
    /usr/src/go/src/testing/testing.go:681 +0x12f
created by time.goFunc
    /usr/src/go/src/time/sleep.go:129 +0x4b

goroutine 1 [chan receive]:
testing.RunTests(0x12ca8f8, 0x17e9600, 0x1d, 0x1d, 0xc207ffc701)
    /usr/src/go/src/testing/testing.go:556 +0xad6
--
    /go/src/github.com/cockroachdb/cockroach/storage/scanner.go:236 +0x1d7
github.com/cockroachdb/cockroach/util/stop.func·001()
    /go/src/github.com/cockroachdb/cockroach/util/stop/stopper.go:79 +0x5d
created by github.com/cockroachdb/cockroach/util/stop.(*Stopper).RunWorker
    /go/src/github.com/cockroachdb/cockroach/util/stop/stopper.go:80 +0xfc
FAIL    github.com/cockroachdb/cockroach/server 33.525s
=== RUN TestNodeStatusMonitor
--- PASS: TestNodeStatusMonitor (0.00s)
=== RUN TestNodeStatusRecorder
--- PASS: TestNodeStatusRecorder (0.00s)
=== RUN TestRuntimeStatRecorder
I0729 16:58:59.434554 403 server/status/runtime.go:118  runtime stats: 8 goroutines, 4.33MiB active, 40000000.00cgo/sec, 76890.00/76890.00 %(u/s)time, 24387.92 %gc (8x)
--- PASS: TestRuntimeStatRecorder (0.00s)
=== RUN TestNodeEventFeed
--- PASS: TestNodeEventFeed (0.00s)
=== RUN TestServerNodeEventFeed

Please assign, take a look and update the issue accordingly.

[BramGruneir]

This seems to just be a slow test machine. Got stuck at the clog mutex while trying to flush the logs. Closing for now, but if it re-occurs, I'll take a closer look.
30 secs is too short, #1856 hopefully will give the test more time to finish.

[tamird]

This test takes 0.244s locally - are you suggesting that circle's machine is 100x slower?

[BramGruneir]

Yeah, you're right. Most likely is a deadlock, possibly in clog. If this repeats we'll have to add some debugging info into clog to see if we can isolate the culprit.

[tbg]

I blame

goroutine 2302 [syscall]:
syscall.Syscall(0x4a, 0x9, 0x0, 0x0, 0xc208037448, 0xc2084c8000, 0x274)
/usr/src/go/src/syscall/asm_linux_amd64.s:21 +0x5
syscall.Fsync(0x9, 0x0, 0x0)
/usr/src/go/src/syscall/zsyscall_linux_amd64.go:503 +0x55
os.(_File).Sync(0xc208037448, 0x0, 0x0)
/usr/src/go/src/os/file_posix.go:129 +0x6a
github.com/cockroachdb/cockroach/util/log.(_syncBuffer).Sync(0xc2081a3860, 0x0, 0x0)
/go/src/github.com/cockroachdb/cockroach/util/log/clog.go:910 +0x3e
github.com/cockroachdb/cockroach/util/log.(_loggingT).flushAll(0x188a660)
/go/src/github.com/cockroachdb/cockroach/util/log/clog.go:1039 +0x99
github.com/cockroachdb/cockroach/util/log.(_loggingT).lockAndFlushAll(0x188a660)
/go/src/github.com/cockroachdb/cockroach/util/log/clog.go:1027 +0x42
github.com/cockroachdb/cockroach/util/log.Flush()

since this guy probably has the lock and others are backed up on it.