Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed test: TestShowTraceReplica #34203

Closed
cockroach-teamcity opened this issue Jan 23, 2019 · 1 comment
Closed

teamcity: failed test: TestShowTraceReplica #34203

cockroach-teamcity opened this issue Jan 23, 2019 · 1 comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
19.1

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed on master (test): TestShowTraceReplica, TestShowTraceReplica/UPSERT_INTO_d.t2_VALUES_(1)

You may want to check for open issues.

#1107084:

TestShowTraceReplica
...rage/replica_raft.go:372  [n1,s1,r20/1:/Table/{24-53}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):1] next=3
I190123 21:28:39.884320 132986 storage/store_snapshot.go:762  [n1,replicate,s1,r20/1:/Table/{24-53}] sending preemptive snapshot a2edf6c9 at applied index 22
I190123 21:28:39.885128 132874 storage/replica_command.go:244  [n1,split,s1,r22/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r23] (zone config)
I190123 21:28:39.885614 132852 storage/store.go:2656  [n2,replicaGC,s2,r20/2:/Table/{24-53}] removing replica r20/2
I190123 21:28:39.885824 132852 storage/replica_destroy.go:152  [n2,replicaGC,s2,r20/2:/Table/{24-53}] removed 6 (0+6) keys in 0ms [clear=0ms commit=0ms]
I190123 21:28:39.896040 132986 storage/store_snapshot.go:805  [n1,replicate,s1,r20/1:/Table/{24-53}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 12, rate-limit: 2.0 MiB/sec, 0.01s
I190123 21:28:39.896515 132857 storage/replica_raftstorage.go:805  [n4,s4,r20/?:{-}] applying preemptive snapshot at index 22 (id=a2edf6c9, encoded size=3608, 1 rocksdb batches, 12 log entries)
I190123 21:28:39.896759 132857 storage/replica_raftstorage.go:811  [n4,s4,r20/?:/Table/{24-53}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I190123 21:28:39.897055 132986 storage/replica_command.go:798  [n1,replicate,s1,r20/1:/Table/{24-53}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r20:/Table/{24-53} [(n1,s1):1, next=3, gen=1]
I190123 21:28:39.900346 132986 storage/replica_raft.go:372  [n1,s1,r20/1:/Table/{24-53}] proposing ADD_REPLICA((n4,s4):3): updated=[(n1,s1):1 (n4,s4):3] next=4
I190123 21:28:39.902664 133026 storage/replica_command.go:798  [n1,replicate,s1,r22/1:/Table/5{4-5}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r22:/Table/5{4-5} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I190123 21:28:39.907286 133026 storage/replica_raft.go:372  [n1,s1,r22/1:/Table/5{4-5}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):1] next=3
I190123 21:28:39.911279 133044 storage/store_snapshot.go:762  [n1,replicate,s1,r22/1:/Table/5{4-5}] sending preemptive snapshot 986127ff at applied index 18
I190123 21:28:39.911492 133044 storage/store_snapshot.go:805  [n1,replicate,s1,r22/1:/Table/5{4-5}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 0.00s
I190123 21:28:39.911934 132865 storage/replica_raftstorage.go:805  [n4,s4,r22/?:{-}] applying preemptive snapshot at index 18 (id=986127ff, encoded size=2850, 1 rocksdb batches, 8 log entries)
I190123 21:28:39.912303 132865 storage/replica_raftstorage.go:811  [n4,s4,r22/?:/Table/5{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I190123 21:28:39.912511 132891 storage/store.go:2656  [n2,replicaGC,s2,r22/2:/Table/5{4-5}] removing replica r22/2
I190123 21:28:39.912674 133044 storage/replica_command.go:798  [n1,replicate,s1,r22/1:/Table/5{4-5}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r22:/Table/5{4-5} [(n1,s1):1, next=3, gen=1]
I190123 21:28:39.912735 132891 storage/replica_destroy.go:152  [n2,replicaGC,s2,r22/2:/Table/5{4-5}] removed 6 (0+6) keys in 0ms [clear=0ms commit=0ms]
I190123 21:28:39.916271 133044 storage/replica_raft.go:372  [n1,s1,r22/1:/Table/5{4-5}] proposing ADD_REPLICA((n4,s4):3): updated=[(n1,s1):1 (n4,s4):3] next=4
I190123 21:28:39.931090 132954 sql/event_log.go:135  [n1,client=127.0.0.1:37288,user=root] Event: "set_zone_config", target: 53, info: {Target:d.t1 Config: Options:constraints = '[+n1]' User:root}
I190123 21:28:39.943093 132954 sql/event_log.go:135  [n1,client=127.0.0.1:37288,user=root] Event: "set_zone_config", target: 54, info: {Target:d.t2 Config: Options:constraints = '[+n2]' User:root}
I190123 21:28:39.953043 132954 sql/event_log.go:135  [n1,client=127.0.0.1:37288,user=root] Event: "set_zone_config", target: 55, info: {Target:d.t3 Config: Options:constraints = '[+n3]' User:root}



TestShowTraceReplica/UPSERT_INTO_d.t2_VALUES_(1)
...a_destroy.go:152  [n1,replicaGC,s1,r18/1:/Table/2{2-3}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I190123 21:43:29.407174 135710 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[3 3]] expected [[2 2]]
I190123 21:43:30.440136 135710 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[3 3]] expected [[2 2]]
I190123 21:43:30.536242 136104 storage/replica_command.go:798  [n2,replicate,s2,r3/2:/System/{NodeLive…-tsd}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r3:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n2,s2):2, next=3, gen=0]
I190123 21:43:30.562410 134083 server/status/runtime.go:464  [n1] runtime stats: 1.4 GiB RSS, 1409 goroutines, 65 MiB/44 MiB/140 MiB GO alloc/idle/total, 137 MiB/185 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (1507x), 1.8 MiB/1.8 MiB (r/w)net
I190123 21:43:30.656401 136104 storage/replica_raft.go:372  [n2,s2,r3/2:/System/{NodeLive…-tsd}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I190123 21:43:30.757409 136126 storage/store.go:2656  [n1,replicaGC,s1,r3/1:/System/{NodeLive…-tsd}] removing replica r3/1
I190123 21:43:30.759102 136126 storage/replica_destroy.go:152  [n1,replicaGC,s1,r3/1:/System/{NodeLive…-tsd}] removed 30 (22+8) keys in 1ms [clear=0ms commit=0ms]
W190123 21:43:30.834677 134085 server/node.go:869  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:23 XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}] XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}
I190123 21:43:31.047846 136263 storage/replica_command.go:798  [n4,replicate,s4,r13/2:/Table/1{7-8}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r13:/Table/1{7-8} [(n1,s1):1, (n4,s4):2, next=3, gen=0]
I190123 21:43:31.127109 136263 storage/replica_raft.go:372  [n4,s4,r13/2:/Table/1{7-8}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3
I190123 21:43:31.158533 136176 storage/store.go:2656  [n1,replicaGC,s1,r13/1:/Table/1{7-8}] removing replica r13/1
I190123 21:43:31.160147 136176 storage/replica_destroy.go:152  [n1,replicaGC,s1,r13/1:/Table/1{7-8}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I190123 21:43:31.450314 134359 server/status/runtime.go:464  [n2] runtime stats: 1.4 GiB RSS, 1407 goroutines, 38 MiB/70 MiB/140 MiB GO alloc/idle/total, 139 MiB/187 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (1509x), 1.8 MiB/1.8 MiB (r/w)net
I190123 21:43:31.550409 135710 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[3 3] [3 3] [3 3] [2 2]] expected [[2 2]]
W190123 21:43:31.670208 134361 server/node.go:869  [n2,summaries] health alerts detected: {Alerts:[{StoreID:2 Category:METRICS Description:queue.replicate.process.failure Value:5 XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}] XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}
I190123 21:43:31.760863 134665 server/status/runtime.go:464  [n3] runtime stats: 1.4 GiB RSS, 1406 goroutines, 52 MiB/57 MiB/140 MiB GO alloc/idle/total, 139 MiB/187 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (1509x), 1.8 MiB/1.8 MiB (r/w)net
W190123 21:43:31.966920 134667 server/node.go:869  [n3,summaries] health alerts detected: {Alerts:[{StoreID:3 Category:METRICS Description:queue.replicate.process.failure Value:3 XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}] XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}
I190123 21:43:32.033058 134924 server/status/runtime.go:464  [n4] runtime stats: 1.4 GiB RSS, 1407 goroutines, 62 MiB/48 MiB/140 MiB GO alloc/idle/total, 139 MiB/187 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (1509x), 1.8 MiB/1.8 MiB (r/w)net
W190123 21:43:32.281683 134926 server/node.go:869  [n4,summaries] health alerts detected: {Alerts:[{StoreID:4 Category:METRICS Description:queue.replicate.process.failure Value:5 XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}] XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}



TestShowTraceReplica/UPSERT_INTO_d.t2_VALUES_(1)
....543447 135374 storage/replica_raft.go:372  [n4,s4,r14/3:/Table/1{8-9}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):3] next=4
I190123 21:29:24.546418 135483 storage/store.go:2656  [n1,replicaGC,s1,r14/1:/Table/1{8-9}] removing replica r14/1
I190123 21:29:24.546660 135483 storage/replica_destroy.go:152  [n1,replicaGC,s1,r14/1:/Table/1{8-9}] removed 7 (0+7) keys in 0ms [clear=0ms commit=0ms]
I190123 21:29:24.622403 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:25.629818 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:26.540250 135503 storage/replica_command.go:798  [n4,replicate,s4,r9/3:/Table/1{3-4}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{3-4} [(n2,s2):2, (n4,s4):3, next=4, gen=0]
I190123 21:29:26.544386 135503 storage/replica_raft.go:372  [n4,s4,r9/3:/Table/1{3-4}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n4,s4):3] next=4
I190123 21:29:26.546052 135547 storage/store.go:2656  [n2,replicaGC,s2,r9/2:/Table/1{3-4}] removing replica r9/2
I190123 21:29:26.546501 135547 storage/replica_destroy.go:152  [n2,replicaGC,s2,r9/2:/Table/1{3-4}] removed 405 (398+7) keys in 0ms [clear=0ms commit=0ms]
I190123 21:29:26.634053 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:27.637994 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:28.642319 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:29.069908 131690 server/status/runtime.go:464  [n1] runtime stats: 232 MiB RSS, 1425 goroutines, 65 MiB/41 MiB/140 MiB GO alloc/idle/total, 52 MiB/86 MiB CGO alloc/total, 212.6 CGO/sec, 4.0/0.6 %(u/s)time, 0.0 %gc (1x), 18 MiB/18 MiB (r/w)net
I190123 21:29:29.282554 131939 server/status/runtime.go:464  [n2] runtime stats: 233 MiB RSS, 1425 goroutines, 71 MiB/36 MiB/140 MiB GO alloc/idle/total, 52 MiB/87 MiB CGO alloc/total, 213.2 CGO/sec, 3.7/0.5 %(u/s)time, 0.0 %gc (0x), 18 MiB/18 MiB (r/w)net
I190123 21:29:29.423933 132211 server/status/runtime.go:464  [n3] runtime stats: 233 MiB RSS, 1425 goroutines, 46 MiB/57 MiB/140 MiB GO alloc/idle/total, 52 MiB/87 MiB CGO alloc/total, 213.2 CGO/sec, 4.1/0.5 %(u/s)time, 0.0 %gc (1x), 18 MiB/18 MiB (r/w)net
I190123 21:29:29.514096 132504 server/status/runtime.go:464  [n4] runtime stats: 234 MiB RSS, 1425 goroutines, 46 MiB/58 MiB/140 MiB GO alloc/idle/total, 53 MiB/88 MiB CGO alloc/total, 213.2 CGO/sec, 4.1/0.6 %(u/s)time, 0.0 %gc (1x), 18 MiB/18 MiB (r/w)net
I190123 21:29:29.646815 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
I190123 21:29:30.650858 133624 sql/show_trace_replica_test.go:100  SucceedsSoon: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
        show_trace_replica_test.go:100: condition failed to evaluate within 45s: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]
            goroutine 133624 [running]:
            runtime/debug.Stack(0xa7a358200, 0xc000793320, 0x3299da0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x32fce00, 0xc0056df000, 0xc000308f00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:49 +0x103
            github.com/cockroachdb/cockroach/pkg/sql_test.TestShowTraceReplica.func2(0xc0056df000)
            	/go/src/github.com/cockroachdb/cockroach/pkg/sql/show_trace_replica_test.go:100 +0x90
            testing.tRunner(0xc0056df000, 0xc000308ec0)
            	/usr/local/go/src/testing/testing.go:827 +0xbf
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:878 +0x35c



TestShowTraceReplica
...replica_command.go:798  [n1,replicate,s1,r20/1:/Table/{24-53}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r20:/Table/{24-53} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I190123 21:43:24.319312 135392 sql/event_log.go:135  [n1,client=127.0.0.1:55280,user=root] Event: "create_table", target: 55, info: {TableName:d.public.t3 Statement:CREATE TABLE d.public.t3 (a INT8 PRIMARY KEY) User:root}
I190123 21:43:24.337211 135554 storage/replica_raft.go:372  [n1,s1,r20/1:/Table/{24-53}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n1,s1):1] next=3
I190123 21:43:24.361084 135572 storage/store_snapshot.go:762  [n1,replicate,s1,r20/1:/Table/{24-53}] sending preemptive snapshot 77b8d74b at applied index 22
I190123 21:43:24.362934 135572 storage/store_snapshot.go:805  [n1,replicate,s1,r20/1:/Table/{24-53}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 12, rate-limit: 2.0 MiB/sec, 0.01s
I190123 21:43:24.365440 135464 storage/replica_command.go:244  [n1,split,s1,r22/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r23] (zone config)
I190123 21:43:24.366653 135575 storage/replica_raftstorage.go:805  [n4,s4,r20/?:{-}] applying preemptive snapshot at index 22 (id=77b8d74b, encoded size=3614, 1 rocksdb batches, 12 log entries)
I190123 21:43:24.371717 135575 storage/replica_raftstorage.go:811  [n4,s4,r20/?:/Table/{24-53}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I190123 21:43:24.376579 135529 storage/store.go:2656  [n3,replicaGC,s3,r20/2:/Table/{24-53}] removing replica r20/2
I190123 21:43:24.378832 135529 storage/replica_destroy.go:152  [n3,replicaGC,s3,r20/2:/Table/{24-53}] removed 6 (0+6) keys in 1ms [clear=1ms commit=0ms]
I190123 21:43:24.386980 135572 storage/replica_command.go:798  [n1,replicate,s1,r20/1:/Table/{24-53}] change replicas (ADD_REPLICA (n4,s4):3): read existing descriptor r20:/Table/{24-53} [(n1,s1):1, next=3, gen=1]
I190123 21:43:24.472021 135392 sql/event_log.go:135  [n1,client=127.0.0.1:55280,user=root] Event: "set_zone_config", target: 53, info: {Target:d.t1 Config: Options:constraints = '[+n1]' User:root}
I190123 21:43:24.494629 135572 storage/replica_raft.go:372  [n1,s1,r20/1:/Table/{24-53}] proposing ADD_REPLICA((n4,s4):3): updated=[(n1,s1):1 (n4,s4):3] next=4
I190123 21:43:24.512369 135516 storage/replica_command.go:798  [n1,replicate,s1,r21/1:/Table/5{3-4}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r21:/Table/5{3-4} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I190123 21:43:24.568873 135516 storage/replica_raft.go:372  [n1,s1,r21/1:/Table/5{3-4}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n1,s1):1] next=3
I190123 21:43:24.586048 135472 storage/replica_command.go:798  [n1,replicate,s1,r9/1:/Table/1{3-4}] change replicas (REMOVE_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{3-4} [(n1,s1):1, (n2,s2):2, next=3, gen=0]
I190123 21:43:24.610588 135537 storage/store.go:2656  [n3,replicaGC,s3,r21/2:/Table/5{3-4}] removing replica r21/2
I190123 21:43:24.614709 135537 storage/replica_destroy.go:152  [n3,replicaGC,s3,r21/2:/Table/5{3-4}] removed 6 (0+6) keys in 1ms [clear=0ms commit=0ms]
I190123 21:43:24.623647 135392 sql/event_log.go:135  [n1,client=127.0.0.1:55280,user=root] Event: "set_zone_config", target: 54, info: {Target:d.t2 Config: Options:constraints = '[+n2]' User:root}
I190123 21:43:24.711216 135472 storage/replica_raft.go:372  [n1,s1,r9/1:/Table/1{3-4}] proposing REMOVE_REPLICA((n2,s2):2): updated=[(n1,s1):1] next=3
I190123 21:43:24.758901 135565 storage/store.go:2656  [n2,replicaGC,s2,r9/2:/Table/1{3-4}] removing replica r9/2
I190123 21:43:24.759853 135392 sql/event_log.go:135  [n1,client=127.0.0.1:55280,user=root] Event: "set_zone_config", target: 55, info: {Target:d.t3 Config: Options:constraints = '[+n3]' User:root}
I190123 21:43:24.761810 135565 storage/replica_destroy.go:152  [n2,replicaGC,s2,r9/2:/Table/1{3-4}] removed 149 (143+6) keys in 1ms [clear=1ms commit=0ms]

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.2 milestone Jan 23, 2019
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Jan 23, 2019
@tbg
Copy link
Member

tbg commented Jan 24, 2019

#34213

@tbg tbg closed this as completed Jan 24, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
19.1
Development

No branches or pull requests
2 participants
@tbg @cockroach-teamcity