Node log from failing acceptance test - never gets a node id assigned

gistfile1.txt

I161103 20:02:03.581745 1 cli/start.go:299  CockroachDB beta-20161103-50-g206dea0 (linux amd64, built 2016/11/03 19:56:32, go1.7.3)
I161103 20:02:03.682189 1 cli/backtrace.go:40  backtrace disabled: stat /opt/backtrace/bin/ptrace: no such file or directory
I161103 20:02:03.682291 1 cli/start.go:315  starting cockroach node
I161103 20:02:03.682335 1 cli/start.go:317  using local environment variables: COCKROACH_CONSISTENCY_CHECK_PANIC_ON_FAILURE, COCKROACH_SCAN_MAX_IDLE_TIME
I161103 20:02:03.683289 1 gossip/gossip.go:237  [n?] initial resolvers: [roach-ab05ac12-0:26257]
W161103 20:02:03.683376 1 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 20:02:03.685166 1 sql/session.go:171  [startup,n?] , memory usage max 0 B
I161103 20:02:03.685213 1 sql/session.go:172  [startup,n?] , memory usage max 0 B
I161103 20:02:03.686746 1 storage/engine/rocksdb.go:326  opening rocksdb instance at "/data3.0"
I161103 20:02:03.687286 35 rpc/context.go:220  [n?] dialing roach-ab05ac12-0:26257
I161103 20:02:03.709799 35 gossip/client.go:126  [n?] node 0: started gossip client to roach-ab05ac12-0:26257
I161103 20:02:03.710317 84 gossip/client.go:225  [n?] received [liveness:1 node:1 store:2 system-db cluster-id first-range liveness:2 node:2 sentinel store:1] from node 1 (10 fresh)
I161103 20:02:03.710355 38 rpc/clock_offset.go:168  [n?] 1 of 1 nodes are within the maximum offset of 250ms
I161103 20:02:03.710465 94 kv/dist_sender.go:206  [n?] gossiped first range descriptor: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I161103 20:02:03.774888 1 server/config.go:443  1 storage engine initialized
I161103 20:02:03.775406 1 server/node.go:421  [n?] store [n0,s0] not bootstrapped
I161103 20:02:03.775444 1 storage/stores.go:296  [n?] read 0 node addresses from persistent storage
I161103 20:02:03.775530 1 server/node.go:564  [n?] connecting to gossip network to verify cluster ID...
I161103 20:02:03.775659 1 server/node.go:585  [n?] node connected via gossip and verified as part of cluster {"c3a228fd-160a-43f2-8163-72c4f960d57a"}
I161103 20:02:03.775776 1 rpc/context.go:220  [n?] dialing roach-ab05ac12-1:26257
I161103 20:02:03.780285 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I161103 20:02:03.780837 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:04.281327 1 kv/dist_sender.go:1108  [n?] application error: range 1: replica {0 0 0} not lease holder; node_id:1 store_id:1 replica_id:1  is
I161103 20:02:04.281387 1 kv/dist_sender.go:1229  [n?] range 1: caching new lease holder {NodeID:1 StoreID:1 ReplicaID:1}
I161103 20:02:06.711034 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:06.781550 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:07.030384 84 gossip/client.go:225  [n?] received [system-db liveness:1 first-range liveness:2 node:1 node:2 sentinel store:1 store:2 cluster-id] from node 1 (1 fresh)
I161103 20:02:07.775275 84 gossip/client.go:225  [n?] received [cluster-id liveness:2 node:2 store:1 system-db first-range liveness:1 node:1 sentinel store:2] from node 1 (1 fresh)
I161103 20:02:08.684018 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:09.711776 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:09.782188 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:12.030156 84 gossip/client.go:225  [n?] received [node:2 sentinel liveness:1 liveness:2 node:1 store:1 store:2 system-db cluster-id first-range] from node 1 (1 fresh)
I161103 20:02:12.712377 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:12.775136 84 gossip/client.go:225  [n?] received [store:2 system-db first-range liveness:1 node:1 node:2 cluster-id liveness:2 sentinel store:1] from node 1 (1 fresh)
I161103 20:02:12.783477 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:13.684038 11 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 20:02:13.687345 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:15.712984 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:15.784400 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:17.029969 84 gossip/client.go:225  [n?] received [node:2 sentinel store:2 system-db cluster-id first-range liveness:2 liveness:1 node:1 store:1] from node 1 (1 fresh)
I161103 20:02:17.775342 84 gossip/client.go:225  [n?] received [cluster-id first-range node:1 node:2 store:1 store:2 system-db liveness:1 liveness:2 sentinel] from node 1 (1 fresh)
I161103 20:02:18.687540 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:18.713522 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:18.784908 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:21.714217 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:21.785528 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:22.029864 84 gossip/client.go:225  [n?] received [first-range liveness:1 liveness:2 node:2 store:1 cluster-id node:1 sentinel store:2 system-db] from node 1 (1 fresh)
I161103 20:02:22.775900 84 gossip/client.go:225  [n?] received [cluster-id liveness:1 node:1 node:2 store:2 system-db first-range liveness:2 sentinel store:1] from node 1 (1 fresh)
I161103 20:02:23.683969 11 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 20:02:23.687819 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:24.715172 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:24.786360 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:27.030210 84 gossip/client.go:225  [n?] received [node:1 node:2 sentinel cluster-id first-range liveness:1 system-db liveness:2 store:1 store:2] from node 1 (1 fresh)
I161103 20:02:27.715906 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:27.775037 84 gossip/client.go:225  [n?] received [system-db cluster-id liveness:2 node:2 sentinel store:1 store:2 first-range liveness:1 node:1] from node 1 (1 fresh)
I161103 20:02:27.786932 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:28.688214 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:30.716742 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:30.787534 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:32.029854 84 gossip/client.go:225  [n?] received [sentinel store:1 store:2 system-db first-range liveness:1 liveness:2 node:1 cluster-id node:2] from node 1 (1 fresh)
I161103 20:02:32.775373 84 gossip/client.go:225  [n?] received [node:1 sentinel system-db liveness:2 first-range liveness:1 node:2 store:1 store:2 cluster-id] from node 1 (1 fresh)
I161103 20:02:33.683904 11 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 20:02:33.688433 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:33.717312 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:33.788047 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:36.718051 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:36.788711 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:37.029805 84 gossip/client.go:225  [n?] received [liveness:2 node:1 node:2 system-db cluster-id first-range liveness:1 sentinel store:1 store:2] from node 1 (1 fresh)
I161103 20:02:37.128178 76 gossip/gossip.go:1071  [n?] node has connected to cluster via gossip
I161103 20:02:37.128328 76 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage
I161103 20:02:37.775265 84 gossip/client.go:225  [n?] received [cluster-id first-range sentinel store:1 store:2 system-db liveness:1 liveness:2 node:1 node:2] from node 1 (1 fresh)
I161103 20:02:38.688735 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:39.718923 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:39.789283 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:42.031361 84 gossip/client.go:225  [n?] received [node:2 sentinel store:1 liveness:1 node:1 liveness:2 store:2 system-db cluster-id first-range] from node 1 (1 fresh)
I161103 20:02:42.719543 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:42.774822 84 gossip/client.go:225  [n?] received [liveness:2 cluster-id first-range node:2 sentinel store:1 store:2 system-db liveness:1 node:1] from node 1 (1 fresh)
I161103 20:02:42.789972 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:43.683981 11 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 20:02:43.688951 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:45.720229 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:45.790503 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:47.029832 84 gossip/client.go:225  [n?] received [cluster-id first-range node:2 store:1 store:2 liveness:1 liveness:2 node:1 sentinel system-db] from node 1 (1 fresh)
I161103 20:02:47.775289 84 gossip/client.go:225  [n?] received [node:1 store:1 first-range liveness:1 liveness:2 node:2 sentinel store:2 system-db cluster-id] from node 1 (1 fresh)
I161103 20:02:48.689304 10 kv/txn_coord_sender.go:258  [n?] txn coordinator: 0.00 txn/sec, 0.00/0.00/0.00/0.00 %cmmt/cmmt1pc/abrt/abnd, 0s/0s/0s avg/σ/max duration, 0.0/0.0/0 avg/σ/max restarts (0 samples over 10s)
I161103 20:02:48.720933 38 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:48.791061 103 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 20:02:48.976899 82 http2_client.go:1053  transport: http2Client.notifyError got notified that the client transport was broken EOF.
W161103 20:02:48.977269 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 13 desc = transport is closing
W161103 20:02:48.977447 76 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 20:02:48.979169 37 /go/src/google.golang.org/grpc/clientconn.go:667  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 172.18.0.2:26257: getsockopt: connection refused"; Reconnecting to {"roach-ab05ac12-0:26257" <nil>}
W161103 20:02:48.979206 110 gossip/client.go:120  [n?] node 0: failed to start gossip client: rpc error: code = 14 desc = grpc: the connection is unavailable
W161103 20:02:49.030757 1 kv/dist_sender.go:1136  [n?,range-lookup] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 20:02:49.120546 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
W161103 20:02:49.120713 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
W161103 20:02:49.330523 1 kv/dist_sender.go:1136  [n?,range-lookup] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
W161103 20:02:49.331428 1 kv/dist_sender.go:1136  [n?,range-lookup] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 20:02:49.536849 78 http2_client.go:1053  transport: http2Client.notifyError got notified that the client transport was broken EOF.
I161103 20:02:49.538100 102 /go/src/google.golang.org/grpc/clientconn.go:667  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 172.18.0.3:26257: getsockopt: connection refused"; Reconnecting to {"roach-ab05ac12-1:26257" <nil>}
I161103 20:02:49.720763 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
W161103 20:02:49.720860 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable