ccl/importccl: TestMultiNodeExportStmt failed #43067

cockroach-teamcity · 2019-12-10T10:35:34Z

(ccl/importccl).TestMultiNodeExportStmt failed on unknown@734e357412dadafcd6084b8eab8e251e44e86b4a:


I191210 10:35:18.954967 216005 storage/store_snapshot.go:977  [n4,replicate,s4,r28/4:/Table/53/1/1{00-40}] sending LEARNER snapshot e33ec032 at applied index 51
I191210 10:35:18.980931 216005 storage/store_snapshot.go:1020  [n4,replicate,s4,r28/4:/Table/53/1/1{00-40}] streamed snapshot to (n5,s5):6LEARNER: kv pairs: 55, log entries: 0, rate-limit: 8.0 MiB/sec, 0.09s
I191210 10:35:18.999266 216378 storage/replica_raftstorage.go:798  [n5,s5,r28/6:{-}] applying LEARNER snapshot [id=e33ec032 index=51]
I191210 10:35:19.026852 216378 storage/replica_raftstorage.go:819  [n5,s5,r28/6:/Table/53/1/1{00-40}] applied LEARNER snapshot [total=27ms ingestion=4@19ms id=e33ec032 index=51]
I191210 10:35:19.072484 216005 storage/replica_command.go:1706  [n4,replicate,s4,r28/4:/Table/53/1/1{00-40}] change replicas (add [(n5,s5):6VOTER_INCOMING] remove [(n3,s3):3VOTER_DEMOTING]): existing descriptor r28:/Table/53/1/1{00-40} [(n1,s1):1, (n4,s4):4, (n3,s3):3, (n5,s5):6LEARNER, next=7, gen=19, sticky=9223372036.854775807,2147483647]
I191210 10:35:19.123663 216438 storage/raft_snapshot_queue.go:125  [n4,raftsnapshot,s4,r52/2:/Table/53/1/1{40-60}] skipping snapshot; replica is likely a learner in the process of being added: (n5,s5):4LEARNER
I191210 10:35:19.127826 216033 storage/store_snapshot.go:977  [n4,s4,r52/2:/Table/53/1/1{40-60}] sending LEARNER snapshot 50054b8a at applied index 14
I191210 10:35:19.129631 216033 storage/store_snapshot.go:1020  [n4,s4,r52/2:/Table/53/1/1{40-60}] streamed snapshot to (n5,s5):4LEARNER: kv pairs: 26, log entries: 0, rate-limit: 8.0 MiB/sec, 0.05s
I191210 10:35:19.142814 216401 storage/replica_raftstorage.go:798  [n5,s5,r52/4:{-}] applying LEARNER snapshot [id=50054b8a index=14]
I191210 10:35:19.155384 216401 storage/replica_raftstorage.go:819  [n5,s5,r52/4:/Table/53/1/1{40-60}] applied LEARNER snapshot [total=12ms ingestion=4@7ms id=50054b8a index=14]
I191210 10:35:19.164680 216033 storage/replica_command.go:1706  [n4,s4,r52/2:/Table/53/1/1{40-60}] change replicas (add [(n5,s5):4VOTER_INCOMING] remove [(n3,s3):3VOTER_DEMOTING]): existing descriptor r52:/Table/53/1/1{40-60} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n5,s5):4LEARNER, next=5, gen=19, sticky=9223372036.854775807,2147483647]
I191210 10:35:19.355348 215504 storage/replica_raft.go:290  [n1,s1,r29/1:/{Table/53/1/1…-Max}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2 (n3,s3):3LEARNER (n5,s5):4] next=5
I191210 10:35:19.410674 215796 storage/replica_raft.go:290  [n1,s1,r41/1:/Table/53/1/{60-80}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER (n5,s5):4] next=5
I191210 10:35:19.498431 216515 storage/replica_command.go:1706  [n2,s2,r42/2:/Table/53/1/{40-60}] change replicas (add [(n4,s4):4LEARNER] remove []): existing descriptor r42:/Table/53/1/{40-60} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=18, sticky=9223372036.854775807,2147483647]
I191210 10:35:19.698562 215504 storage/replica_command.go:1706  [n1,s1,r29/1:/{Table/53/1/1…-Max}] change replicas (add [] remove [(n3,s3):3LEARNER]): existing descriptor r29:/{Table/53/1/180-Max} [(n1,s1):1, (n4,s4):2, (n3,s3):3LEARNER, (n5,s5):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191210 10:35:19.758444 215796 storage/replica_command.go:1706  [n1,replicate,s1,r41/1:/Table/53/1/{60-80}] change replicas (add [] remove [(n3,s3):3LEARNER]): existing descriptor r41:/Table/53/1/{60-80} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, (n5,s5):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191210 10:35:19.846060 212785 storage/replica_raft.go:290  [n1,s1,r30/1:/Table/53/1/{80-100}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER (n5,s5):4] next=5
I191210 10:35:20.072475 212785 storage/replica_command.go:1706  [n1,s1,r30/1:/Table/53/1/{80-100}] change replicas (add [] remove [(n3,s3):3LEARNER]): existing descriptor r30:/Table/53/1/{80-100} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, (n5,s5):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191210 10:35:20.330500 216515 storage/replica_raft.go:290  [n2,s2,r42/2:/Table/53/1/{40-60}] proposing SIMPLE(l4) ADD_REPLICA[(n4,s4):4LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3 (n4,s4):4LEARNER] next=5
I191210 10:35:20.332620 216033 storage/replica_raft.go:290  [n4,s4,r52/2:/Table/53/1/1{40-60}] proposing ENTER_JOINT(r3 l3 v4) ADD_REPLICA[(n5,s5):4VOTER_INCOMING], REMOVE_REPLICA[(n3,s3):3VOTER_DEMOTING]: after=[(n1,s1):1 (n4,s4):2 (n3,s3):3VOTER_DEMOTING (n5,s5):4VOTER_INCOMING] next=5
I191210 10:35:20.341066 215504 storage/replica_raft.go:290  [n1,s1,r29/1:/{Table/53/1/1…-Max}] proposing SIMPLE(r3) REMOVE_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n4,s4):2 (n5,s5):4] next=5
I191210 10:35:20.428306 215796 storage/replica_raft.go:290  [n1,s1,r41/1:/Table/53/1/{60-80}] proposing SIMPLE(r3) REMOVE_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n5,s5):4] next=5

details

Parameters:

TAGS=
GOFLAGS=-race -parallel=2

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

The text was updated successfully, but these errors were encountered:

cockroach-teamcity · 2019-12-10T10:45:24Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@734e357412dadafcd6084b8eab8e251e44e86b4a:


I191210 10:13:19.300315 245508 storage/store_remove_replica.go:129  [n5,s5,r28/4:/{Table/53/1/1…-Max}] removing replica r28/4
I191210 10:13:19.433973 269909 storage/replica_command.go:1706  [n1,replicate,s1,r27/1:/Table/53{-/1/100}] change replicas (add [] remove [(n4,s4):2VOTER_DEMOTING]): existing descriptor r27:/Table/53{-/1/100} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n5,s5):5, next=6, gen=13]
I191210 10:13:19.819139 267393 storage/replica_command.go:406  [n1,s1,r27/1:/Table/53{-/1/100}] initiating a split of this range at key /Table/53/1/60 [r29] (manual)
I191210 10:13:19.883909 266769 storage/replica_command.go:406  [n1,s1,r28/1:/{Table/53/1/1…-Max}] initiating a split of this range at key /Table/53/1/160 [r30] (manual)
I191210 10:13:20.216923 269909 storage/replica_raft.go:290  [n1,s1,r27/1:/Table/53{-/1/100}] proposing ENTER_JOINT(r2 l2) REMOVE_REPLICA[(n4,s4):2VOTER_DEMOTING]: after=[(n1,s1):1 (n4,s4):2VOTER_DEMOTING (n2,s2):3 (n5,s5):5] next=6
I191210 10:13:20.380690 269909 storage/replica_command.go:1706  [n1,replicate,s1,r27/1:/Table/53{-/1/100}] change replicas (add [] remove []): existing descriptor r27:/Table/53{-/1/100} [(n1,s1):1, (n4,s4):2VOTER_DEMOTING, (n2,s2):3, (n5,s5):5, next=6, gen=14]
I191210 10:13:20.804850 269909 storage/replica_raft.go:290  [n1,s1,r27/1:/Table/53{-/1/100}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2LEARNER (n2,s2):3 (n5,s5):5] next=6
I191210 10:13:20.982847 269909 storage/replica_command.go:1706  [n1,replicate,s1,r27/1:/Table/53{-/1/100}] change replicas (add [] remove [(n4,s4):2LEARNER]): existing descriptor r27:/Table/53{-/1/100} [(n1,s1):1, (n4,s4):2LEARNER, (n2,s2):3, (n5,s5):5, next=6, gen=15]
I191210 10:13:21.189079 267393 storage/replica_command.go:406  [n1,s1,r27/1:/Table/53{-/1/100}] initiating a split of this range at key /Table/53/1/60 [r31] (manual)
I191210 10:13:21.446632 266769 storage/replica_command.go:406  [n1,s1,r28/1:/Table/53/1/1{00-60}] initiating a split of this range at key /Table/53/1/140 [r32] (manual)
I191210 10:13:21.483067 242892 server/status/runtime.go:498  [n1] runtime stats: 1.8 GiB RSS, 1972 goroutines, 90 MiB/75 MiB/204 MiB GO alloc/idle/total, 207 MiB/264 MiB CGO alloc/total, 861.1 CGO/sec, 194.1/18.0 %(u/s)time, 0.3 %gc (7x), 3.4 MiB/3.4 MiB (r/w)net
I191210 10:13:21.713962 269909 storage/replica_raft.go:290  [n1,s1,r27/1:/Table/53{-/1/100}] proposing SIMPLE(r2) REMOVE_REPLICA[(n4,s4):2LEARNER]: after=[(n1,s1):1 (n5,s5):5 (n2,s2):3] next=6
I191210 10:13:21.927503 244767 storage/store_remove_replica.go:129  [n4,s4,r27/2:/Table/53{-/1/100}] removing replica r27/2
I191210 10:13:22.034896 267393 storage/replica_command.go:406  [n1,s1,r27/1:/Table/53{-/1/100}] initiating a split of this range at key /Table/53/1/60 [r33] (manual)
I191210 10:13:22.192399 270406 storage/replica_command.go:406  [n2,s2,r30/3:/{Table/53/1/1…-Max}] initiating a split of this range at key /Table/53/1/180 [r47] (manual)
I191210 10:13:23.036831 243925 server/status/runtime.go:498  [n2] runtime stats: 1.8 GiB RSS, 1979 goroutines, 119 MiB/45 MiB/204 MiB GO alloc/idle/total, 207 MiB/264 MiB CGO alloc/total, 919.3 CGO/sec, 197.2/16.5 %(u/s)time, 0.5 %gc (7x), 3.2 MiB/3.2 MiB (r/w)net
I191210 10:13:23.831988 266769 storage/replica_command.go:406  [n1,s1,r28/1:/Table/53/1/1{00-40}] initiating a split of this range at key /Table/53/1/120 [r34] (manual)
I191210 10:13:23.832849 244273 server/status/runtime.go:498  [n3] runtime stats: 1.8 GiB RSS, 1981 goroutines, 118 MiB/49 MiB/204 MiB GO alloc/idle/total, 207 MiB/264 MiB CGO alloc/total, 1001.5 CGO/sec, 201.4/16.6 %(u/s)time, 0.6 %gc (8x), 3.5 MiB/3.5 MiB (r/w)net
I191210 10:13:24.337708 267393 storage/replica_command.go:406  [n1,s1,r33/1:/Table/53/1/{60-100}] initiating a split of this range at key /Table/53/1/80 [r35] (manual)
I191210 10:13:24.540040 270769 storage/replica_command.go:406  [n1,s1,r27/1:/Table/53{-/1/60}] initiating a split of this range at key /Table/53/1/40 [r36] (manual)
I191210 10:13:24.901128 244810 server/status/runtime.go:498  [n4] runtime stats: 1.8 GiB RSS, 1989 goroutines, 112 MiB/52 MiB/204 MiB GO alloc/idle/total, 207 MiB/265 MiB CGO alloc/total, 1027.7 CGO/sec, 199.8/17.6 %(u/s)time, 0.6 %gc (7x), 3.6 MiB/3.6 MiB (r/w)net
W191210 10:13:24.903929 242834 storage/store_raft.go:496  [n1,s1,r28/1:/Table/53/1/1{00-40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 10:13:24.949210 244675 storage/store_raft.go:496  [n4,s4,r1/3:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 10:13:24.979295 244741 storage/store_raft.go:496  [n4,s4,r3/3:/System/{NodeLive…-tsd}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 10:13:24.989132 243866 storage/store_raft.go:496  [n2,s2,r28/3:/Table/53/1/1{00-40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]

details

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

tbg · 2019-12-10T11:26:21Z

uh-oh: cc @nvanbenschoten @ajwerner is there a recent change we can blame for this? This just repro'ed in nightly stress and master, respectively.

F191210 10:35:27.740990 196365 storage/replica_init.go:276  [n1,s1,r9/1:/Table/1{3-4}] range descriptor ID (53) does not match replica's range ID (9)
goroutine 196365 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x991b301, 0x0, 0x0, 0x820967)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xbf
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x8f4e240, 0xc000000004, 0x8898083, 0x17, 0x114, 0xc0073213e0, 0x59)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:214 +0xc1c
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x626fac0, 0xc0028eb770, 0xc000000004, 0x2, 0x53fac82, 0x3f, 0xc0060562e8, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x291
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x626fac0, 0xc0028eb770, 0x1, 0x4, 0x53fac82, 0x3f, 0xc0060562e8, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:155
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).setDesc(0xc001650900, 0x626fac0, 0xc0028eb770, 0xc0020705b0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_init.go:276 +0x907
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleDescResult(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_result.go:241
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).handleNonTrivialReplicatedEvalResult(0xc0016509d0, 0x626fac0, 0xc0028eb770, 0x0, 0xc00249e410, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1122 +0xa0b
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).ApplySideEffects(0xc0016509d0, 0x62ac780, 0xc00390f008, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1005 +0xb65
github.com/cockroachdb/cockroach/pkg/storage/apply.mapCheckedCmdIter(0x14b6be1fda68, 0xc001650be8, 0xc006057048, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/cmd.go:182 +0x129
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).applyOneBatch(0xc006057578, 0x626fac0, 0xc0028eb770, 0x62ac840, 0xc001650b88, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:281 +0x272
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).ApplyCommittedEntries(0xc006057578, 0x626fac0, 0xc0028eb770, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:247 +0x103
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReadyRaftMuLocked(0xc001650900, 0x626fac0, 0xc0028eb770, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:766 +0x10fa
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReady(0xc001650900, 0x626fac0, 0xc0028eb770, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:440 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processReady(0xc0006a3800, 0x626fac0, 0xc0041e2180, 0x9)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store_raft.go:487 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc006a05440, 0x626fac0, 0xc0041e2180)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:226 +0x31a
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x626fac0, 0xc0041e2180)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc0050d2ee0, 0xc00371cfa0, 0xc0050d2ed0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:190 +0xc4

ajwerner · 2019-12-10T16:00:14Z

This seems like a big deal. I'll also try to repro it.

ajwerner · 2019-12-10T18:57:28Z

This repros for me, going to kick off a bisect rather than trying to think too hard about it just yet.

cockroach-teamcity · 2019-12-10T22:12:28Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@92d57bd8ed61ac2eae7fa390e40d6d41839dcd15:


W191210 21:34:25.063734 266385 storage/store_raft.go:496  [n3,s3,r27/5:/Table/53{-/1/40}] handle raft ready: 0.6s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.065614 265992 storage/store_raft.go:496  [n2,s2,r27/3:/Table/53{-/1/40}] handle raft ready: 0.6s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.106671 266384 storage/store_raft.go:496  [n3,s3,r31/2:/Table/53/1/1{00-60}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:34:25.121597 265995 storage/store_raft.go:496  [n2,s2,r31/3:/Table/53/1/1{00-60}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
I191210 21:34:25.123598 267749 server/status/runtime.go:498  [n5] runtime stats: 1.9 GiB RSS, 1975 goroutines, 72 MiB/88 MiB/204 MiB GO alloc/idle/total, 242 MiB/298 MiB CGO alloc/total, 744.5 CGO/sec, 200.7/23.4 %(u/s)time, 0.3 %gc (6x), 3.8 MiB/3.8 MiB (r/w)net
W191210 21:34:25.126108 265893 storage/store_raft.go:496  [n2,s2,r33/3:/Table/53/1/{80-100}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:34:25.136380 266368 storage/store_raft.go:496  [n3,s3,r33/2:/Table/53/1/{80-100}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:34:25.137415 265078 storage/store_raft.go:496  [n1,s1,r31/1:/Table/53/1/1{00-60}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:34:25.157115 265033 storage/store_raft.go:496  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.159069 267800 storage/store_raft.go:496  [n5,s5,r1/2:/{Min-System/NodeL…}] handle raft ready: 0.6s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.160647 266984 storage/store_raft.go:496  [n4,s4,r1/3:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.172305 266356 storage/store_raft.go:496  [n3,s3,r1/4:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.182924 265040 storage/store_raft.go:496  [n1,s1,r47/1:/{Table/53/1/1…-Max}] handle raft ready: 0.6s [applied=3, batches=1, state_assertions=0]
W191210 21:34:25.186160 266008 storage/store_raft.go:496  [n2,s2,r1/5:/{Min-System/NodeL…}] handle raft ready: 0.6s [applied=2, batches=1, state_assertions=0]
W191210 21:34:25.229715 265948 storage/store_raft.go:496  [n2,s2,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.9s [applied=3, batches=3, state_assertions=1]
W191210 21:34:25.239018 266977 storage/store_raft.go:496  [n4,s4,r2/4:/System/NodeLiveness{-Max}] handle raft ready: 0.9s [applied=3, batches=3, state_assertions=1]
W191210 21:34:25.240352 266333 storage/store_raft.go:496  [n3,s3,r2/3:/System/NodeLiveness{-Max}] handle raft ready: 0.9s [applied=3, batches=3, state_assertions=1]
W191210 21:34:25.241771 265070 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.9s [applied=3, batches=3, state_assertions=1]
W191210 21:34:25.419568 267796 storage/store_raft.go:496  [n5,s5,r2/2:/System/NodeLiveness{-Max}] handle raft ready: 1.1s [applied=3, batches=3, state_assertions=1]
W191210 21:34:25.483946 266307 storage/node_liveness.go:559  [n3,liveness-hb] slow heartbeat took 2.7s
W191210 21:34:25.743291 267038 storage/node_liveness.go:559  [n4,liveness-hb] slow heartbeat took 1.2s
W191210 21:34:25.786880 265111 storage/node_liveness.go:559  [n1,liveness-hb] slow heartbeat took 1.4s
W191210 21:34:26.217994 299815 storage/replica_raft.go:104  [n1,s1,r47/1:/Table/53/1/1{60-80}] context canceled before proposing: 1 HeartbeatTxn
W191210 21:34:27.000389 266387 storage/store_raft.go:496  [n3,s3,r31/2:/Table/53/1/1{00-40}] handle raft ready: 1.0s [applied=1, batches=1, state_assertions=1]
W191210 21:34:27.015583 265043 storage/store_raft.go:496  [n1,s1,r31/1:/Table/53/1/1{00-40}] handle raft ready: 1.0s [applied=1, batches=1, state_assertions=1]
W191210 21:34:27.003886 299706 storage/replica_raft.go:104  [n3,s3,r31/2:/Table/53/1/1{00-40}] context canceled before proposing: 1 HeartbeatTxn
I191210 21:34:27.036217 300581 storage/replica_command.go:1706  [n3,replicate,s3,r48/2:/Table/53/1/1{40-60}] change replicas (add [(n4,s4):4LEARNER] remove []): existing descriptor r48:/Table/53/1/1{40-60} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=18, sticky=9223372036.854775807,2147483647]
W191210 21:34:27.206279 265890 storage/store_raft.go:496  [n2,s2,r31/3:/Table/53/1/1{00-40}] handle raft ready: 1.2s [applied=1, batches=1, state_assertions=1]
W191210 21:34:27.268745 267739 storage/store_raft.go:496  [n5,s5,r9/4:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:34:27.329446 266341 storage/store_raft.go:496  [n3,s3,r9/5:/Table/1{3-4}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]

details

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

cockroach-teamcity · 2019-12-10T22:34:54Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@978c3abcce7fd2b0f2f26f45bd2c12baaebd29a9:


W191210 21:56:04.486706 259732 storage/store_raft.go:496  [n1,s1,r57/1:/Table/53/1/{80-100}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.497865 259686 storage/store_raft.go:496  [n1,s1,r40/1:/Table/53/1/1{60-80}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
I191210 21:56:04.519358 259636 server/status/runtime.go:498  [n1] runtime stats: 2.0 GiB RSS, 1992 goroutines, 92 MiB/69 MiB/204 MiB GO alloc/idle/total, 219 MiB/271 MiB CGO alloc/total, 887.0 CGO/sec, 206.6/22.5 %(u/s)time, 0.5 %gc (6x), 2.8 MiB/2.8 MiB (r/w)net
W191210 21:56:04.520578 260851 storage/node_liveness.go:559  [n3,liveness-hb] slow heartbeat took 1.5s
W191210 21:56:04.524467 260974 storage/store_raft.go:496  [n3,s3,r40/4:/Table/53/1/1{60-80}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.549862 260615 storage/store_raft.go:496  [n2,s2,r40/3:/Table/53/1/1{60-80}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.665709 259745 storage/store_raft.go:496  [n1,s1,r39/1:/Table/53/1/1{00-20}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.669273 261634 storage/store_raft.go:496  [n4,s4,r39/2:/Table/53/1/1{00-20}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.672286 262597 storage/store_raft.go:496  [n5,s5,r9/3:/Table/1{3-4}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.675078 260653 storage/store_raft.go:496  [n2,s2,r39/3:/Table/53/1/1{00-20}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.707190 260606 storage/store_raft.go:496  [n2,s2,r9/4:/Table/1{3-4}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.719379 260962 storage/store_raft.go:496  [n3,s3,r9/5:/Table/1{3-4}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.723143 259723 storage/store_raft.go:496  [n1,s1,r9/1:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.743513 261650 storage/store_raft.go:496  [n4,s4,r9/2:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:04.764384 260637 storage/store_raft.go:496  [n2,s2,r2/2:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
I191210 21:56:04.978982 302127 storage/replica_raft.go:290  [n5,s5,r57/2:/Table/53/1/{80-100}] proposing SIMPLE(l4) ADD_REPLICA[(n3,s3):4LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n2,s2):3 (n3,s3):4LEARNER] next=5
W191210 21:56:05.326885 262509 storage/store_raft.go:496  [n5,s5,r2/3:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.331668 261687 storage/store_raft.go:496  [n4,s4,r2/4:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.339486 260985 storage/store_raft.go:496  [n3,s3,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.350238 259698 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.414313 261648 storage/store_raft.go:496  [n4,s4,r1/3:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.420469 259688 storage/store_raft.go:496  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.436416 262728 storage/node_liveness.go:559  [n5,liveness-hb] slow heartbeat took 1.6s
W191210 21:56:05.541891 259731 storage/store_raft.go:496  [n1,s1,r45/1:/Table/53/1/1{20-40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=1]
W191210 21:56:05.567816 259744 storage/store_raft.go:496  [n1,s1,r27/1:/Table/53{-/1/40}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.600459 261670 storage/store_raft.go:496  [n4,s4,r27/5:/Table/53{-/1/40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.607576 260638 storage/store_raft.go:496  [n2,s2,r27/3:/Table/53{-/1/40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191210 21:56:05.857630 261628 storage/store_raft.go:496  [n4,s4,r2/4:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=2, batches=2, state_assertions=1]
W191210 21:56:05.861456 260985 storage/store_raft.go:496  [n3,s3,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=2, batches=2, state_assertions=1]
W191210 21:56:05.868666 259698 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=2, batches=2, state_assertions=1]
W191210 21:56:05.902034 262681 storage/store_raft.go:496  [n5,s5,r2/3:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=2, batches=2, state_assertions=1]

details

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

cockroach-teamcity · 2019-12-12T02:32:10Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@b2fcc8cb865f5f7c49ab9158e9d5570c471873b5:


W191212 01:51:49.715831 306013 storage/store_raft.go:496  [n5,s5,r1/3:/{Min-System/NodeL…}] handle raft ready: 1.0s [applied=1, batches=1, state_assertions=0]
W191212 01:51:49.758712 304575 storage/store_raft.go:496  [n3,s3,r1/4:/{Min-System/NodeL…}] handle raft ready: 0.9s [applied=1, batches=1, state_assertions=0]
W191212 01:51:49.761920 304192 storage/store_raft.go:496  [n2,s2,r1/5:/{Min-System/NodeL…}] handle raft ready: 0.9s [applied=1, batches=1, state_assertions=0]
W191212 01:51:49.766332 305234 storage/store_raft.go:496  [n4,s4,r1/2:/{Min-System/NodeL…}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=0]
W191212 01:51:49.818189 303154 storage/store_raft.go:496  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
W191212 01:51:49.888948 303286 storage/node_liveness.go:559  [n1,liveness-hb] slow heartbeat took 2.2s
I191212 01:51:50.044165 348138 storage/replica_raft.go:283  [n1,s1,r34/1:/Table/53/1/1{00-40}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2 (n2,s2):3LEARNER (n5,s5):4] next=5
I191212 01:51:50.046401 347893 storage/replica_raft.go:283  [n1,s1,r50/1:/Table/53/1/1{40-60}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2 (n2,s2):3LEARNER (n3,s3):4] next=5
W191212 01:51:50.143885 304157 storage/store_raft.go:496  [n2,s2,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
I191212 01:51:50.365539 347900 storage/replica_raft.go:283  [n4,s4,r35/2:/Table/53/1/{60-100}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2 (n2,s2):3LEARNER (n3,s3):4] next=5
W191212 01:51:50.384739 305298 storage/node_liveness.go:559  [n4,liveness-hb] slow heartbeat took 1.7s
W191212 01:51:50.662400 303224 storage/store_raft.go:496  [n1,s1,r34/1:/Table/53/1/1{00-40}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=1]
I191212 01:51:50.746805 347893 storage/replica_command.go:1706  [n1,s1,r50/1:/Table/53/1/1{40-60}] change replicas (add [] remove [(n2,s2):3LEARNER]): existing descriptor r50:/Table/53/1/1{40-60} [(n1,s1):1, (n4,s4):2, (n2,s2):3LEARNER, (n3,s3):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191212 01:51:50.877068 344158 storage/replica_raft.go:283  [n1,s1,r36/1:/{Table/53/1/1…-Max}] proposing LEAVE_JOINT: after=[(n1,s1):1 (n4,s4):2 (n2,s2):3LEARNER (n5,s5):4] next=5
I191212 01:51:50.886937 305987 server/status/runtime.go:498  [n5] runtime stats: 2.1 GiB RSS, 1982 goroutines, 75 MiB/83 MiB/204 MiB GO alloc/idle/total, 217 MiB/269 MiB CGO alloc/total, 692.4 CGO/sec, 226.6/22.1 %(u/s)time, 0.7 %gc (6x), 2.6 MiB/2.6 MiB (r/w)net
I191212 01:51:50.903586 348138 storage/replica_command.go:1706  [n1,replicate,s1,r34/1:/Table/53/1/1{00-40}] change replicas (add [] remove [(n2,s2):3LEARNER]): existing descriptor r34:/Table/53/1/1{00-40} [(n1,s1):1, (n4,s4):2, (n2,s2):3LEARNER, (n5,s5):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191212 01:51:50.926401 347900 storage/replica_command.go:1706  [n4,s4,r35/2:/Table/53/1/{60-100}] change replicas (add [] remove [(n2,s2):3LEARNER]): existing descriptor r35:/Table/53/1/{60-100} [(n1,s1):1, (n4,s4):2, (n2,s2):3LEARNER, (n3,s3):4, next=5, gen=20, sticky=9223372036.854775807,2147483647]
I191212 01:51:51.237673 344158 storage/replica_command.go:1706  [n1,s1,r36/1:/{Table/53/1/1…-Max}] change replicas (add [] remove [(n2,s2):3LEARNER]): existing descriptor r36:/{Table/53/1/180-Max} [(n1,s1):1, (n4,s4):2, (n2,s2):3LEARNER, (n5,s5):4, next=5, gen=21, sticky=9223372036.854775807,2147483647]
I191212 01:51:52.505043 347893 storage/replica_raft.go:283  [n1,s1,r50/1:/Table/53/1/1{40-60}] proposing SIMPLE(r3) REMOVE_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n4,s4):2 (n3,s3):4] next=5
I191212 01:51:52.564339 303280 server/status/runtime.go:498  [n1] runtime stats: 2.1 GiB RSS, 1985 goroutines, 100 MiB/60 MiB/204 MiB GO alloc/idle/total, 218 MiB/272 MiB CGO alloc/total, 725.6 CGO/sec, 231.7/21.9 %(u/s)time, 0.7 %gc (6x), 2.5 MiB/2.5 MiB (r/w)net
W191212 01:51:52.643708 304201 storage/store_raft.go:496  [n2,s2,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=2, batches=2, state_assertions=1]
I191212 01:51:52.744167 347900 storage/replica_raft.go:283  [n4,s4,r35/2:/Table/53/1/{60-100}] proposing SIMPLE(r3) REMOVE_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n4,s4):2 (n3,s3):4] next=5
I191212 01:51:52.791214 348138 storage/replica_raft.go:283  [n1,s1,r34/1:/Table/53/1/1{00-40}] proposing SIMPLE(r3) REMOVE_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n4,s4):2 (n5,s5):4] next=5
I191212 01:51:52.913468 344158 storage/replica_raft.go:283  [n1,s1,r36/1:/{Table/53/1/1…-Max}] proposing SIMPLE(r3) REMOVE_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n4,s4):2 (n5,s5):4] next=5
W191212 01:51:53.092550 350454 storage/replica_raft.go:98  [n1,s1,r50/1:/Table/53/1/1{40-60}] context canceled before proposing: 1 HeartbeatTxn

details

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

cockroach-teamcity · 2019-12-12T19:38:02Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@9d43e69185e256927c626f2447dfb6f4aaa8f3bd:


I191212 18:58:50.483586 264417 storage/replica_raft.go:283  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(v2) ADD_REPLICA[(n5,s5):2]: after=[(n1,s1):1 (n5,s5):2] next=3
I191212 18:58:50.511076 264417 storage/replica_command.go:1706  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n4,s4):3LEARNER] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, (n5,s5):2, next=3, gen=2]
I191212 18:58:50.996780 264417 storage/replica_raft.go:283  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(l3) ADD_REPLICA[(n4,s4):3LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n4,s4):3LEARNER] next=4
I191212 18:58:51.066736 293822 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r4/1:/System{/tsd-tse}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):3LEARNER
I191212 18:58:51.070220 264417 storage/store_snapshot.go:977  [n1,replicate,s1,r4/1:/System{/tsd-tse}] sending LEARNER snapshot 3506ae71 at applied index 242
I191212 18:58:51.659377 294023 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r4/1:/System{/tsd-tse}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):3LEARNER
I191212 18:58:52.045530 264560 server/status/runtime.go:498  [n1] runtime stats: 1.9 GiB RSS, 1564 goroutines, 68 MiB/95 MiB/204 MiB GO alloc/idle/total, 190 MiB/240 MiB CGO alloc/total, 1187.8 CGO/sec, 202.2/18.2 %(u/s)time, 0.7 %gc (7x), 4.7 MiB/4.7 MiB (r/w)net
W191212 18:58:52.556774 264581 server/node.go:835  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:ranges.underreplicated Value:2}]}
I191212 18:58:52.859885 294274 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r4/1:/System{/tsd-tse}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):3LEARNER
I191212 18:58:53.182514 264417 storage/store_snapshot.go:1020  [n1,replicate,s1,r4/1:/System{/tsd-tse}] streamed snapshot to (n4,s4):3LEARNER: kv pairs: 3266, log entries: 0, rate-limit: 8.0 MiB/sec, 2.12s
I191212 18:58:53.325473 293909 storage/replica_raftstorage.go:798  [n4,s4,r4/3:{-}] applying LEARNER snapshot [id=3506ae71 index=242]
I191212 18:58:53.411356 293909 storage/replica_raftstorage.go:819  [n4,s4,r4/3:/System{/tsd-tse}] applied LEARNER snapshot [total=56ms ingestion=4@52ms id=3506ae71 index=242]
I191212 18:58:53.509323 264417 storage/replica_command.go:1706  [n1,replicate,s1,r4/1:/System{/tsd-tse}] change replicas (add [(n4,s4):3] remove []): existing descriptor r4:/System{/tsd-tse} [(n1,s1):1, (n5,s5):2, (n4,s4):3LEARNER, next=4, gen=3]
I191212 18:58:53.937663 265519 server/status/runtime.go:498  [n2] runtime stats: 1.9 GiB RSS, 1569 goroutines, 78 MiB/88 MiB/204 MiB GO alloc/idle/total, 191 MiB/241 MiB CGO alloc/total, 1282.1 CGO/sec, 201.7/20.4 %(u/s)time, 0.3 %gc (6x), 4.2 MiB/4.2 MiB (r/w)net
I191212 18:58:54.154621 264417 storage/replica_raft.go:283  [n1,s1,r4/1:/System{/tsd-tse}] proposing SIMPLE(v3) ADD_REPLICA[(n4,s4):3]: after=[(n1,s1):1 (n5,s5):2 (n4,s4):3] next=4
I191212 18:58:54.509667 264417 storage/replica_command.go:1706  [n1,replicate,s1,r22/1:/Table/2{6-7}] change replicas (add [(n5,s5):4LEARNER] remove []): existing descriptor r22:/Table/2{6-7} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]
I191212 18:58:54.889968 265886 server/status/runtime.go:498  [n3] runtime stats: 1.9 GiB RSS, 1571 goroutines, 121 MiB/43 MiB/204 MiB GO alloc/idle/total, 191 MiB/241 MiB CGO alloc/total, 1281.2 CGO/sec, 205.1/21.1 %(u/s)time, 0.3 %gc (6x), 4.2 MiB/4.2 MiB (r/w)net
I191212 18:58:55.034533 264417 storage/replica_raft.go:283  [n1,s1,r22/1:/Table/2{6-7}] proposing SIMPLE(l4) ADD_REPLICA[(n5,s5):4LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3 (n5,s5):4LEARNER] next=5
I191212 18:58:55.130908 294758 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r22/1:/Table/2{6-7}] skipping snapshot; replica is likely a learner in the process of being added: (n5,s5):4LEARNER
I191212 18:58:55.170364 264417 storage/store_snapshot.go:977  [n1,replicate,s1,r22/1:/Table/2{6-7}] sending LEARNER snapshot ad3213cc at applied index 52
I191212 18:58:55.186400 264417 storage/store_snapshot.go:1020  [n1,replicate,s1,r22/1:/Table/2{6-7}] streamed snapshot to (n5,s5):4LEARNER: kv pairs: 20, log entries: 0, rate-limit: 8.0 MiB/sec, 0.08s
I191212 18:58:55.298150 294735 storage/replica_raftstorage.go:798  [n5,s5,r22/4:{-}] applying LEARNER snapshot [id=ad3213cc index=52]
I191212 18:58:55.490582 294735 storage/replica_raftstorage.go:819  [n5,s5,r22/4:/Table/2{6-7}] applied LEARNER snapshot [total=161ms ingestion=4@109ms id=ad3213cc index=52]
I191212 18:58:55.550978 264417 storage/replica_command.go:1706  [n1,replicate,s1,r22/1:/Table/2{6-7}] change replicas (add [(n5,s5):4] remove []): existing descriptor r22:/Table/2{6-7} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4LEARNER, next=5, gen=5]

details

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

cockroach-teamcity · 2019-12-14T07:14:50Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@5baacb4cb245997b540cd631a54a4ce21b642f59:

Fatal error:

F191214 06:36:44.726834 272718 storage/replica_init.go:276  [n2,s2,r9/3:/Table/1{3-4}] range descriptor ID (51) does not match replica's range ID (9)

Stack:

goroutine 272718 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0xa492401, 0x0, 0x0, 0xda07a7)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xbf
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x9ac4b00, 0xc000000004, 0x92122ff, 0x17, 0x114, 0xc0041d1140, 0x59)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:214 +0xc1c
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x6b9b560, 0xc005371e00, 0xc000000004, 0x2, 0x5d25045, 0x3f, 0xc0010ce330, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x291
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x6b9b560, 0xc005371e00, 0x1, 0x4, 0x5d25045, 0x3f, 0xc0010ce330, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:155
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).setDesc(0xc00418e900, 0x6b9b560, 0xc005371e00, 0xc00521ad20)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_init.go:276 +0x907
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleDescResult(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_result.go:263
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).handleNonTrivialReplicatedEvalResult(0xc00418e9d0, 0x6b9b560, 0xc005371e00, 0xc0004a0c80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1118 +0xa6f
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).ApplySideEffects(0xc00418e9d0, 0x6bd8380, 0xc0037ef008, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1001 +0xb60
github.com/cockroachdb/cockroach/pkg/storage/apply.mapCheckedCmdIter(0x14a6bcafe008, 0xc00418ebe8, 0xc0010cf048, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/cmd.go:182 +0x129
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).applyOneBatch(0xc0010cf578, 0x6b9b560, 0xc005371e00, 0x6bd8440, 0xc00418eb88, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:281 +0x272
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).ApplyCommittedEntries(0xc0010cf578, 0x6b9b560, 0xc005371e00, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:247 +0x103
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReadyRaftMuLocked(0xc00418e900, 0x6b9b560, 0xc005371e00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:757 +0x10fa
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReady(0xc00418e900, 0x6b9b560, 0xc005371e00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:431 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processReady(0xc000220a00, 0x6b9b560, 0xc006c6ee40, 0x9)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store_raft.go:487 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc006efd200, 0x6b9b560, 0xc006c6ee40)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:226 +0x31a
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x6b9b560, 0xc006c6ee40)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc0019cdc20, 0xc00605dd60, 0xc0019cdc00)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:190 +0xc4

Log preceding fatal error

W191214 06:36:42.399961 272717 storage/store_raft.go:496  [n2,s2,r51/3:/Table/53/1/1{40-60}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191214 06:36:42.408343 271768 storage/store_raft.go:496  [n1,s1,r51/1:/Table/53/1/1{40-60}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
I191214 06:36:42.421117 317712 storage/replica_raft.go:283  [n3,s3,r59/3:/{Table/53/1/1…-Max}] proposing SIMPLE(l4) ADD_REPLICA[(n4,s4):4LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n3,s3):3 (n4,s4):4LEARNER] next=5
W191214 06:36:42.424663 271742 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 1.1s [applied=2, batches=2, state_assertions=1]
I191214 06:36:42.626712 271815 server/status/runtime.go:498  [n1] runtime stats: 2.1 GiB RSS, 2014 goroutines, 88 MiB/72 MiB/204 MiB GO alloc/idle/total, 213 MiB/266 MiB CGO alloc/total, 873.6 CGO/sec, 225.4/21.8 %(u/s)time, 0.6 %gc (7x), 2.8 MiB/2.8 MiB (r/w)net
I191214 06:36:42.639219 315361 storage/replica_raft.go:283  [n5,s5,r36/2:/Table/53/1/{20-40}] proposing LEAVE_JOINT: after=[(n1,s1):1LEARNER (n5,s5):2 (n2,s2):3 (n4,s4):4] next=5
W191214 06:36:42.847579 273615 storage/store_raft.go:496  [n4,s4,r1/5:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=4, batches=1, state_assertions=0]
W191214 06:36:42.850310 273061 storage/store_raft.go:496  [n3,s3,r1/2:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=4, batches=1, state_assertions=0]
I191214 06:36:42.850363 312876 storage/replica_raft.go:283  [n5,s5,r35/2:/Table/53/1/{40-60}] proposing SIMPLE(l5) ADD_REPLICA[(n3,s3):5LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n4,s4):4 (n3,s3):5LEARNER] next=6
I191214 06:36:42.855584 317629 storage/replica_raft.go:283  [n3,s3,r49/4:/Table/53/1/1{60-80}] proposing SIMPLE(l5) ADD_REPLICA[(n4,s4):5LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n3,s3):4 (n4,s4):5LEARNER] next=6
W191214 06:36:42.876630 271713 storage/store_raft.go:496  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=4, batches=1, state_assertions=0]
W191214 06:36:42.882468 274678 storage/store_raft.go:496  [n5,s5,r1/3:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=4, batches=1, state_assertions=0]
W191214 06:36:42.889259 272691 storage/store_raft.go:496  [n2,s2,r1/4:/{Min-System/NodeL…}] handle raft ready: 0.7s [applied=4, batches=1, state_assertions=0]
W191214 06:36:42.922685 271821 storage/node_liveness.go:559  [n1,liveness-hb] slow heartbeat took 1.1s
W191214 06:36:42.933008 273690 storage/node_liveness.go:559  [n4,liveness-hb] slow heartbeat took 1.6s
W191214 06:36:42.941900 271635 storage/store_raft.go:496  [n1,s1,r3/6:/System/{NodeLive…-tsd}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191214 06:36:42.947886 273619 storage/store_raft.go:496  [n4,s4,r3/3:/System/{NodeLive…-tsd}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191214 06:36:43.077093 271762 storage/store_raft.go:496  [n1,s1,r9/1:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191214 06:36:43.080905 273062 storage/store_raft.go:496  [n3,s3,r9/4:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191214 06:36:43.088711 273581 storage/store_raft.go:496  [n4,s4,r9/5:/Table/1{3-4}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191214 06:36:43.097262 274638 storage/store_raft.go:496  [n5,s5,r51/2:/Table/53/1/1{40-60}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
I191214 06:36:43.313316 318433 storage/replica_raft.go:283  [n5,s5,r9/2:/Table/1{3-4}] proposing SIMPLE(l4) ADD_REPLICA[(n3,s3):4LEARNER]: after=[(n1,s1):1 (n5,s5):2 (n2,s2):3 (n3,s3):4LEARNER] next=5
W191214 06:36:43.366241 271738 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.7s [applied=2, batches=1, state_assertions=0]
I191214 06:36:43.449828 315361 storage/replica_command.go:1706  [n5,s5,r36/2:/Table/53/1/{20-40}] change replicas (add [] remove [(n1,s1):1LEARNER]): existing descriptor r36:/Table/53/1/{20-40} [(n1,s1):1LEARNER, (n5,s5):2, (n2,s2):3, (n4,s4):4, next=5, gen=22, sticky=9223372036.854775807,2147483647]
W191214 06:36:43.582233 317591 storage/replica_raft.go:98  [n5,s5,r35/2:/Table/53/1/{40-60}] context canceled before proposing: 1 HeartbeatTxn
I191214 06:36:43.595460 318530 storage/raft_snapshot_queue.go:169  [n3,raftsnapshot,s3,r59/3:/{Table/53/1/1…-Max}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):4LEARNER
I191214 06:36:43.638674 318532 storage/raft_snapshot_queue.go:169  [n3,raftsnapshot,s3,r59/3:/{Table/53/1/1…-Max}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):4LEARNER
I191214 06:36:43.643456 317712 storage/store_snapshot.go:977  [n3,s3,r59/3:/{Table/53/1/1…-Max}] sending LEARNER snapshot c4c81e83 at applied index 16
I191214 06:36:43.645262 317712 storage/store_snapshot.go:1020  [n3,s3,r59/3:/{Table/53/1/1…-Max}] streamed snapshot to (n4,s4):4LEARNER: kv pairs: 26, log entries: 0, rate-limit: 8.0 MiB/sec, 0.06s
I191214 06:36:43.676554 318598 storage/replica_raftstorage.go:798  [n4,s4,r59/4:{-}] applying LEARNER snapshot [id=c4c81e83 index=16]
W191214 06:36:43.809361 274592 storage/store_raft.go:496  [n5,s5,r33/2:/Table/53/1/1{00-40}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=1]
I191214 06:36:43.879685 312876 storage/store_snapshot.go:977  [n5,replicate,s5,r35/2:/Table/53/1/{40-60}] sending LEARNER snapshot 5b29e188 at applied index 47
I191214 06:36:43.886900 312876 storage/store_snapshot.go:1020  [n5,replicate,s5,r35/2:/Table/53/1/{40-60}] streamed snapshot to (n3,s3):5LEARNER: kv pairs: 30, log entries: 0, rate-limit: 8.0 MiB/sec, 0.14s
I191214 06:36:43.902158 318590 storage/raft_snapshot_queue.go:169  [n3,raftsnapshot,s3,r49/4:/Table/53/1/1{60-80}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):5LEARNER
I191214 06:36:43.992888 318639 storage/raft_snapshot_queue.go:169  [n5,raftsnapshot,s5,r35/2:/Table/53/1/{40-60}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):5LEARNER
I191214 06:36:43.993080 318669 storage/replica_raftstorage.go:798  [n3,s3,r35/5:{-}] applying LEARNER snapshot [id=5b29e188 index=47]
I191214 06:36:44.016089 318642 storage/raft_snapshot_queue.go:169  [n5,raftsnapshot,s5,r35/2:/Table/53/1/{40-60}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):5LEARNER
I191214 06:36:44.020422 318598 storage/replica_raftstorage.go:819  [n4,s4,r59/4:/{Table/53/1/1…-Max}] applied LEARNER snapshot [total=343ms ingestion=4@15ms id=c4c81e83 index=16]
W191214 06:36:44.200633 274594 storage/store_raft.go:496  [n5,s5,r9/2:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191214 06:36:44.208414 273602 storage/store_raft.go:496  [n4,s4,r9/5:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191214 06:36:44.211088 272718 storage/store_raft.go:496  [n2,s2,r9/3:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
I191214 06:36:44.218475 317629 storage/store_snapshot.go:977  [n3,replicate,s3,r49/4:/Table/53/1/1{60-80}] sending LEARNER snapshot 80f5b249 at applied index 50
I191214 06:36:44.220145 317712 storage/replica_command.go:1706  [n3,s3,r59/3:/{Table/53/1/1…-Max}] change replicas (add [(n4,s4):4VOTER_INCOMING] remove [(n1,s1):1VOTER_DEMOTING]): existing descriptor r59:/{Table/53/1/180-Max} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n4,s4):4LEARNER, next=5, gen=23, sticky=9223372036.854775807,2147483647]
I191214 06:36:44.228746 317629 storage/store_snapshot.go:1020  [n3,replicate,s3,r49/4:/Table/53/1/1{60-80}] streamed snapshot to (n4,s4):5LEARNER: kv pairs: 31, log entries: 0, rate-limit: 8.0 MiB/sec, 0.50s
W191214 06:36:44.252732 273059 storage/store_raft.go:496  [n3,s3,r9/4:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191214 06:36:44.259886 271770 storage/store_raft.go:496  [n1,s1,r9/1:/Table/1{3-4}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
I191214 06:36:44.286920 318579 storage/replica_raftstorage.go:798  [n4,s4,r49/5:{-}] applying LEARNER snapshot [id=80f5b249 index=50]
I191214 06:36:44.319574 318807 storage/raft_snapshot_queue.go:169  [n3,raftsnapshot,s3,r49/4:/Table/53/1/1{60-80}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):5LEARNER
I191214 06:36:44.321042 272761 server/status/runtime.go:498  [n2] runtime stats: 2.1 GiB RSS, 2021 goroutines, 96 MiB/66 MiB/204 MiB GO alloc/idle/total, 213 MiB/267 MiB CGO alloc/total, 963.0 CGO/sec, 228.1/20.9 %(u/s)time, 0.6 %gc (7x), 2.9 MiB/2.9 MiB (r/w)net
I191214 06:36:44.682742 318669 storage/replica_raftstorage.go:819  [n3,s3,r35/5:/Table/53/1/{40-60}] applied LEARNER snapshot [total=689ms ingestion=4@180ms id=5b29e188 index=47]

Repro

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

danhhz · 2019-12-16T22:41:29Z

@ajwerner this just showed up in #37883 (comment) as well

ajwerner · 2019-12-16T22:43:19Z

Nice! We're close to sleuthing this one. It's related to creating a new transaction inside of InternalExecutor.Exec leading to an orphaned old txn and a new transaction anchored in the wrong place. It's a pretty gnarly bug.

ajwerner · 2019-12-16T23:09:38Z

Okay, we think this comes down to an s/nil, nil/nil, err/ here:

cockroach/pkg/sql/physical_schema_accessors.go

Line 197 in 1092fb6

return nil, nil

Proving that hypothesis with some stressing now.

ajwerner · 2019-12-16T23:10:07Z

@danhhz we should probably push the Alpha for this

nvanbenschoten · 2019-12-16T23:12:13Z

Is that the issue or is this?
https://github.com/cockroachdb/cockroach/pull/41977/files#diff-302100451a82b3ea6099b2ca508dde8aR1754

cockroach-teamcity · 2019-12-16T23:15:38Z

(ccl/importccl).TestMultiNodeExportStmt failed on master@1092fb6eb353d8a07962248a91683be38353aa05:

Fatal error:

F191216 22:36:16.324278 287011 storage/replica_init.go:276  [n1,s1,r9/1:/Table/1{3-4}] range descriptor ID (60) does not match replica's range ID (9)

Stack:

goroutine 287011 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0xa4a4401, 0x0, 0x0, 0xda07a7)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xbf
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x9ad6a40, 0xc000000004, 0x922443f, 0x17, 0x114, 0xc0030c0ea0, 0x59)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:214 +0xc1c
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x6ba75c0, 0xc00416a3c0, 0xc000000004, 0x2, 0x5d2fe3f, 0x3f, 0xc007d56330, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x291
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x6ba75c0, 0xc00416a3c0, 0x1, 0x4, 0x5d2fe3f, 0x3f, 0xc007d56330, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:155
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).setDesc(0xc00290c000, 0x6ba75c0, 0xc00416a3c0, 0xc000e788c0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_init.go:276 +0x907
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleDescResult(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_result.go:263
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).handleNonTrivialReplicatedEvalResult(0xc00290c0d0, 0x6ba75c0, 0xc00416a3c0, 0xc001c95c20, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1118 +0xa6f
github.com/cockroachdb/cockroach/pkg/storage.(*replicaStateMachine).ApplySideEffects(0xc00290c0d0, 0x6be4500, 0xc0086e1008, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_application_state_machine.go:1001 +0xb60
github.com/cockroachdb/cockroach/pkg/storage/apply.mapCheckedCmdIter(0x14602008f358, 0xc00290c2e8, 0xc007d57048, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/cmd.go:182 +0x129
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).applyOneBatch(0xc007d57578, 0x6ba75c0, 0xc0048a65a0, 0x6be45c0, 0xc00290c288, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:281 +0x272
github.com/cockroachdb/cockroach/pkg/storage/apply.(*Task).ApplyCommittedEntries(0xc007d57578, 0x6ba75c0, 0xc0048a65a0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/apply/task.go:247 +0x103
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReadyRaftMuLocked(0xc00290c000, 0x6ba75c0, 0xc0048a65a0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:721 +0x10fa
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).handleRaftReady(0xc00290c000, 0x6ba75c0, 0xc0048a65a0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_raft.go:395 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processReady(0xc0041c0000, 0x6ba75c0, 0xc001643770, 0x9)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store_raft.go:487 +0x1a0
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc0014693b0, 0x6ba75c0, 0xc001643770)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:226 +0x31a
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x6ba75c0, 0xc001643770)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc004050100, 0xc002c71400, 0xc0040500f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:190 +0xc4

Log preceding fatal error

W191216 22:36:14.108774 289799 storage/store_raft.go:496  [n5,s5,r50/3:/Table/53/1/1{40-60}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=1]
I191216 22:36:14.194983 331567 storage/replica_raft.go:247  [n1,s1,r9/1:/Table/1{3-4}] proposing SIMPLE(l4) ADD_REPLICA[(n2,s2):4LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n5,s5):3 (n2,s2):4LEARNER] next=5
W191216 22:36:14.285725 288872 storage/store_raft.go:496  [n4,s4,r9/4:/Table/1{3-4}] handle raft ready: 0.9s [applied=1, batches=1, state_assertions=0]
W191216 22:36:14.287132 289633 storage/store_raft.go:496  [n5,s5,r9/3:/Table/1{3-4}] handle raft ready: 0.9s [applied=1, batches=1, state_assertions=0]
I191216 22:36:14.346877 330054 storage/replica_command.go:1706  [n3,s3,r36/2:/Table/53/1/{40-60}] change replicas (add [(n2,s2):4VOTER_INCOMING] remove [(n5,s5):3VOTER_DEMOTING]): existing descriptor r36:/Table/53/1/{40-60} [(n1,s1):1, (n3,s3):2, (n5,s5):3, (n2,s2):4LEARNER, next=5, gen=19, sticky=9223372036.854775807,2147483647]
W191216 22:36:14.398945 289751 storage/store_raft.go:496  [n5,s5,r2/2:/System/NodeLiveness{-Max}] handle raft ready: 1.0s [applied=2, batches=1, state_assertions=0]
I191216 22:36:14.512859 332038 storage/raft_snapshot_queue.go:169  [n2,raftsnapshot,s2,r50/4:/Table/53/1/1{40-60}] skipping snapshot; replica is likely a learner in the process of being added: (n4,s4):5LEARNER
I191216 22:36:14.537759 330805 storage/store_snapshot.go:977  [n2,replicate,s2,r50/4:/Table/53/1/1{40-60}] sending LEARNER snapshot 4925e020 at applied index 50
I191216 22:36:14.541376 330805 storage/store_snapshot.go:1020  [n2,replicate,s2,r50/4:/Table/53/1/1{40-60}] streamed snapshot to (n4,s4):5LEARNER: kv pairs: 31, log entries: 0, rate-limit: 8.0 MiB/sec, 0.05s
I191216 22:36:14.548914 331994 storage/replica_raftstorage.go:798  [n4,s4,r50/5:{-}] applying LEARNER snapshot [id=4925e020 index=50]
W191216 22:36:14.940401 289751 storage/store_raft.go:496  [n5,s5,r2/2:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:14.994007 289758 storage/store_raft.go:496  [n5,s5,r59/3:/Table/53/1/{80-100}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:14.998310 287011 storage/store_raft.go:496  [n1,s1,r9/1:/Table/1{3-4}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.000569 288868 storage/store_raft.go:496  [n4,s4,r2/3:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.009299 286991 storage/store_raft.go:496  [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.011770 288279 storage/store_raft.go:496  [n3,s3,r2/4:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.029268 287940 storage/store_raft.go:496  [n2,s2,r2/5:/System/NodeLiveness{-Max}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.031904 288280 storage/store_raft.go:496  [n3,s3,r59/2:/Table/53/1/{80-100}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.077605 288931 storage/store_raft.go:496  [n4,s4,r59/1:/Table/53/1/{80-100}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.091695 288305 storage/store_raft.go:496  [n3,s3,r9/5:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.094228 287924 storage/store_raft.go:496  [n2,s2,r9/2:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.096173 289667 storage/store_raft.go:496  [n5,s5,r9/3:/Table/1{3-4}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
I191216 22:36:15.114465 331994 storage/replica_raftstorage.go:819  [n4,s4,r50/5:/Table/53/1/1{40-60}] applied LEARNER snapshot [total=565ms ingestion=4@90ms id=4925e020 index=50]
W191216 22:36:15.156681 288864 storage/store_raft.go:496  [n4,s4,r9/4:/Table/1{3-4}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.168558 289660 storage/store_raft.go:496  [n5,s5,r34/3:/Table/53/1/{60-80}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W191216 22:36:15.185698 288935 storage/store_raft.go:496  [n4,s4,r34/4:/Table/53/1/{60-80}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
I191216 22:36:15.476444 286788 server/status/runtime.go:498  [n1] runtime stats: 2.1 GiB RSS, 2013 goroutines, 125 MiB/33 MiB/204 MiB GO alloc/idle/total, 258 MiB/308 MiB CGO alloc/total, 679.5 CGO/sec, 227.3/21.4 %(u/s)time, 0.6 %gc (5x), 2.3 MiB/2.3 MiB (r/w)net
W191216 22:36:15.519357 288279 storage/store_raft.go:496  [n3,s3,r2/4:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.526833 286977 storage/store_raft.go:496  [n1,s1,r60/1:/Table/53/1/1{20-40}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:15.589324 286985 storage/store_raft.go:496  [n1,s1,r36/1:/Table/53/1/{40-60}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=0]
W191216 22:36:15.607072 289712 storage/store_raft.go:496  [n5,s5,r36/3:/Table/53/1/{40-60}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=0]
I191216 22:36:15.617700 330805 storage/replica_command.go:1706  [n2,replicate,s2,r50/4:/Table/53/1/1{40-60}] change replicas (add [(n4,s4):5VOTER_INCOMING] remove [(n5,s5):3VOTER_DEMOTING]): existing descriptor r50:/Table/53/1/1{40-60} [(n2,s2):4, (n3,s3):2, (n5,s5):3, (n4,s4):5LEARNER, next=6, gen=23, sticky=9223372036.854775807,2147483647]
W191216 22:36:15.636658 289865 storage/node_liveness.go:559  [n5,liveness-hb] slow heartbeat took 2.7s
W191216 22:36:15.638524 288374 storage/node_liveness.go:559  [n3,liveness-hb] slow heartbeat took 2.7s
W191216 22:36:15.641156 288028 storage/node_liveness.go:559  [n2,liveness-hb] slow heartbeat took 3.5s
W191216 22:36:15.701870 287909 storage/store_raft.go:496  [n2,s2,r36/4:/Table/53/1/{40-60}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191216 22:36:15.820329 289758 storage/store_raft.go:496  [n5,s5,r59/3:/Table/53/1/{80-100}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.841774 288280 storage/store_raft.go:496  [n3,s3,r59/2:/Table/53/1/{80-100}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.878471 288305 storage/store_raft.go:496  [n3,s3,r1/5:/{Min-System/NodeL…}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.881975 287939 storage/store_raft.go:496  [n2,s2,r1/4:/{Min-System/NodeL…}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.913897 288860 storage/store_raft.go:496  [n4,s4,r1/3:/{Min-System/NodeL…}] handle raft ready: 0.8s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.952498 288931 storage/store_raft.go:496  [n4,s4,r59/1:/Table/53/1/{80-100}] handle raft ready: 0.9s [applied=1, batches=1, state_assertions=1]
W191216 22:36:15.966742 288334 storage/store_raft.go:496  [n3,s3,r60/2:/Table/53/1/1{20-40}] handle raft ready: 0.5s [applied=0, batches=0, state_assertions=0]
W191216 22:36:16.055335 288313 storage/store_raft.go:496  [n3,s3,r8/4:/Table/1{2-3}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191216 22:36:16.068144 289668 storage/store_raft.go:496  [n5,s5,r60/3:/Table/53/1/1{20-40}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:16.083262 287918 storage/store_raft.go:496  [n2,s2,r8/2:/Table/1{2-3}] handle raft ready: 0.6s [applied=1, batches=1, state_assertions=0]
W191216 22:36:16.104320 286977 storage/store_raft.go:496  [n1,s1,r60/1:/Table/53/1/1{20-40}] handle raft ready: 0.6s [applied=0, batches=0, state_assertions=0]
W191216 22:36:16.111335 287016 storage/store_raft.go:496  [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 1.0s [applied=1, batches=1, state_assertions=1]
W191216 22:36:16.145929 289742 storage/store_raft.go:496  [n5,s5,r1/2:/{Min-System/NodeL…}] handle raft ready: 1.0s [applied=1, batches=1, state_assertions=1]
W191216 22:36:16.302400 288868 storage/store_raft.go:496  [n4,s4,r2/3:/System/NodeLiveness{-Max}] handle raft ready: 0.9s [applied=3, batches=1, state_assertions=0]

Repro

Parameters:

GOFLAGS=-json

make stressrace TESTS=TestMultiNodeExportStmt PKG=./pkg/ccl/importccl TESTTIMEOUT=5m STRESSFLAGS=-timeout 5m' 2>&1

_{powered by pkg/cmd/internal/issues}

andreimatei · 2019-12-16T23:19:04Z

#22615 strikes again

43145: storage/diskmap: remove SortedDiskMapIterator.{Key,Value} r=petermattis a=petermattis Remove `SortedDiskMapIterator.{Key,Value}` as these accessors are horribly slow due to performing an allocation on every call. Change the existing uses of these methods to `Unsafe{Key,Value}` adding copying when necessary. Most of the use cases were easy to fix, though note that `diskRowIterator.Row()` contains a TODO because the removal of the allocation there caused many test failures. The `PebbleMapIteration` benchmarks still show a regression in comparison to f5009c8. That regression is entirely due to Pebble's new memtable sizing heuristics which start with a small memtable size and dynamically grow the size up to the configured limit. Adding a knob to disable that behavior for the purposes of a benchmark does not seem worthwhile. ``` name old time/op new time/op delta RocksDBMapIteration/InputSize4096-16 1.18ms ± 3% 0.81ms ± 0% -31.56% (p=0.000 n=10+8) RocksDBMapIteration/InputSize16384-16 5.83ms ± 1% 4.14ms ± 3% -29.13% (p=0.000 n=9+10) RocksDBMapIteration/InputSize65536-16 24.8ms ± 1% 17.7ms ± 3% -28.54% (p=0.000 n=9+10) RocksDBMapIteration/InputSize262144-16 137ms ± 0% 105ms ± 2% -23.65% (p=0.000 n=9+9) RocksDBMapIteration/InputSize1048576-16 547ms ± 1% 430ms ± 1% -21.44% (p=0.000 n=8+9) PebbleMapIteration/InputSize4096-16 594µs ± 1% 323µs ± 2% -45.65% (p=0.000 n=9+9) PebbleMapIteration/InputSize16384-16 3.29ms ± 1% 2.15ms ± 1% -34.70% (p=0.000 n=10+9) PebbleMapIteration/InputSize65536-16 16.0ms ± 7% 11.2ms ±11% -30.26% (p=0.000 n=10+10) PebbleMapIteration/InputSize262144-16 96.7ms ± 3% 76.5ms ± 5% -20.88% (p=0.000 n=10+10) PebbleMapIteration/InputSize1048576-16 267ms ± 0% 185ms ± 1% -30.60% (p=0.000 n=9+10) name old alloc/op new alloc/op delta RocksDBMapIteration/InputSize4096-16 262kB ± 0% 0kB ± 0% -99.97% (p=0.000 n=10+10) RocksDBMapIteration/InputSize16384-16 1.31MB ± 0% 0.00MB ± 0% -99.99% (p=0.000 n=10+10) RocksDBMapIteration/InputSize65536-16 5.51MB ± 0% 0.00MB ± 3% -100.00% (p=0.000 n=10+10) RocksDBMapIteration/InputSize262144-16 22.3MB ± 0% 0.0MB ± 0% -100.00% (p=0.000 n=10+10) RocksDBMapIteration/InputSize1048576-16 89.4MB ± 0% 0.0MB ± 0% -100.00% (p=0.000 n=10+9) PebbleMapIteration/InputSize4096-16 263kB ± 0% 0kB ± 0% -99.91% (p=0.000 n=10+10) PebbleMapIteration/InputSize16384-16 1.31MB ± 0% 0.00MB ± 0% -99.98% (p=0.000 n=10+8) PebbleMapIteration/InputSize65536-16 5.50MB ± 0% 0.00MB ± 3% -99.99% (p=0.000 n=10+9) PebbleMapIteration/InputSize262144-16 22.3MB ± 0% 0.0MB ± 0% -99.99% (p=0.000 n=10+7) PebbleMapIteration/InputSize1048576-16 89.3MB ± 0% 0.0MB ±26% -100.00% (p=0.000 n=10+10) name old allocs/op new allocs/op delta RocksDBMapIteration/InputSize4096-16 8.20k ± 0% 0.00k ± 0% -99.96% (p=0.000 n=10+10) RocksDBMapIteration/InputSize16384-16 41.0k ± 0% 0.0k ± 0% -99.99% (p=0.000 n=10+10) RocksDBMapIteration/InputSize65536-16 172k ± 0% 0k ± 0% -100.00% (p=0.000 n=10+10) RocksDBMapIteration/InputSize262144-16 696k ± 0% 0k ± 0% -100.00% (p=0.000 n=10+10) RocksDBMapIteration/InputSize1048576-16 2.79M ± 0% 0.00M ± 0% -100.00% (p=0.000 n=9+9) PebbleMapIteration/InputSize4096-16 8.20k ± 0% 0.01k ± 0% -99.94% (p=0.000 n=10+10) PebbleMapIteration/InputSize16384-16 41.0k ± 0% 0.0k ± 0% -99.99% (p=0.000 n=10+10) PebbleMapIteration/InputSize65536-16 172k ± 0% 0k ± 0% -100.00% (p=0.000 n=10+10) PebbleMapIteration/InputSize262144-16 696k ± 0% 0k ± 0% -100.00% (p=0.000 n=10+10) PebbleMapIteration/InputSize1048576-16 2.79M ± 0% 0.00M ± 9% -100.00% (p=0.000 n=10+10) ``` Release note: None 43207: roachprod/gce: use 2 SSDs for c2 machine types r=nvanbenschoten a=nvanbenschoten This is required to spin up c2 instances, just as it is to spin up n2 instances. Release note: None 43214: sql: stop swallowing errors from UncachedPhysicalAccessor.IsValidSchema r=andreimatei a=ajwerner Before this commit we'd swallow retriable errors during execution. This can be very problematic as it can lead to lost writes and other general funkiness. We're opting to not write a test for this specific case as there is ongoing work to change interfaces to preclude this sort of bug. Fixes #43067 Fixes #37883 (comment) Release note: None 43219: pgwire/pgcode: fix DeprecatedInternalConnectionFailure r=nvanbenschoten a=nvanbenschoten This was moved from "08006" in #41451, not "XXC03". Release note: None Co-authored-by: Peter Mattis <[email protected]> Co-authored-by: Nathan VanBenschoten <[email protected]> Co-authored-by: Andrew Werner <[email protected]>

cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Dec 10, 2019

cockroach-teamcity added this to the 20.1 milestone Dec 10, 2019

cockroach-teamcity assigned dt Dec 10, 2019

tbg assigned nvanbenschoten and unassigned dt Dec 10, 2019

danhhz mentioned this issue Dec 16, 2019

ccl/partitionccl: TestRepartitioning failed under stress #37883

Closed

bdarnell mentioned this issue Dec 16, 2019

build: Lint against if err != nil { return nil } #19316

Closed

andreimatei assigned ajwerner and unassigned nvanbenschoten Dec 16, 2019

ajwerner mentioned this issue Dec 16, 2019

sql: stop swallowing errors from UncachedPhysicalAccessor.IsValidSchema #43214

Merged

craig bot closed this as completed in 892ab04 Dec 17, 2019

nvanbenschoten mentioned this issue Sep 21, 2021

roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #70410

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ccl/importccl: TestMultiNodeExportStmt failed #43067

ccl/importccl: TestMultiNodeExportStmt failed #43067

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

tbg commented Dec 10, 2019

ajwerner commented Dec 10, 2019

ajwerner commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 12, 2019

cockroach-teamcity commented Dec 12, 2019

cockroach-teamcity commented Dec 14, 2019

danhhz commented Dec 16, 2019

ajwerner commented Dec 16, 2019

ajwerner commented Dec 16, 2019

ajwerner commented Dec 16, 2019

nvanbenschoten commented Dec 16, 2019

cockroach-teamcity commented Dec 16, 2019

andreimatei commented Dec 16, 2019

ccl/importccl: TestMultiNodeExportStmt failed #43067

ccl/importccl: TestMultiNodeExportStmt failed #43067

Comments

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

tbg commented Dec 10, 2019

ajwerner commented Dec 10, 2019

ajwerner commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 10, 2019

cockroach-teamcity commented Dec 12, 2019

cockroach-teamcity commented Dec 12, 2019

cockroach-teamcity commented Dec 14, 2019

danhhz commented Dec 16, 2019

ajwerner commented Dec 16, 2019

ajwerner commented Dec 16, 2019

ajwerner commented Dec 16, 2019

nvanbenschoten commented Dec 16, 2019

cockroach-teamcity commented Dec 16, 2019

andreimatei commented Dec 16, 2019