Skip to content

Instantly share code, notes, and snippets.

@tbg

tbg/gist:fd882caa6ed72e7af0cbd7c8fb0c3504

Created August 22, 2019 08:57
Show Gist options
  • Save tbg/fd882caa6ed72e7af0cbd7c8fb0c3504 to your computer and use it in GitHub Desktop.
Save tbg/fd882caa6ed72e7af0cbd7c8fb0c3504 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
make stress PKG=./pkg/sql/distsqlplan/ STRESSFLAGS='-maxruns 3000 -stderr=false' TESTS=TestSpanResolverUsesCaches
tschottdorf@gceworker-tschottdorf:~$ cat /tmp/go-stress093573368
I190822 08:54:55.324581 1 rand.go:83 Random seed: -5098855079789502367
=== RUN TestSpanResolverUsesCaches
I190822 08:54:55.335859 56 base/addr_validation.go:296 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.335891 56 base/addr_validation.go:342 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W190822 08:54:55.346974 56 server/status/runtime.go:308 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I190822 08:54:55.380399 56 server/server.go:902 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I190822 08:54:55.391610 56 server/config.go:502 [n?] 1 storage engine initialized
I190822 08:54:55.391632 56 server/config.go:505 [n?] RocksDB cache size: 128 MiB
I190822 08:54:55.391640 56 server/config.go:505 [n?] store 0: in-memory, size 0 B
I190822 08:54:55.391808 56 server/server.go:1350 [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I190822 08:54:55.391846 56 server/server.go:1360 [n?] **** add additional nodes by specifying --join=127.0.0.1:39651
I190822 08:54:55.394971 56 server/node.go:317 [n?] **** cluster bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0 has been created
I190822 08:54:55.395218 56 gossip/gossip.go:394 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:39651" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc1" > > ServerVersion:<major_val:19 minor_val:1 patch:0 unstable:8 > build_tag:"v19.2.0-alpha.20190606-1632-gfad16a0f4c" started_at:1566464095395061120 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:33151" >
I190822 08:54:55.398863 56 server/node.go:422 [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=8.7 KiB), ranges=20, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=929.00 pMax=7848.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I190822 08:54:55.398967 56 storage/stores.go:240 [n1] read 0 node addresses from persistent storage
I190822 08:54:55.399085 56 server/node.go:636 [n1] connecting to gossip network to verify cluster ID...
I190822 08:54:55.399119 56 server/node.go:656 [n1] node connected via gossip and verified as part of cluster "bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0"
I190822 08:54:55.399183 56 server/node.go:503 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I190822 08:54:55.399277 56 server/server.go:1980 [n1] Could not start goroutine dumper worker due to: directory to store dumps could not be determined
I190822 08:54:55.399345 56 server/server.go:1477 [n1] starting https server at 127.0.0.1:37777 (use: 127.0.0.1:37777)
I190822 08:54:55.399418 56 server/server.go:1482 [n1] starting postgres server at 127.0.0.1:33151 (use: 127.0.0.1:33151)
I190822 08:54:55.399449 56 server/server.go:1484 [n1] starting grpc server at 127.0.0.1:39651
I190822 08:54:55.399502 56 server/server.go:1485 [n1] advertising CockroachDB node at 127.0.0.1:39651
W190822 08:54:55.399975 344 storage/store.go:1546 [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I190822 08:54:55.433363 43 sql/event_log.go:130 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I190822 08:54:55.445713 475 sql/event_log.go:130 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:19.1-8 User:root}
I190822 08:54:55.454724 594 sql/event_log.go:130 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I190822 08:54:55.478781 757 sql/event_log.go:130 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:3e6e7e7c-3eb7-4d4a-9fc9-c5c797c9de5d User:root}
I190822 08:54:55.498077 612 sql/event_log.go:130 [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I190822 08:54:55.503901 703 sql/event_log.go:130 [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I190822 08:54:55.509572 56 server/server.go:1553 [n1] done ensuring all necessary migrations have run
I190822 08:54:55.509628 56 server/server.go:1791 [n1] serving sql connections
I190822 08:54:55.512676 744 server/server_update.go:68 [n1] no need to upgrade, cluster already at the newest version
I190822 08:54:55.513243 746 sql/event_log.go:130 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:39651 Attrs: Locality:region=test,dc=dc1 ServerVersion:19.1-8 BuildTag:v19.2.0-alpha.20190606-1632-gfad16a0f4c StartedAt:1566464095395061120 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:33151} ClusterID:bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0 StartedAt:1566464095395061120 LastUp:1566464095395061120}
I190822 08:54:55.526778 763 sql/event_log.go:130 [n1,client=127.0.0.1:57136,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.range_merge.queue_enabled Value:false User:root}
I190822 08:54:55.529874 56 base/addr_validation.go:296 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.529898 56 base/addr_validation.go:342 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W190822 08:54:55.548610 56 server/status/runtime.go:308 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I190822 08:54:55.564996 56 server/server.go:902 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I190822 08:54:55.576142 56 server/config.go:502 [n?] 1 storage engine initialized
I190822 08:54:55.576164 56 server/config.go:505 [n?] RocksDB cache size: 128 MiB
I190822 08:54:55.576173 56 server/config.go:505 [n?] store 0: in-memory, size 0 B
W190822 08:54:55.576340 56 gossip/gossip.go:1517 [n?] no incoming or outgoing connections
I190822 08:54:55.576396 56 server/server.go:1350 [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I190822 08:54:55.587775 854 gossip/client.go:124 [n?] started gossip client to 127.0.0.1:39651
I190822 08:54:55.588253 862 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:46533
I190822 08:54:55.588848 56 server/node.go:636 [n?] connecting to gossip network to verify cluster ID...
I190822 08:54:55.588881 56 server/node.go:656 [n?] node connected via gossip and verified as part of cluster "bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0"
I190822 08:54:55.589547 862 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:46533
I190822 08:54:55.604726 56 server/node.go:372 [n?] new node allocated ID 2
I190822 08:54:55.604814 56 gossip/gossip.go:394 [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:46533" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc2" > > ServerVersion:<major_val:19 minor_val:1 patch:0 unstable:8 > build_tag:"v19.2.0-alpha.20190606-1632-gfad16a0f4c" started_at:1566464095604745953 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:36663" >
I190822 08:54:55.604864 56 storage/stores.go:240 [n2] read 0 node addresses from persistent storage
I190822 08:54:55.604934 56 storage/stores.go:259 [n2] wrote 1 node addresses to persistent storage
I190822 08:54:55.605351 83 storage/stores.go:259 [n1] wrote 1 node addresses to persistent storage
I190822 08:54:55.609468 56 server/node.go:611 [n2] bootstrapped store [n2,s2]
I190822 08:54:55.609591 56 server/node.go:503 [n2] node=2: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I190822 08:54:55.609656 56 server/server.go:1980 [n2] Could not start goroutine dumper worker due to: directory to store dumps could not be determined
I190822 08:54:55.609723 56 server/server.go:1477 [n2] starting https server at 127.0.0.1:35877 (use: 127.0.0.1:35877)
I190822 08:54:55.609752 56 server/server.go:1482 [n2] starting postgres server at 127.0.0.1:36663 (use: 127.0.0.1:36663)
I190822 08:54:55.609770 56 server/server.go:1484 [n2] starting grpc server at 127.0.0.1:46533
I190822 08:54:55.609792 56 server/server.go:1485 [n2] advertising CockroachDB node at 127.0.0.1:46533
I190822 08:54:55.637746 56 server/server.go:1553 [n2] done ensuring all necessary migrations have run
I190822 08:54:55.637821 56 server/server.go:1791 [n2] serving sql connections
I190822 08:54:55.646537 56 base/addr_validation.go:296 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.647328 56 base/addr_validation.go:342 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.656139 1035 sql/event_log.go:130 [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:127.0.0.1:46533 Attrs: Locality:region=test,dc=dc2 ServerVersion:19.1-8 BuildTag:v19.2.0-alpha.20190606-1632-gfad16a0f4c StartedAt:1566464095604745953 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:36663} ClusterID:bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0 StartedAt:1566464095604745953 LastUp:1566464095604745953}
I190822 08:54:55.656254 1033 server/server_update.go:68 [n2] no need to upgrade, cluster already at the newest version
W190822 08:54:55.666117 56 server/status/runtime.go:308 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I190822 08:54:55.675360 56 server/server.go:902 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I190822 08:54:55.690146 56 server/config.go:502 [n?] 1 storage engine initialized
I190822 08:54:55.690166 56 server/config.go:505 [n?] RocksDB cache size: 128 MiB
I190822 08:54:55.690175 56 server/config.go:505 [n?] store 0: in-memory, size 0 B
W190822 08:54:55.690258 56 gossip/gossip.go:1517 [n?] no incoming or outgoing connections
I190822 08:54:55.690298 56 server/server.go:1350 [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I190822 08:54:55.703422 1451 gossip/client.go:124 [n?] started gossip client to 127.0.0.1:39651
I190822 08:54:55.703673 1371 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:39903
I190822 08:54:55.704486 56 server/node.go:636 [n?] connecting to gossip network to verify cluster ID...
I190822 08:54:55.704526 56 server/node.go:656 [n?] node connected via gossip and verified as part of cluster "bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0"
I190822 08:54:55.705614 1371 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:39903
I190822 08:54:55.726549 56 server/node.go:372 [n?] new node allocated ID 3
I190822 08:54:55.726626 56 gossip/gossip.go:394 [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:39903" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc3" > > ServerVersion:<major_val:19 minor_val:1 patch:0 unstable:8 > build_tag:"v19.2.0-alpha.20190606-1632-gfad16a0f4c" started_at:1566464095726561320 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:40739" >
I190822 08:54:55.726684 56 storage/stores.go:240 [n3] read 0 node addresses from persistent storage
I190822 08:54:55.726715 56 storage/stores.go:259 [n3] wrote 2 node addresses to persistent storage
I190822 08:54:55.727454 83 storage/stores.go:259 [n1] wrote 2 node addresses to persistent storage
I190822 08:54:55.727755 977 storage/stores.go:259 [n2] wrote 2 node addresses to persistent storage
I190822 08:54:55.729243 56 server/node.go:611 [n3] bootstrapped store [n3,s3]
I190822 08:54:55.729336 56 server/node.go:503 [n3] node=3: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I190822 08:54:55.729382 56 server/server.go:1980 [n3] Could not start goroutine dumper worker due to: directory to store dumps could not be determined
I190822 08:54:55.729432 56 server/server.go:1477 [n3] starting https server at 127.0.0.1:34803 (use: 127.0.0.1:34803)
I190822 08:54:55.729457 56 server/server.go:1482 [n3] starting postgres server at 127.0.0.1:40739 (use: 127.0.0.1:40739)
I190822 08:54:55.729472 56 server/server.go:1484 [n3] starting grpc server at 127.0.0.1:39903
I190822 08:54:55.729488 56 server/server.go:1485 [n3] advertising CockroachDB node at 127.0.0.1:39903
I190822 08:54:55.769588 56 server/server.go:1553 [n3] done ensuring all necessary migrations have run
I190822 08:54:55.769622 56 server/server.go:1791 [n3] serving sql connections
I190822 08:54:55.772284 56 base/addr_validation.go:296 [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.772314 56 base/addr_validation.go:342 [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I190822 08:54:55.795673 1408 server/server_update.go:68 [n3] no need to upgrade, cluster already at the newest version
W190822 08:54:55.797910 56 server/status/runtime.go:308 [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I190822 08:54:55.804770 56 server/server.go:902 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I190822 08:54:55.806577 1746 sql/event_log.go:130 [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:127.0.0.1:39903 Attrs: Locality:region=test,dc=dc3 ServerVersion:19.1-8 BuildTag:v19.2.0-alpha.20190606-1632-gfad16a0f4c StartedAt:1566464095726561320 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:40739} ClusterID:bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0 StartedAt:1566464095726561320 LastUp:1566464095726561320}
I190822 08:54:55.823375 56 server/config.go:502 [n?] 1 storage engine initialized
I190822 08:54:55.823395 56 server/config.go:505 [n?] RocksDB cache size: 128 MiB
I190822 08:54:55.823404 56 server/config.go:505 [n?] store 0: in-memory, size 0 B
W190822 08:54:55.823467 56 gossip/gossip.go:1517 [n?] no incoming or outgoing connections
I190822 08:54:55.823513 56 server/server.go:1350 [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I190822 08:54:55.833784 1789 gossip/client.go:124 [n?] started gossip client to 127.0.0.1:39651
I190822 08:54:55.834108 1954 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:38207
I190822 08:54:55.834912 56 server/node.go:636 [n?] connecting to gossip network to verify cluster ID...
I190822 08:54:55.834948 56 server/node.go:656 [n?] node connected via gossip and verified as part of cluster "bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0"
I190822 08:54:55.835606 1954 gossip/server.go:227 [n1] received initial cluster-verification connection from 127.0.0.1:38207
I190822 08:54:55.856917 56 server/node.go:372 [n?] new node allocated ID 4
I190822 08:54:55.857008 56 gossip/gossip.go:394 [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:38207" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc4" > > ServerVersion:<major_val:19 minor_val:1 patch:0 unstable:8 > build_tag:"v19.2.0-alpha.20190606-1632-gfad16a0f4c" started_at:1566464095856945742 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:40259" >
I190822 08:54:55.857062 56 storage/stores.go:240 [n4] read 0 node addresses from persistent storage
I190822 08:54:55.857104 56 storage/stores.go:259 [n4] wrote 3 node addresses to persistent storage
I190822 08:54:55.857555 83 storage/stores.go:259 [n1] wrote 3 node addresses to persistent storage
I190822 08:54:55.858450 1378 storage/stores.go:259 [n3] wrote 3 node addresses to persistent storage
I190822 08:54:55.858507 977 storage/stores.go:259 [n2] wrote 3 node addresses to persistent storage
I190822 08:54:55.859750 56 server/node.go:611 [n4] bootstrapped store [n4,s4]
I190822 08:54:55.859858 56 server/node.go:503 [n4] node=4: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I190822 08:54:55.859915 56 server/server.go:1980 [n4] Could not start goroutine dumper worker due to: directory to store dumps could not be determined
I190822 08:54:55.859989 56 server/server.go:1477 [n4] starting https server at 127.0.0.1:33397 (use: 127.0.0.1:33397)
I190822 08:54:55.860019 56 server/server.go:1482 [n4] starting postgres server at 127.0.0.1:40259 (use: 127.0.0.1:40259)
I190822 08:54:55.860038 56 server/server.go:1484 [n4] starting grpc server at 127.0.0.1:38207
I190822 08:54:55.860062 56 server/server.go:1485 [n4] advertising CockroachDB node at 127.0.0.1:38207
W190822 08:54:55.882602 56 jobs/registry.go:339 [n4] unable to get node liveness: node not in the liveness table
I190822 08:54:55.883303 56 server/server.go:1553 [n4] done ensuring all necessary migrations have run
I190822 08:54:55.883368 56 server/server.go:1791 [n4] serving sql connections
I190822 08:54:55.892187 1800 sql/event_log.go:130 [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:127.0.0.1:38207 Attrs: Locality:region=test,dc=dc4 ServerVersion:19.1-8 BuildTag:v19.2.0-alpha.20190606-1632-gfad16a0f4c StartedAt:1566464095856945742 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:40259} ClusterID:bfa8c10a-51f0-46e0-8cbf-c2167d5e25c0 StartedAt:1566464095856945742 LastUp:1566464095856945742}
I190822 08:54:55.894005 1798 server/server_update.go:68 [n4] no need to upgrade, cluster already at the newest version
I190822 08:54:55.904182 763 sql/event_log.go:130 [n1,client=127.0.0.1:57136,user=root] Event: "create_database", target: 52, info: {DatabaseName:t Statement:CREATE DATABASE t User:root}
I190822 08:54:55.907766 763 sql/event_log.go:130 [n1,client=127.0.0.1:57136,user=root] Event: "create_table", target: 53, info: {TableName:t.public.test Statement:CREATE TABLE test (k INT8 PRIMARY KEY) User:root}
I190822 08:54:55.915657 56 storage/replica_command.go:283 [n1,s1,r20/1:/{Table/24-Max}] initiating a split of this range at key /Table/53/1/0 [r21] (manual)
I190822 08:54:55.926929 56 storage/replica_command.go:283 [n1,s1,r21/1:/{Table/53/1/0-Max}] initiating a split of this range at key /Table/53/1/10 [r22] (manual)
I190822 08:54:55.942046 56 storage/replica_command.go:283 [n1,s1,r22/1:/{Table/53/1/10-Max}] initiating a split of this range at key /Table/53/1/20 [r23] (manual)
I190822 08:54:56.257243 56 storage/replica_command.go:1263 [n1,s1,r21/1:/Table/53/1/{0-10}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r21:/Table/53/1/{0-10} [(n1,s1):1, next=2, gen=2]
I190822 08:54:56.261140 56 storage/replica_raft.go:291 [n1,s1,r21/1:/Table/53/1/{0-10}] proposing ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I190822 08:54:56.263419 56 storage/store_snapshot.go:995 [n1,s1,r21/1:/Table/53/1/{0-10}] sending LEARNER snapshot 3515065c at applied index 18
I190822 08:54:56.263588 2538 storage/raft_snapshot_queue.go:120 [n1,raftsnapshot,s1,r21/1:/Table/53/1/{0-10}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):2LEARNER
I190822 08:54:56.263659 56 storage/store_snapshot.go:1038 [n1,s1,r21/1:/Table/53/1/{0-10}] streamed snapshot to (n2,s2):2: kv pairs: 9, log entries: 0, rate-limit: 8.0 MiB/sec, 0.00s
I190822 08:54:56.264223 2449 storage/replica_raftstorage.go:808 [n2,s2,r21/2:{-}] applying LEARNER snapshot [id=3515065c index=18]
W190822 08:54:56.266252 2449 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.266688 2449 storage/replica_raftstorage.go:829 [n2,s2,r21/2:/Table/53/1/{0-10}] applied LEARNER snapshot [total=2ms ingestion=4@2ms id=3515065c index=18]
W190822 08:54:56.266957 17 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.267264 56 storage/replica_command.go:1263 [n1,s1,r21/1:/Table/53/1/{0-10}] change replicas (add [(n2,s2):2] remove []): existing descriptor r21:/Table/53/1/{0-10} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=3]
I190822 08:54:56.269853 56 storage/replica_raft.go:291 [n1,s1,r21/1:/Table/53/1/{0-10}] proposing ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I190822 08:54:56.270281 56 storage/replica_command.go:1263 [n1,s1,r21/1:/Table/53/1/{0-10}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r21:/Table/53/1/{0-10} [(n1,s1):1, (n2,s2):2, next=3, gen=4]
I190822 08:54:56.278281 56 storage/replica_raft.go:291 [n1,s1,r21/1:/Table/53/1/{0-10}] proposing ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I190822 08:54:56.284356 56 storage/store_snapshot.go:995 [n1,s1,r21/1:/Table/53/1/{0-10}] sending LEARNER snapshot 567cdd3e at applied index 22
I190822 08:54:56.284494 56 storage/store_snapshot.go:1038 [n1,s1,r21/1:/Table/53/1/{0-10}] streamed snapshot to (n3,s3):3: kv pairs: 13, log entries: 0, rate-limit: 8.0 MiB/sec, 0.00s
I190822 08:54:56.284512 2568 storage/raft_snapshot_queue.go:120 [n1,raftsnapshot,s1,r21/1:/Table/53/1/{0-10}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I190822 08:54:56.285227 2580 storage/replica_raftstorage.go:808 [n3,s3,r21/3:{-}] applying LEARNER snapshot [id=567cdd3e index=22]
W190822 08:54:56.286942 2580 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.287275 2580 storage/replica_raftstorage.go:829 [n3,s3,r21/3:/Table/53/1/{0-10}] applied LEARNER snapshot [total=2ms ingestion=4@2ms id=567cdd3e index=22]
W190822 08:54:56.288145 17 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.288691 56 storage/replica_command.go:1263 [n1,s1,r21/1:/Table/53/1/{0-10}] change replicas (add [(n3,s3):3] remove []): existing descriptor r21:/Table/53/1/{0-10} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=5]
I190822 08:54:56.291340 56 storage/replica_raft.go:291 [n1,s1,r21/1:/Table/53/1/{0-10}] proposing ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I190822 08:54:56.293543 56 storage/replica_command.go:1263 [n1,s1,r22/1:/Table/53/1/{10-20}] change replicas (add [(n2,s2):2LEARNER] remove []): existing descriptor r22:/Table/53/1/{10-20} [(n1,s1):1, next=2, gen=3]
I190822 08:54:56.296252 56 storage/replica_raft.go:291 [n1,s1,r22/1:/Table/53/1/{10-20}] proposing ADD_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1 (n2,s2):2LEARNER] next=3
I190822 08:54:56.301653 2612 storage/store_snapshot.go:995 [n1,raftsnapshot,s1,r22/1:/Table/53/1/{10-20}] sending RAFT snapshot 606ee41d at applied index 18
I190822 08:54:56.301760 2612 storage/store_snapshot.go:1038 [n1,raftsnapshot,s1,r22/1:/Table/53/1/{10-20}] streamed snapshot to (n2,s2):2LEARNER: kv pairs: 8, log entries: 0, rate-limit: 8.0 MiB/sec, 0.00s
I190822 08:54:56.302390 2586 storage/replica_raftstorage.go:808 [n2,s2,r22/2:{-}] applying RAFT snapshot [id=606ee41d index=18]
W190822 08:54:56.302965 2586 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
W190822 08:54:56.303930 17 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.304516 56 storage/replica_command.go:948 [n1,s1,r22/1:/Table/53/1/{10-20}] could not promote [n2,s2] to voter, rolling back: snapshot failed: (n2,s2):2: remote couldn't accept LEARNER snapshot 508ce0fd at applied index 18 with error: [n2,s2],r22: cannot apply snapshot: [n2,s2]: canApplySnapshotLocked: cannot add placeholder, have an existing placeholder range=22 [/Table/53/1/10-/Table/53/1/20) (placeholder)
W190822 08:54:56.304608 2586 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.304737 56 storage/replica_command.go:1263 [n1,s1,r22/1:/Table/53/1/{10-20}] change replicas (add [] remove [(n2,s2):2LEARNER]): existing descriptor r22:/Table/53/1/{10-20} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=4]
W190822 08:54:56.305250 2586 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.305580 2586 storage/replica_raftstorage.go:829 [n2,s2,r22/2:/Table/53/1/{10-20}] applied RAFT snapshot [total=3ms ingestion=4@2ms id=606ee41d index=18]
W190822 08:54:56.306421 17 storage/engine/rocksdb.go:116 [rocksdb] [db/version_set.cc:3086] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
I190822 08:54:56.307116 56 storage/replica_raft.go:291 [n1,s1,r22/1:/Table/53/1/{10-20}] proposing REMOVE_REPLICA[(n2,s2):2LEARNER]: after=[(n1,s1):1] next=3
I190822 08:54:56.307500 56 storage/replica_command.go:1160 [n1,s1,r22/1:/Table/53/1/{10-20}] rolled back learner (n2,s2):2LEARNER to r22:/Table/53/1/{10-20} [(n1,s1):1, next=3, gen=5]
I190822 08:54:56.307778 2575 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_ir_batcher
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.307805 2575 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.307835 2575 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.307912 2573 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] storage.replicaGC: processing replica
1 [async] intent_resolver_ir_batcher
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
E190822 08:54:56.307995 2555 storage/queue.go:1027 [n2,replicaGC,s2,r22/2:/Table/53/1/{10-20}] node unavailable; try another peer
I190822 08:54:56.308027 2574 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_ir_batcher
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.308030 2573 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_ir_batcher
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.308056 2546 storage/queue.go:518 [n2,s2,r22/2:/Table/53/1/{10-20}] rate limited in Add (replicaGC): node unavailable; try another peer
I190822 08:54:56.308179 2573 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.308197 2573 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] closedts-rangefeed-subscriber
W190822 08:54:56.308277 2445 storage/raft_transport.go:620 [n1] while processing outgoing Raft queue to node 2: rpc error: code = Unavailable desc = transport is closing:
W190822 08:54:56.308298 2571 storage/intentresolver/intent_resolver.go:610 failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
W190822 08:54:56.308880 2582 storage/raft_transport.go:620 [n3] while processing outgoing Raft queue to node 1: EOF:
I190822 08:54:56.309304 2574 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
I190822 08:54:56.309342 2574 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] closedts-rangefeed-subscriber
W190822 08:54:56.309538 2540 storage/raft_transport.go:620 [n1] while processing outgoing Raft queue to node 3: rpc error: code = Canceled desc = grpc: the client connection is closing:
I190822 08:54:56.307780 2572 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
17 [async] storage.IntentResolver: cleanup txn records
1 storage.IntentResolver: processing intents
1 [async] intent_resolver_ir_batcher
1 [async] intent_resolver_gc_batcher
1 [async] closedts-rangefeed-subscriber
1 MaybeAdd (split)
I190822 08:54:56.310067 2572 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 [async] closedts-rangefeed-subscriber
1 MaybeAdd (split)
I190822 08:54:56.310559 2575 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
I190822 08:54:56.310610 2575 util/stop/stopper.go:542 quiescing; tasks left:
2 [async] closedts-subscription
I190822 08:54:56.310632 2575 util/stop/stopper.go:542 quiescing; tasks left:
1 [async] closedts-subscription
I190822 08:54:56.311382 2573 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
I190822 08:54:56.311427 2573 util/stop/stopper.go:542 quiescing; tasks left:
2 [async] closedts-subscription
W190822 08:54:56.311549 1072 storage/raft_transport.go:620 [n2] while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
I190822 08:54:56.312157 2572 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
1 MaybeAdd (split)
I190822 08:54:56.312217 2574 util/stop/stopper.go:542 quiescing; tasks left:
3 [async] closedts-subscription
I190822 08:54:56.312222 2572 util/stop/stopper.go:542 quiescing; tasks left:
2 [async] closedts-subscription
1 MaybeAdd (split)
I190822 08:54:56.312247 2572 util/stop/stopper.go:542 quiescing; tasks left:
1 [async] closedts-subscription
1 MaybeAdd (split)
I190822 08:54:56.312253 2574 util/stop/stopper.go:542 quiescing; tasks left:
2 [async] closedts-subscription
I190822 08:54:56.312296 2574 util/stop/stopper.go:542 quiescing; tasks left:
1 [async] closedts-subscription
I190822 08:54:56.312408 2573 util/stop/stopper.go:542 quiescing; tasks left:
1 [async] closedts-subscription
I190822 08:54:56.312539 2572 util/stop/stopper.go:542 quiescing; tasks left:
1 MaybeAdd (split)
--- FAIL: TestSpanResolverUsesCaches (1.01s)
span_resolver_test.go:55: could not add [n2,s2 n3,s3] replicas to range containing /Table/53/1/10: snapshot failed: (n2,s2):2: remote couldn't accept LEARNER snapshot 508ce0fd at applied index 18 with error: [n2,s2],r22: cannot apply snapshot: [n2,s2]: canApplySnapshotLocked: cannot add placeholder, have an existing placeholder range=22 [/Table/53/1/10-/Table/53/1/20) (placeholder)
AdminChangeReplicas error
github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).changeReplicas
/home/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:395
github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).AddReplicas
/home/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:406
github.com/cockroachdb/cockroach/pkg/testutils/testcluster.(*TestCluster).AddReplicasOrFatal
/home/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/testutils/testcluster/testcluster.go:493
github.com/cockroachdb/cockroach/pkg/sql/distsqlplan_test.TestSpanResolverUsesCaches
/home/tschottdorf/go/src/github.com/cockroachdb/cockroach/pkg/sql/distsqlplan/span_resolver_test.go:55
testing.tRunner
/usr/local/go/src/testing/testing.go:865
runtime.goexit
/usr/local/go/src/runtime/asm_amd64.s:1337
FAIL
ERROR: exit status 1
tschottdorf@gceworker-tschottdorf:~$
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment