Node log from failing acceptance test (with --verbosity=3) never gets a node id assigned

gistfile1.txt

I161103 22:07:55.926466 1 cli/start.go:299  CockroachDB beta-20161103-52-gb34be88 (linux amd64, built 2016/11/03 20:08:41, go1.7.3)
I161103 22:07:56.032814 1 cli/backtrace.go:40  backtrace disabled: stat /opt/backtrace/bin/ptrace: no such file or directory
I161103 22:07:56.033018 1 cli/start.go:315  starting cockroach node
I161103 22:07:56.033086 1 cli/start.go:317  using local environment variables: COCKROACH_SCAN_MAX_IDLE_TIME, COCKROACH_CONSISTENCY_CHECK_PANIC_ON_FAILURE
I161103 22:07:56.051797 1 util/metric/registry.go:80  Added metric: gossip.connections.incoming (*metric.Gauge)
I161103 22:07:56.051905 1 util/metric/registry.go:80  Added metric: gossip.bytes.received (*metric.Counter)
I161103 22:07:56.051926 1 util/metric/registry.go:80  Added metric: gossip.bytes.sent (*metric.Counter)
I161103 22:07:56.051941 1 util/metric/registry.go:80  Added metric: gossip.infos.received (*metric.Counter)
I161103 22:07:56.051958 1 util/metric/registry.go:80  Added metric: gossip.infos.sent (*metric.Counter)
I161103 22:07:56.051985 1 util/metric/registry.go:80  Added metric: gossip.connections.outgoing (*metric.Gauge)
I161103 22:07:56.052043 1 gossip/gossip.go:237  [n?] initial resolvers: [roach-e9340988-0:26257]
W161103 22:07:56.052095 1 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 22:07:56.056565 1 util/metric/registry.go:80  Added metric: txn.aborts (*metric.CounterWithRates)
I161103 22:07:56.056604 1 util/metric/registry.go:80  Added metric: txn.commits (*metric.CounterWithRates)
I161103 22:07:56.056620 1 util/metric/registry.go:80  Added metric: txn.commits1PC (*metric.CounterWithRates)
I161103 22:07:56.056638 1 util/metric/registry.go:80  Added metric: txn.abandons (*metric.CounterWithRates)
I161103 22:07:56.056653 1 util/metric/registry.go:80  Added metric: txn.durations (*metric.Histogram)
I161103 22:07:56.056667 1 util/metric/registry.go:80  Added metric: txn.restarts (*metric.Histogram)
I161103 22:07:56.056702 1 util/metric/registry.go:80  Added metric: liveness.heartbeatsuccesses (*metric.Counter)
I161103 22:07:56.056733 1 util/metric/registry.go:80  Added metric: liveness.heartbeatfailures (*metric.Counter)
I161103 22:07:56.056747 1 util/metric/registry.go:80  Added metric: liveness.epochincrements (*metric.Counter)
I161103 22:07:56.057568 1 util/metric/registry.go:80  Added metric: sql.mon.internal.max (*metric.Histogram)
I161103 22:07:56.057606 1 util/metric/registry.go:80  Added metric: sql.mon.internal.cur (*metric.Counter)
I161103 22:07:56.057621 1 util/metric/registry.go:80  Added metric: sql.mon.internal.txn.max (*metric.Histogram)
I161103 22:07:56.057635 1 util/metric/registry.go:80  Added metric: sql.mon.internal.txn.cur (*metric.Counter)
I161103 22:07:56.057648 1 util/metric/registry.go:80  Added metric: sql.mon.internal.session.max (*metric.Histogram)
I161103 22:07:56.057666 1 util/metric/registry.go:80  Added metric: sql.mon.internal.session.cur (*metric.Counter)
I161103 22:07:56.058565 1 util/metric/registry.go:80  Added metric: sql.mon.admin.max (*metric.Histogram)
I161103 22:07:56.058599 1 util/metric/registry.go:80  Added metric: sql.mon.admin.cur (*metric.Counter)
I161103 22:07:56.058614 1 util/metric/registry.go:80  Added metric: sql.mon.admin.txn.max (*metric.Histogram)
I161103 22:07:56.058628 1 util/metric/registry.go:80  Added metric: sql.mon.admin.txn.cur (*metric.Counter)
I161103 22:07:56.058641 1 util/metric/registry.go:80  Added metric: sql.mon.admin.session.max (*metric.Histogram)
I161103 22:07:56.058660 1 util/metric/registry.go:80  Added metric: sql.mon.admin.session.cur (*metric.Counter)
I161103 22:07:56.067667 1 sql/table.go:446  [startup,n?] planner releasing leases
I161103 22:07:56.067750 1 sql/session.go:171  [startup,n?] , memory usage max 0 B
I161103 22:07:56.067784 1 sql/mon/mem_usage.go:571  [startup,n?] : releasing 0 bytes to the pool
I161103 22:07:56.067835 1 sql/session.go:172  [startup,n?] , memory usage max 0 B
I161103 22:07:56.067860 1 sql/mon/mem_usage.go:571  [startup,n?] : releasing 0 bytes to the pool
I161103 22:07:56.067901 1 util/metric/registry.go:97  Skipping unexported field cfg
I161103 22:07:56.067931 1 util/metric/registry.go:97  Skipping unexported field reCache
I161103 22:07:56.067957 1 util/metric/registry.go:97  Skipping unexported field virtualSchemas
I161103 22:07:56.067979 1 util/metric/registry.go:80  Added metric: sql.latency (*metric.Histogram)
I161103 22:07:56.068006 1 util/metric/registry.go:80  Added metric: sql.select.count (*metric.Counter)
I161103 22:07:56.068020 1 util/metric/registry.go:80  Added metric: sql.txn.begin.count (*metric.Counter)
I161103 22:07:56.068034 1 util/metric/registry.go:80  Added metric: sql.txn.commit.count (*metric.Counter)
I161103 22:07:56.068051 1 util/metric/registry.go:80  Added metric: sql.txn.abort.count (*metric.Counter)
I161103 22:07:56.068097 1 util/metric/registry.go:80  Added metric: sql.txn.rollback.count (*metric.Counter)
I161103 22:07:56.068157 1 util/metric/registry.go:80  Added metric: sql.update.count (*metric.Counter)
I161103 22:07:56.068176 1 util/metric/registry.go:80  Added metric: sql.insert.count (*metric.Counter)
I161103 22:07:56.068191 1 util/metric/registry.go:80  Added metric: sql.delete.count (*metric.Counter)
I161103 22:07:56.068204 1 util/metric/registry.go:80  Added metric: sql.ddl.count (*metric.Counter)
I161103 22:07:56.068218 1 util/metric/registry.go:80  Added metric: sql.misc.count (*metric.Counter)
I161103 22:07:56.068232 1 util/metric/registry.go:80  Added metric: sql.query.count (*metric.Counter)
I161103 22:07:56.068250 1 util/metric/registry.go:97  Skipping unexported field systemConfig
I161103 22:07:56.068263 1 util/metric/registry.go:97  Skipping unexported field databaseCache
I161103 22:07:56.068277 1 util/metric/registry.go:97  Skipping unexported field systemConfigMu
I161103 22:07:56.068290 1 util/metric/registry.go:97  Skipping unexported field systemConfigCond
I161103 22:07:56.069718 1 sql/pgwire/server.go:144  sql: starting monitor, reserved 500 MiB, pool (none)
I161103 22:07:56.069760 1 sql/pgwire/server.go:150  conn: starting monitor, reserved 0 B, pool sql
I161103 22:07:56.069778 1 util/metric/registry.go:80  Added metric: sql.bytesin (*metric.Counter)
I161103 22:07:56.069793 1 util/metric/registry.go:80  Added metric: sql.bytesout (*metric.Counter)
I161103 22:07:56.069806 1 util/metric/registry.go:80  Added metric: sql.conns (*metric.Counter)
I161103 22:07:56.069825 1 util/metric/registry.go:80  Added metric: sql.mon.conns.max (*metric.Histogram)
I161103 22:07:56.069849 1 util/metric/registry.go:80  Added metric: sql.mon.conns.cur (*metric.Counter)
I161103 22:07:56.069862 1 util/metric/registry.go:80  Added metric: sql.mon.conns.txn.max (*metric.Histogram)
I161103 22:07:56.069875 1 util/metric/registry.go:80  Added metric: sql.mon.conns.txn.cur (*metric.Counter)
I161103 22:07:56.069889 1 util/metric/registry.go:80  Added metric: sql.mon.conns.session.max (*metric.Histogram)
I161103 22:07:56.069902 1 util/metric/registry.go:80  Added metric: sql.mon.conns.session.cur (*metric.Counter)
I161103 22:07:56.069916 1 util/metric/registry.go:80  Added metric: sql.mon.client.max (*metric.Histogram)
I161103 22:07:56.069929 1 util/metric/registry.go:80  Added metric: sql.mon.client.cur (*metric.Counter)
I161103 22:07:56.069953 1 util/metric/registry.go:80  Added metric: sql.mon.client.txn.max (*metric.Histogram)
I161103 22:07:56.069967 1 util/metric/registry.go:80  Added metric: sql.mon.client.txn.cur (*metric.Counter)
I161103 22:07:56.069980 1 util/metric/registry.go:80  Added metric: sql.mon.client.session.max (*metric.Histogram)
I161103 22:07:56.069993 1 util/metric/registry.go:80  Added metric: sql.mon.client.session.cur (*metric.Counter)
I161103 22:07:56.070007 1 util/metric/registry.go:97  Skipping unexported field internalMemMetrics
I161103 22:07:56.070027 1 util/metric/registry.go:80  Added metric: clock-offset.meannanos (*metric.Gauge)
I161103 22:07:56.070051 1 util/metric/registry.go:80  Added metric: clock-offset.stddevnanos (*metric.Gauge)
I161103 22:07:56.070103 1 util/metric/registry.go:97  Skipping unexported field clock
I161103 22:07:56.070132 1 util/metric/registry.go:97  Skipping unexported field startTimeNanos
I161103 22:07:56.070148 1 util/metric/registry.go:97  Skipping unexported field lastNow
I161103 22:07:56.070161 1 util/metric/registry.go:97  Skipping unexported field lastUtime
I161103 22:07:56.070185 1 util/metric/registry.go:97  Skipping unexported field lastStime
I161103 22:07:56.070198 1 util/metric/registry.go:97  Skipping unexported field lastPauseTime
I161103 22:07:56.070211 1 util/metric/registry.go:97  Skipping unexported field lastCgoCall
I161103 22:07:56.070223 1 util/metric/registry.go:97  Skipping unexported field lastNumGC
I161103 22:07:56.070237 1 util/metric/registry.go:97  Skipping unexported field fdUsageNotImplemented
I161103 22:07:56.070251 1 util/metric/registry.go:80  Added metric: sys.cgocalls (*metric.Gauge)
I161103 22:07:56.070275 1 util/metric/registry.go:80  Added metric: sys.goroutines (*metric.Gauge)
I161103 22:07:56.070289 1 util/metric/registry.go:80  Added metric: sys.go.allocbytes (*metric.Gauge)
I161103 22:07:56.070302 1 util/metric/registry.go:80  Added metric: sys.go.totalbytes (*metric.Gauge)
I161103 22:07:56.070315 1 util/metric/registry.go:80  Added metric: sys.cgo.allocbytes (*metric.Gauge)
I161103 22:07:56.070328 1 util/metric/registry.go:80  Added metric: sys.cgo.totalbytes (*metric.Gauge)
I161103 22:07:56.070341 1 util/metric/registry.go:80  Added metric: sys.gc.count (*metric.Gauge)
I161103 22:07:56.070355 1 util/metric/registry.go:80  Added metric: sys.gc.pause.ns (*metric.Gauge)
I161103 22:07:56.070372 1 util/metric/registry.go:80  Added metric: sys.gc.pause.percent (*metric.GaugeFloat64)
I161103 22:07:56.070386 1 util/metric/registry.go:80  Added metric: sys.cpu.user.ns (*metric.Gauge)
I161103 22:07:56.070400 1 util/metric/registry.go:80  Added metric: sys.cpu.user.percent (*metric.GaugeFloat64)
I161103 22:07:56.070412 1 util/metric/registry.go:80  Added metric: sys.cpu.sys.ns (*metric.Gauge)
I161103 22:07:56.070426 1 util/metric/registry.go:80  Added metric: sys.cpu.sys.percent (*metric.GaugeFloat64)
I161103 22:07:56.070439 1 util/metric/registry.go:80  Added metric: sys.rss (*metric.Gauge)
I161103 22:07:56.070463 1 util/metric/registry.go:80  Added metric: sys.fd.open (*metric.Gauge)
I161103 22:07:56.070479 1 util/metric/registry.go:80  Added metric: sys.fd.softlimit (*metric.Gauge)
I161103 22:07:56.070501 1 util/metric/registry.go:80  Added metric: sys.uptime (*metric.Gauge)
I161103 22:07:56.070524 1 util/metric/registry.go:80  Added metric: build.timestamp (*metric.Gauge)
I161103 22:07:56.070561 1 util/metric/registry.go:80  Added metric: exec.latency (*metric.Histogram)
I161103 22:07:56.070589 1 util/metric/registry.go:80  Added metric: exec.success (*metric.Counter)
I161103 22:07:56.070606 1 util/metric/registry.go:80  Added metric: exec.error (*metric.Counter)
I161103 22:07:56.070644 1 server/admin.go:96  admin: starting unlimited monitor
I161103 22:07:56.071219 1 storage/engine/rocksdb.go:326  opening rocksdb instance at "/data3.0"
I161103 22:07:56.072225 1 storage/engine/rocksdb.go:77  RocksDB version: 4.8.0
I161103 22:07:56.072295 1 storage/engine/rocksdb.go:77  Git sha rocksdb_build_git_sha:9dd1f18d3ab20667957cf240724a5d12e660ad42
I161103 22:07:56.072332 1 storage/engine/rocksdb.go:77  Compile date Nov  3 2016
I161103 22:07:56.072360 1 storage/engine/rocksdb.go:77  DB SUMMARY
I161103 22:07:56.072428 1 storage/engine/rocksdb.go:77  SST files in /data3.0 dir, Total Num: 0, files: 
I161103 22:07:56.072468 1 storage/engine/rocksdb.go:77  Write Ahead Log file in /data3.0: 
I161103 22:07:56.072490 1 storage/engine/rocksdb.go:77           Options.error_if_exists: 0
I161103 22:07:56.072512 1 storage/engine/rocksdb.go:77         Options.create_if_missing: 1
I161103 22:07:56.072535 1 storage/engine/rocksdb.go:77           Options.paranoid_checks: 1
I161103 22:07:56.072550 1 storage/engine/rocksdb.go:77                       Options.env: 0x2608380
I161103 22:07:56.072576 1 storage/engine/rocksdb.go:77                  Options.info_log: 0x7f9ddd41f0c0
I161103 22:07:56.072591 1 storage/engine/rocksdb.go:77            Options.max_open_files: -1
I161103 22:07:56.072608 1 storage/engine/rocksdb.go:77  Options.max_file_opening_threads: 16
I161103 22:07:56.072624 1 storage/engine/rocksdb.go:77        Options.max_total_wal_size: 0
I161103 22:07:56.072646 1 storage/engine/rocksdb.go:77         Options.disableDataSync: 0
I161103 22:07:56.072668 1 storage/engine/rocksdb.go:77               Options.use_fsync: 0
I161103 22:07:56.072694 1 storage/engine/rocksdb.go:77       Options.max_log_file_size: 0
I161103 22:07:56.072709 1 storage/engine/rocksdb.go:77  Options.max_manifest_file_size: 18446744073709551615
I161103 22:07:56.072724 1 storage/engine/rocksdb.go:77       Options.log_file_time_to_roll: 0
I161103 22:07:56.072739 1 storage/engine/rocksdb.go:77       Options.keep_log_file_num: 1000
I161103 22:07:56.072764 1 storage/engine/rocksdb.go:77    Options.recycle_log_file_num: 0
I161103 22:07:56.072778 1 storage/engine/rocksdb.go:77         Options.allow_os_buffer: 1
I161103 22:07:56.072792 1 storage/engine/rocksdb.go:77        Options.allow_mmap_reads: 0
I161103 22:07:56.072825 1 storage/engine/rocksdb.go:77        Options.allow_fallocate: 1
I161103 22:07:56.072849 1 storage/engine/rocksdb.go:77       Options.allow_mmap_writes: 0
I161103 22:07:56.072889 1 storage/engine/rocksdb.go:77           Options.create_missing_column_families: 0
I161103 22:07:56.072912 1 storage/engine/rocksdb.go:77                               Options.db_log_dir: 
I161103 22:07:56.072931 1 storage/engine/rocksdb.go:77                                  Options.wal_dir: /data3.0
I161103 22:07:56.072947 1 storage/engine/rocksdb.go:77                 Options.table_cache_numshardbits: 6
I161103 22:07:56.072961 1 storage/engine/rocksdb.go:77      Options.delete_obsolete_files_period_micros: 21600000000
I161103 22:07:56.072986 1 storage/engine/rocksdb.go:77               Options.base_background_compactions: 1
I161103 22:07:56.073002 1 storage/engine/rocksdb.go:77               Options.max_background_compactions: 3
I161103 22:07:56.073020 1 storage/engine/rocksdb.go:77                       Options.max_subcompactions: 2
I161103 22:07:56.073045 1 storage/engine/rocksdb.go:77                   Options.max_background_flushes: 1
I161103 22:07:56.073059 1 storage/engine/rocksdb.go:77                          Options.WAL_ttl_seconds: 0
I161103 22:07:56.073074 1 storage/engine/rocksdb.go:77                        Options.WAL_size_limit_MB: 0
I161103 22:07:56.073099 1 storage/engine/rocksdb.go:77              Options.manifest_preallocation_size: 4194304
I161103 22:07:56.073114 1 storage/engine/rocksdb.go:77                           Options.allow_os_buffer: 1
I161103 22:07:56.073131 1 storage/engine/rocksdb.go:77                          Options.allow_mmap_reads: 0
I161103 22:07:56.073157 1 storage/engine/rocksdb.go:77                         Options.allow_mmap_writes: 0
I161103 22:07:56.073187 1 storage/engine/rocksdb.go:77                       Options.is_fd_close_on_exec: 1
I161103 22:07:56.073202 1 storage/engine/rocksdb.go:77                     Options.stats_dump_period_sec: 600
I161103 22:07:56.073218 1 storage/engine/rocksdb.go:77                     Options.advise_random_on_open: 1
I161103 22:07:56.073233 1 storage/engine/rocksdb.go:77                      Options.db_write_buffer_size: 0d
I161103 22:07:56.073251 1 storage/engine/rocksdb.go:77           Options.access_hint_on_compaction_start: NORMAL
I161103 22:07:56.073282 1 storage/engine/rocksdb.go:77    Options.new_table_reader_for_compaction_inputs: 0
I161103 22:07:56.073298 1 storage/engine/rocksdb.go:77                 Options.compaction_readahead_size: 0d
I161103 22:07:56.073373 1 storage/engine/rocksdb.go:77                 Options.random_access_max_buffer_size: 1048576d
I161103 22:07:56.073404 1 storage/engine/rocksdb.go:77                Options.writable_file_max_buffer_size: 1048576d
I161103 22:07:56.073428 1 storage/engine/rocksdb.go:77                        Options.use_adaptive_mutex: 0
I161103 22:07:56.073452 1 storage/engine/rocksdb.go:77                              Options.rate_limiter: (nil)
I161103 22:07:56.073471 1 storage/engine/rocksdb.go:77       Options.sst_file_manager.rate_bytes_per_sec: 0
I161103 22:07:56.073491 1 storage/engine/rocksdb.go:77                            Options.bytes_per_sync: 0
I161103 22:07:56.073508 1 storage/engine/rocksdb.go:77                        Options.wal_bytes_per_sync: 0
I161103 22:07:56.073532 1 storage/engine/rocksdb.go:77                         Options.wal_recovery_mode: 2
I161103 22:07:56.073554 1 storage/engine/rocksdb.go:77                    Options.enable_thread_tracking: 0
I161103 22:07:56.073578 1 storage/engine/rocksdb.go:77           Options.allow_concurrent_memtable_write: 0
I161103 22:07:56.073612 1 storage/engine/rocksdb.go:77        Options.enable_write_thread_adaptive_yield: 0
I161103 22:07:56.073630 1 storage/engine/rocksdb.go:77               Options.write_thread_max_yield_usec: 100
I161103 22:07:56.073668 1 storage/engine/rocksdb.go:77              Options.write_thread_slow_yield_usec: 3
I161103 22:07:56.073697 1 storage/engine/rocksdb.go:77                                 Options.row_cache: None
I161103 22:07:56.073717 1 storage/engine/rocksdb.go:77         Options.wal_filter: None
I161103 22:07:56.073732 1 storage/engine/rocksdb.go:77  Compression algorithms supported:
I161103 22:07:56.073750 1 storage/engine/rocksdb.go:77  	Snappy supported: 1
I161103 22:07:56.073765 1 storage/engine/rocksdb.go:77  	Zlib supported: 0
I161103 22:07:56.073792 1 storage/engine/rocksdb.go:77  	Bzip supported: 0
I161103 22:07:56.073810 1 storage/engine/rocksdb.go:77  	LZ4 supported: 0
I161103 22:07:56.073825 1 storage/engine/rocksdb.go:77  Fast CRC32 supported: 0
I161103 22:07:56.073906 1 storage/engine/rocksdb.go:77  Creating manifest 1 
I161103 22:07:56.074117 8 rpc/context.go:220  [n?] dialing roach-e9340988-0:26257
I161103 22:07:56.101266 8 gossip/client.go:126  [n?] node 0: started gossip client to roach-e9340988-0:26257
I161103 22:07:56.102247 39 gossip/client.go:225  [n?] received [cluster-id liveness:1 node:1 store:1 system-db first-range liveness:2 node:2 sentinel store:2] from node 1 (10 fresh)
I161103 22:07:56.102312 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:07:56.102474 88 kv/dist_sender.go:206  [n?] gossiped first range descriptor: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I161103 22:07:56.102551 88 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Min desc=<nil>
I161103 22:07:56.103314 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=12.876208ms, err=14.470202ms, at=2016-11-03 22:07:56.103277728 +0000 UTC
I161103 22:07:56.103350 11 rpc/clock_offset.go:168  [n?] 1 of 1 nodes are within the maximum offset of 250ms
I161103 22:07:56.103606 31 sql/lease.go:1168  received a new config; will refresh leases
I161103 22:07:56.103705 31 sql/lease.go:1192  /Table/3/1/2/2/1: refreshing lease table: 2 (namespace), version: 1, deleted: false
I161103 22:07:56.103755 31 sql/lease.go:1192  /Table/3/1/3/2/1: refreshing lease table: 3 (descriptor), version: 1, deleted: false
I161103 22:07:56.103815 31 sql/lease.go:1192  /Table/3/1/4/2/1: refreshing lease table: 4 (users), version: 1, deleted: false
I161103 22:07:56.103891 31 sql/lease.go:1192  /Table/3/1/5/2/1: refreshing lease table: 5 (zones), version: 1, deleted: false
I161103 22:07:56.103957 31 sql/lease.go:1192  /Table/3/1/11/2/1: refreshing lease table: 11 (lease), version: 1, deleted: false
I161103 22:07:56.104032 31 sql/lease.go:1192  /Table/3/1/12/2/1: refreshing lease table: 12 (eventlog), version: 1, deleted: false
I161103 22:07:56.104119 31 sql/lease.go:1192  /Table/3/1/13/2/1: refreshing lease table: 13 (rangelog), version: 1, deleted: false
I161103 22:07:56.104188 31 sql/lease.go:1192  /Table/3/1/14/2/1: refreshing lease table: 14 (ui), version: 1, deleted: false
I161103 22:07:56.164100 1 storage/engine/rocksdb.go:77  Recovering from manifest file: MANIFEST-000001
I161103 22:07:56.164443 1 storage/engine/rocksdb.go:77  --------------- Options for column family [default]:
I161103 22:07:56.164484 1 storage/engine/rocksdb.go:77                Options.comparator: rocksdb.InternalKeyComparator:cockroach_comparator
I161103 22:07:56.164636 1 storage/engine/rocksdb.go:77            Options.merge_operator: cockroach_merge_operator
I161103 22:07:56.164674 1 storage/engine/rocksdb.go:77         Options.compaction_filter: None
I161103 22:07:56.165059 1 storage/engine/rocksdb.go:77         Options.compaction_filter_factory: None
I161103 22:07:56.165244 1 storage/engine/rocksdb.go:77          Options.memtable_factory: SkipListFactory
I161103 22:07:56.165406 1 storage/engine/rocksdb.go:77             Options.table_factory: BlockBasedTable
I161103 22:07:56.165574 1 storage/engine/rocksdb.go:77             table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7f9ddd43b018)
  cache_index_and_filter_blocks: 0
  pin_l0_filter_and_index_blocks_in_cache: 0
  index_type: 0
  hash_index_allow_collision: 1
  checksum: 1
  no_block_cache: 0
  block_cache: 0x7f9ddd40d010
  block_cache_size: 524073984
  block_cache_compressed: (nil)
  block_size: 32768
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  filter_policy: rocksdb.BuiltinBloomFilter
  whole_key_filtering: 0
  skip_table_builder_flush: 0
  format_version: 2
I161103 22:07:56.165616 1 storage/engine/rocksdb.go:77         Options.write_buffer_size: 8388608
I161103 22:07:56.165729 1 storage/engine/rocksdb.go:77   Options.max_write_buffer_number: 16
I161103 22:07:56.165844 1 storage/engine/rocksdb.go:77           Options.compression: Snappy
I161103 22:07:56.165876 1 storage/engine/rocksdb.go:77        Options.prefix_extractor: cockroach_prefix_extractor
I161103 22:07:56.165905 1 storage/engine/rocksdb.go:77              Options.num_levels: 7
I161103 22:07:56.166025 1 storage/engine/rocksdb.go:77         Options.min_write_buffer_number_to_merge: 1
I161103 22:07:56.166069 1 storage/engine/rocksdb.go:77      Options.max_write_buffer_number_to_maintain: 0
I161103 22:07:56.166230 1 storage/engine/rocksdb.go:77             Options.compression_opts.window_bits: -14
I161103 22:07:56.166346 1 storage/engine/rocksdb.go:77                   Options.compression_opts.level: -1
I161103 22:07:56.166388 1 storage/engine/rocksdb.go:77                Options.compression_opts.strategy: 0
I161103 22:07:56.166598 1 storage/engine/rocksdb.go:77          Options.compression_opts.max_dict_bytes: 0
I161103 22:07:56.166737 1 storage/engine/rocksdb.go:77       Options.level0_file_num_compaction_trigger: 1
I161103 22:07:56.166875 1 storage/engine/rocksdb.go:77           Options.level0_slowdown_writes_trigger: 16
I161103 22:07:56.166905 1 storage/engine/rocksdb.go:77               Options.level0_stop_writes_trigger: 17
I161103 22:07:56.166934 1 storage/engine/rocksdb.go:77                    Options.target_file_size_base: 4194304
I161103 22:07:56.167089 1 storage/engine/rocksdb.go:77              Options.target_file_size_multiplier: 2
I161103 22:07:56.167217 1 storage/engine/rocksdb.go:77                 Options.max_bytes_for_level_base: 16777216
I161103 22:07:56.167320 1 storage/engine/rocksdb.go:77  Options.level_compaction_dynamic_level_bytes: 1
I161103 22:07:56.167379 1 storage/engine/rocksdb.go:77           Options.max_bytes_for_level_multiplier: 10
I161103 22:07:56.167461 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[0]: 1
I161103 22:07:56.167495 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[1]: 1
I161103 22:07:56.167517 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[2]: 1
I161103 22:07:56.167610 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[3]: 1
I161103 22:07:56.167632 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[4]: 1
I161103 22:07:56.167653 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[5]: 1
I161103 22:07:56.167736 1 storage/engine/rocksdb.go:77  Options.max_bytes_for_level_multiplier_addtl[6]: 1
I161103 22:07:56.167761 1 storage/engine/rocksdb.go:77        Options.max_sequential_skip_in_iterations: 8
I161103 22:07:56.167782 1 storage/engine/rocksdb.go:77               Options.expanded_compaction_factor: 25
I161103 22:07:56.167861 1 storage/engine/rocksdb.go:77                 Options.source_compaction_factor: 1
I161103 22:07:56.167900 1 storage/engine/rocksdb.go:77           Options.max_grandparent_overlap_factor: 10
I161103 22:07:56.167922 1 storage/engine/rocksdb.go:77                         Options.arena_block_size: 1048576
I161103 22:07:56.167943 1 storage/engine/rocksdb.go:77    Options.soft_pending_compaction_bytes_limit: 68719476736
I161103 22:07:56.168033 1 storage/engine/rocksdb.go:77    Options.hard_pending_compaction_bytes_limit: 274877906944
I161103 22:07:56.168055 1 storage/engine/rocksdb.go:77        Options.rate_limit_delay_max_milliseconds: 1000
I161103 22:07:56.168077 1 storage/engine/rocksdb.go:77                 Options.disable_auto_compactions: 0
I161103 22:07:56.168289 1 storage/engine/rocksdb.go:77                            Options.filter_deletes: 0
I161103 22:07:56.168334 1 storage/engine/rocksdb.go:77            Options.verify_checksums_in_compaction: 1
I161103 22:07:56.168356 1 storage/engine/rocksdb.go:77                          Options.compaction_style: 0
I161103 22:07:56.168432 1 storage/engine/rocksdb.go:77                            Options.compaction_pri: 0
I161103 22:07:56.168469 1 storage/engine/rocksdb.go:77   Options.compaction_options_universal.size_ratio: 1
I161103 22:07:56.168491 1 storage/engine/rocksdb.go:77  Options.compaction_options_universal.min_merge_width: 2
I161103 22:07:56.168512 1 storage/engine/rocksdb.go:77  Options.compaction_options_universal.max_merge_width: 4294967295
I161103 22:07:56.168602 1 storage/engine/rocksdb.go:77  Options.compaction_options_universal.max_size_amplification_percent: 200
I161103 22:07:56.168636 1 storage/engine/rocksdb.go:77  Options.compaction_options_universal.compression_size_percent: -1
I161103 22:07:56.168833 1 storage/engine/rocksdb.go:77  Options.compaction_options_fifo.max_table_files_size: 1073741824
I161103 22:07:56.168951 1 storage/engine/rocksdb.go:77                    Options.table_properties_collectors: TimeBoundTblPropCollectorFactory; 
I161103 22:07:56.168991 1 storage/engine/rocksdb.go:77                    Options.inplace_update_support: 0
I161103 22:07:56.169115 1 storage/engine/rocksdb.go:77                  Options.inplace_update_num_locks: 10000
I161103 22:07:56.169157 1 storage/engine/rocksdb.go:77                Options.min_partial_merge_operands: 2
I161103 22:07:56.169468 1 storage/engine/rocksdb.go:77                Options.memtable_prefix_bloom_bits: 0
I161103 22:07:56.169503 1 storage/engine/rocksdb.go:77              Options.memtable_prefix_bloom_probes: 6
I161103 22:07:56.169526 1 storage/engine/rocksdb.go:77    Options.memtable_prefix_bloom_huge_page_tlb_size: 0
I161103 22:07:56.169611 1 storage/engine/rocksdb.go:77                            Options.bloom_locality: 0
I161103 22:07:56.169640 1 storage/engine/rocksdb.go:77                     Options.max_successive_merges: 0
I161103 22:07:56.169662 1 storage/engine/rocksdb.go:77                 Options.optimize_filters_for_hits: 1
I161103 22:07:56.169753 1 storage/engine/rocksdb.go:77                 Options.paranoid_file_checks: 0
I161103 22:07:56.169775 1 storage/engine/rocksdb.go:77                 Options.report_bg_io_stats: 0
I161103 22:07:56.172347 1 storage/engine/rocksdb.go:77  Recovered from manifest file:/data3.0/MANIFEST-000001 succeeded,manifest_file_number is 1, next_file_number is 3, last_sequence is 0, log_number is 0,prev_log_number is 0,max_column_family is 0
I161103 22:07:56.172453 1 storage/engine/rocksdb.go:77  Column family [default] (ID 0), log number is 0
I161103 22:07:56.223864 1 storage/engine/rocksdb.go:77  DB pointer 0x7f9ddd45b000
I161103 22:07:56.225193 1 server/config.go:443  1 storage engine initialized
I161103 22:07:56.225700 1 util/metric/registry.go:97  Skipping unexported field registry
I161103 22:07:56.225809 1 util/metric/registry.go:80  Added metric: replicas (*metric.Counter)
I161103 22:07:56.225843 1 util/metric/registry.go:80  Added metric: replicas.reserved (*metric.Counter)
I161103 22:07:56.225930 1 util/metric/registry.go:80  Added metric: replicas.leaders (*metric.Gauge)
I161103 22:07:56.225964 1 util/metric/registry.go:80  Added metric: replicas.leaders_not_leaseholders (*metric.Gauge)
I161103 22:07:56.226048 1 util/metric/registry.go:80  Added metric: replicas.leaseholders (*metric.Gauge)
I161103 22:07:56.226081 1 util/metric/registry.go:80  Added metric: replicas.quiescent (*metric.Gauge)
I161103 22:07:56.226172 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.maxsize (*metric.Gauge)
I161103 22:07:56.226206 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.maxwritecount (*metric.Gauge)
I161103 22:07:56.226299 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.maxreadcount (*metric.Gauge)
I161103 22:07:56.226404 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.maxtreesize (*metric.Gauge)
I161103 22:07:56.226436 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.maxoverlaps (*metric.Gauge)
I161103 22:07:56.226456 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.combinedqueuesize (*metric.Gauge)
I161103 22:07:56.226582 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.combinedwritecount (*metric.Gauge)
I161103 22:07:56.226615 1 util/metric/registry.go:80  Added metric: replicas.commandqueue.combinedreadcount (*metric.Gauge)
I161103 22:07:56.226708 1 util/metric/registry.go:80  Added metric: ranges.available (*metric.Gauge)
I161103 22:07:56.226742 1 util/metric/registry.go:80  Added metric: ranges.allocator.noop (*metric.Gauge)
I161103 22:07:56.226824 1 util/metric/registry.go:80  Added metric: ranges.allocator.remove (*metric.Gauge)
I161103 22:07:56.226857 1 util/metric/registry.go:80  Added metric: ranges.allocator.add (*metric.Gauge)
I161103 22:07:56.226874 1 util/metric/registry.go:80  Added metric: ranges.allocator.removedead (*metric.Gauge)
I161103 22:07:56.226975 1 util/metric/registry.go:80  Added metric: leases.success (*metric.Counter)
I161103 22:07:56.227069 1 util/metric/registry.go:80  Added metric: leases.error (*metric.Counter)
I161103 22:07:56.227108 1 util/metric/registry.go:80  Added metric: livebytes (*metric.Gauge)
I161103 22:07:56.227220 1 util/metric/registry.go:80  Added metric: keybytes (*metric.Gauge)
I161103 22:07:56.227323 1 util/metric/registry.go:80  Added metric: valbytes (*metric.Gauge)
I161103 22:07:56.227356 1 util/metric/registry.go:80  Added metric: intentbytes (*metric.Gauge)
I161103 22:07:56.227443 1 util/metric/registry.go:80  Added metric: livecount (*metric.Gauge)
I161103 22:07:56.227476 1 util/metric/registry.go:80  Added metric: keycount (*metric.Gauge)
I161103 22:07:56.227495 1 util/metric/registry.go:80  Added metric: valcount (*metric.Gauge)
I161103 22:07:56.227602 1 util/metric/registry.go:80  Added metric: intentcount (*metric.Gauge)
I161103 22:07:56.227620 1 util/metric/registry.go:80  Added metric: intentage (*metric.Gauge)
I161103 22:07:56.227724 1 util/metric/registry.go:80  Added metric: gcbytesage (*metric.Gauge)
I161103 22:07:56.227742 1 util/metric/registry.go:80  Added metric: lastupdatenanos (*metric.Gauge)
I161103 22:07:56.227832 1 util/metric/registry.go:80  Added metric: capacity (*metric.Gauge)
I161103 22:07:56.227864 1 util/metric/registry.go:80  Added metric: capacity.available (*metric.Gauge)
I161103 22:07:56.227880 1 util/metric/registry.go:80  Added metric: capacity.reserved (*metric.Counter)
I161103 22:07:56.227963 1 util/metric/registry.go:80  Added metric: sysbytes (*metric.Gauge)
I161103 22:07:56.227979 1 util/metric/registry.go:80  Added metric: syscount (*metric.Gauge)
I161103 22:07:56.227995 1 util/metric/registry.go:80  Added metric: rocksdb.block.cache.hits (*metric.Gauge)
I161103 22:07:56.228072 1 util/metric/registry.go:80  Added metric: rocksdb.block.cache.misses (*metric.Gauge)
I161103 22:07:56.228101 1 util/metric/registry.go:80  Added metric: rocksdb.block.cache.usage (*metric.Gauge)
I161103 22:07:56.228117 1 util/metric/registry.go:80  Added metric: rocksdb.block.cache.pinned-usage (*metric.Gauge)
I161103 22:07:56.228201 1 util/metric/registry.go:80  Added metric: rocksdb.bloom.filter.prefix.checked (*metric.Gauge)
I161103 22:07:56.228231 1 util/metric/registry.go:80  Added metric: rocksdb.bloom.filter.prefix.useful (*metric.Gauge)
I161103 22:07:56.228247 1 util/metric/registry.go:80  Added metric: rocksdb.memtable.hits (*metric.Gauge)
I161103 22:07:56.228324 1 util/metric/registry.go:80  Added metric: rocksdb.memtable.misses (*metric.Gauge)
I161103 22:07:56.228352 1 util/metric/registry.go:80  Added metric: rocksdb.memtable.total-size (*metric.Gauge)
I161103 22:07:56.228368 1 util/metric/registry.go:80  Added metric: rocksdb.flushes (*metric.Gauge)
I161103 22:07:56.228383 1 util/metric/registry.go:80  Added metric: rocksdb.compactions (*metric.Gauge)
I161103 22:07:56.228462 1 util/metric/registry.go:80  Added metric: rocksdb.table-readers-mem-estimate (*metric.Gauge)
I161103 22:07:56.228492 1 util/metric/registry.go:80  Added metric: rocksdb.read-amplification (*metric.Gauge)
I161103 22:07:56.228508 1 util/metric/registry.go:80  Added metric: rocksdb.num-sstables (*metric.Gauge)
I161103 22:07:56.228524 1 util/metric/registry.go:80  Added metric: range.splits (*metric.Counter)
I161103 22:07:56.228612 1 util/metric/registry.go:80  Added metric: range.adds (*metric.Counter)
I161103 22:07:56.228628 1 util/metric/registry.go:80  Added metric: range.removes (*metric.Counter)
I161103 22:07:56.228716 1 util/metric/registry.go:80  Added metric: range.snapshots.generated (*metric.Counter)
I161103 22:07:56.228746 1 util/metric/registry.go:80  Added metric: range.snapshots.normal-applied (*metric.Counter)
I161103 22:07:56.228763 1 util/metric/registry.go:80  Added metric: range.snapshots.preemptive-applied (*metric.Counter)
I161103 22:07:56.228881 1 util/metric/registry.go:80  Added metric: raft.ticks (*metric.Counter)
I161103 22:07:56.228985 1 util/metric/registry.go:80  Added metric: raft.process.workingnanos (*metric.Counter)
I161103 22:07:56.229017 1 util/metric/registry.go:80  Added metric: raft.process.tickingnanos (*metric.Counter)
I161103 22:07:56.229035 1 util/metric/registry.go:80  Added metric: raft.rcvd.prop (*metric.Counter)
I161103 22:07:56.229055 1 util/metric/registry.go:80  Added metric: raft.rcvd.app (*metric.Counter)
I161103 22:07:56.229142 1 util/metric/registry.go:80  Added metric: raft.rcvd.appresp (*metric.Counter)
I161103 22:07:56.229159 1 util/metric/registry.go:80  Added metric: raft.rcvd.vote (*metric.Counter)
I161103 22:07:56.229177 1 util/metric/registry.go:80  Added metric: raft.rcvd.voteresp (*metric.Counter)
I161103 22:07:56.229265 1 util/metric/registry.go:80  Added metric: raft.rcvd.prevote (*metric.Counter)
I161103 22:07:56.229281 1 util/metric/registry.go:80  Added metric: raft.rcvd.prevoteresp (*metric.Counter)
I161103 22:07:56.229298 1 util/metric/registry.go:80  Added metric: raft.rcvd.snap (*metric.Counter)
I161103 22:07:56.229403 1 util/metric/registry.go:80  Added metric: raft.rcvd.heartbeat (*metric.Counter)
I161103 22:07:56.229422 1 util/metric/registry.go:80  Added metric: raft.rcvd.heartbeatresp (*metric.Counter)
I161103 22:07:56.229438 1 util/metric/registry.go:80  Added metric: raft.rcvd.transferleader (*metric.Counter)
I161103 22:07:56.229519 1 util/metric/registry.go:80  Added metric: raft.rcvd.timeoutnow (*metric.Counter)
I161103 22:07:56.229549 1 util/metric/registry.go:80  Added metric: raft.rcvd.dropped (*metric.Counter)
I161103 22:07:56.229565 1 util/metric/registry.go:97  Skipping unexported field raftRcvdMessages
I161103 22:07:56.229660 1 util/metric/registry.go:80  Added metric: raft.enqueued.pending (*metric.Gauge)
I161103 22:07:56.229718 1 util/metric/registry.go:80  Added metric: raft.heartbeats.pending (*metric.Gauge)
I161103 22:07:56.229972 1 util/metric/registry.go:80  Added metric: queue.gc.process.success (*metric.Counter)
I161103 22:07:56.230019 1 util/metric/registry.go:80  Added metric: queue.gc.process.failure (*metric.Counter)
I161103 22:07:56.230160 1 util/metric/registry.go:80  Added metric: queue.gc.pending (*metric.Gauge)
I161103 22:07:56.230264 1 util/metric/registry.go:80  Added metric: queue.gc.processingnanos (*metric.Counter)
I161103 22:07:56.230299 1 util/metric/registry.go:80  Added metric: queue.raftlog.process.success (*metric.Counter)
I161103 22:07:56.230378 1 util/metric/registry.go:80  Added metric: queue.raftlog.process.failure (*metric.Counter)
I161103 22:07:56.230406 1 util/metric/registry.go:80  Added metric: queue.raftlog.pending (*metric.Gauge)
I161103 22:07:56.230484 1 util/metric/registry.go:80  Added metric: queue.raftlog.processingnanos (*metric.Counter)
I161103 22:07:56.230513 1 util/metric/registry.go:80  Added metric: queue.consistency.process.success (*metric.Counter)
I161103 22:07:56.230528 1 util/metric/registry.go:80  Added metric: queue.consistency.process.failure (*metric.Counter)
I161103 22:07:56.230552 1 util/metric/registry.go:80  Added metric: queue.consistency.pending (*metric.Gauge)
I161103 22:07:56.230639 1 util/metric/registry.go:80  Added metric: queue.consistency.processingnanos (*metric.Counter)
I161103 22:07:56.230654 1 util/metric/registry.go:80  Added metric: queue.replicagc.process.success (*metric.Counter)
I161103 22:07:56.230668 1 util/metric/registry.go:80  Added metric: queue.replicagc.process.failure (*metric.Counter)
I161103 22:07:56.230741 1 util/metric/registry.go:80  Added metric: queue.replicagc.pending (*metric.Gauge)
I161103 22:07:56.230767 1 util/metric/registry.go:80  Added metric: queue.replicagc.processingnanos (*metric.Counter)
I161103 22:07:56.230782 1 util/metric/registry.go:80  Added metric: queue.replicate.process.success (*metric.Counter)
I161103 22:07:56.230795 1 util/metric/registry.go:80  Added metric: queue.replicate.process.failure (*metric.Counter)
I161103 22:07:56.230867 1 util/metric/registry.go:80  Added metric: queue.replicate.pending (*metric.Gauge)
I161103 22:07:56.230881 1 util/metric/registry.go:80  Added metric: queue.replicate.processingnanos (*metric.Counter)
I161103 22:07:56.230895 1 util/metric/registry.go:80  Added metric: queue.replicate.purgatory (*metric.Gauge)
I161103 22:07:56.230919 1 util/metric/registry.go:80  Added metric: queue.split.process.success (*metric.Counter)
I161103 22:07:56.231001 1 util/metric/registry.go:80  Added metric: queue.split.process.failure (*metric.Counter)
I161103 22:07:56.231016 1 util/metric/registry.go:80  Added metric: queue.split.pending (*metric.Gauge)
I161103 22:07:56.231030 1 util/metric/registry.go:80  Added metric: queue.split.processingnanos (*metric.Counter)
I161103 22:07:56.231099 1 util/metric/registry.go:80  Added metric: queue.tsmaintenance.process.failure (*metric.Counter)
I161103 22:07:56.231125 1 util/metric/registry.go:80  Added metric: queue.tsmaintenance.process.success (*metric.Counter)
I161103 22:07:56.231139 1 util/metric/registry.go:80  Added metric: queue.tsmaintenance.pending (*metric.Gauge)
I161103 22:07:56.231153 1 util/metric/registry.go:80  Added metric: queue.tsmaintenance.processingnanos (*metric.Counter)
I161103 22:07:56.231178 1 util/metric/registry.go:80  Added metric: queue.gc.info.numkeysaffected (*metric.Counter)
I161103 22:07:56.231241 1 util/metric/registry.go:80  Added metric: queue.gc.info.intentsconsidered (*metric.Counter)
I161103 22:07:56.231256 1 util/metric/registry.go:80  Added metric: queue.gc.info.intenttxns (*metric.Counter)
I161103 22:07:56.231271 1 util/metric/registry.go:80  Added metric: queue.gc.info.transactionspanscanned (*metric.Counter)
I161103 22:07:56.231286 1 util/metric/registry.go:80  Added metric: queue.gc.info.transactionspangcaborted (*metric.Counter)
I161103 22:07:56.231318 1 util/metric/registry.go:80  Added metric: queue.gc.info.transactionspangccommitted (*metric.Counter)
I161103 22:07:56.231334 1 util/metric/registry.go:80  Added metric: queue.gc.info.transactionspangcpending (*metric.Counter)
I161103 22:07:56.231412 1 util/metric/registry.go:80  Added metric: queue.gc.info.abortspanscanned (*metric.Counter)
I161103 22:07:56.231439 1 util/metric/registry.go:80  Added metric: queue.gc.info.abortspanconsidered (*metric.Counter)
I161103 22:07:56.231457 1 util/metric/registry.go:80  Added metric: queue.gc.info.abortspangcnum (*metric.Counter)
I161103 22:07:56.231472 1 util/metric/registry.go:80  Added metric: queue.gc.info.pushtxn (*metric.Counter)
I161103 22:07:56.231486 1 util/metric/registry.go:80  Added metric: queue.gc.info.resolvetotal (*metric.Counter)
I161103 22:07:56.231500 1 util/metric/registry.go:80  Added metric: queue.gc.info.resolvesuccess (*metric.Counter)
I161103 22:07:56.231515 1 util/metric/registry.go:80  Added metric: mutex.storenanos (*metric.Histogram)
I161103 22:07:56.231529 1 util/metric/registry.go:80  Added metric: mutex.schedulernanos (*metric.Histogram)
I161103 22:07:56.231542 1 util/metric/registry.go:80  Added metric: mutex.raftnanos (*metric.Histogram)
I161103 22:07:56.231561 1 util/metric/registry.go:80  Added metric: mutex.replicananos (*metric.Histogram)
I161103 22:07:56.231585 1 util/metric/registry.go:80  Added metric: mutex.commandqueuenanos (*metric.Histogram)
I161103 22:07:56.231600 1 util/metric/registry.go:97  Skipping unexported field mu
I161103 22:07:56.231970 1 server/node.go:421  [n?] store [n0,s0] not bootstrapped
I161103 22:07:56.232062 1 storage/stores.go:296  [n?] read 0 node addresses from persistent storage
I161103 22:07:56.232181 1 server/node.go:564  [n?] connecting to gossip network to verify cluster ID...
I161103 22:07:56.232278 1 server/node.go:585  [n?] node connected via gossip and verified as part of cluster {"8d726864-1c2f-4cdf-9364-c4a995679a2e"}
I161103 22:07:56.232422 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/System/"node-idgen"
I161103 22:07:56.232462 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/Meta2/System/"node-idgen"
I161103 22:07:56.232510 1 rpc/context.go:220  [n?] dialing roach-e9340988-1:26257
I161103 22:07:56.232607 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:07:56.232666 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-0:26257: RangeLookup [/Meta1/System/"node-idgen",/Min)
I161103 22:07:56.236011 1 kv/dist_sender.go:1106  [n?,range-lookup] RPC reply: (err: <nil>), *roachpb.RangeLookupResponse
I161103 22:07:56.236151 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:07:56.236258 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:07:56.236302 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-0:26257: RangeLookup [/Meta2/System/"node-idgen",/Min)
I161103 22:07:56.242599 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=4.445935ms, err=4.804007ms, at=2016-11-03 22:07:56.242553936 +0000 UTC
I161103 22:07:56.242650 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:07:56.242740 1 kv/dist_sender.go:1106  [n?,range-lookup] RPC reply: (err: <nil>), *roachpb.RangeLookupResponse
I161103 22:07:56.242828 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 22:07:56.242887 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 22:07:56.242929 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 22:07:56.242953 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:07:56.243006 1 kv/range_cache.go:608  [n?] clearing overlapping descriptor: key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:07:56.243054 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:07:56.243113 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I161103 22:07:56.243154 1 kv/leaseholder_cache.go:61  [n?] lookup lease holder for range 1: not found
I161103 22:07:56.243187 1 kv/dist_sender.go:1081  [n?] sending RPC for batch: 1 Inc
I161103 22:07:56.243216 1 kv/transport.go:168  [n?] sending request to roach-e9340988-0:26257: Increment [/System/"node-idgen",/Min)
I161103 22:07:56.743831 1 kv/dist_sender.go:1096  [n?] timeout, trying next peer
I161103 22:07:56.743897 1 kv/transport.go:168  [n?] sending request to roach-e9340988-1:26257: Increment [/System/"node-idgen",/Min)
I161103 22:07:56.745562 1 kv/dist_sender.go:1106  [n?] RPC reply: (err: range 1: replica {0 0 0} not lease holder; node_id:1 store_id:1 replica_id:1  is)
I161103 22:07:56.745616 1 kv/leaseholder_cache.go:61  [n?] lookup lease holder for range 1: not found
I161103 22:07:56.745924 1 kv/dist_sender.go:1229  [n?] range 1: caching new lease holder {NodeID:1 StoreID:1 ReplicaID:1}
I161103 22:07:56.745958 1 kv/leaseholder_cache.go:81  [n?] updating lease holder for range 1: {1 1 1}
I161103 22:07:58.616867 39 gossip/client.go:225  [n?] received [liveness:2 node:1 node:2 liveness:1 first-range sentinel store:1 store:2 system-db cluster-id] from node 1 (1 fresh)
I161103 22:07:58.616918 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:07:59.104932 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=232.921µs, err=517.781µs, at=2016-11-03 22:07:59.104902058 +0000 UTC
I161103 22:07:59.104974 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:07:59.244884 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=28.665µs, err=629.647µs, at=2016-11-03 22:07:59.24483568 +0000 UTC
I161103 22:07:59.244998 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:00.248496 39 gossip/client.go:225  [n?] received [liveness:1 node:1 node:2 store:2 store:1 system-db cluster-id first-range liveness:2 sentinel] from node 1 (1 fresh)
I161103 22:08:00.248546 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:01.057933 29 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 22:08:02.106393 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=72.763µs, err=481.874µs, at=2016-11-03 22:08:02.106315839 +0000 UTC
I161103 22:08:02.106471 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:02.247955 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=28.665µs, err=629.647µs, at=2016-11-03 22:07:59.24483568 +0000 UTC
I161103 22:08:02.248331 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:03.615588 39 gossip/client.go:225  [n?] received [cluster-id liveness:1 node:1 store:2 system-db first-range liveness:2 node:2 sentinel store:1] from node 1 (1 fresh)
I161103 22:08:03.615651 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:05.107960 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:05.108000 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:05.250936 39 gossip/client.go:225  [n?] received [first-range liveness:1 store:2 cluster-id node:1 node:2 sentinel store:1 system-db liveness:2] from node 1 (1 fresh)
I161103 22:08:05.251075 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:05.252694 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=28.665µs, err=629.647µs, at=2016-11-03 22:07:59.24483568 +0000 UTC
I161103 22:08:05.252765 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:06.059018 30 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 22:08:06.059086 29 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 22:08:08.113688 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:08.113832 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:08.253867 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:08.253916 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:08.616123 39 gossip/client.go:225  [n?] received [cluster-id liveness:2 node:2 sentinel first-range liveness:1 node:1 store:1 store:2 system-db] from node 1 (1 fresh)
I161103 22:08:08.616301 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:10.244588 39 gossip/client.go:225  [n?] received [liveness:1 liveness:2 node:2 store:2 system-db cluster-id first-range node:1 sentinel store:1] from node 1 (1 fresh)
I161103 22:08:10.244643 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:11.060195 29 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 22:08:11.116268 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:11.116326 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:11.255488 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:11.255548 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:13.616468 39 gossip/client.go:225  [n?] received [node:1 node:2 sentinel system-db cluster-id first-range liveness:1 liveness:2 store:1 store:2] from node 1 (1 fresh)
I161103 22:08:13.616515 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:14.118794 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:14.118857 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:14.257904 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:14.257947 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:15.251853 39 gossip/client.go:225  [n?] received [first-range liveness:1 store:1 system-db cluster-id liveness:2 node:1 node:2 sentinel store:2] from node 1 (1 fresh)
I161103 22:08:15.252129 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:16.058595 30 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 22:08:16.060817 29 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 22:08:17.121949 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:17.122085 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:17.259716 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:17.259769 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:18.617468 39 gossip/client.go:225  [n?] received [liveness:1 node:2 sentinel store:1 system-db cluster-id first-range liveness:2 node:1 store:2] from node 1 (1 fresh)
I161103 22:08:18.618583 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:20.124621 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:20.124815 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:20.245190 39 gossip/client.go:225  [n?] received [node:2 sentinel system-db cluster-id first-range liveness:1 liveness:2 node:1 store:1 store:2] from node 1 (1 fresh)
I161103 22:08:20.245225 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:20.262135 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:20.262193 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:21.061354 29 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 22:08:23.128585 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:23.128638 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:23.264853 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:23.265004 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:23.615704 39 gossip/client.go:225  [n?] received [node:1 node:2 cluster-id liveness:1 liveness:2 sentinel store:1 store:2 system-db first-range] from node 1 (1 fresh)
I161103 22:08:23.616002 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:25.247931 39 gossip/client.go:225  [n?] received [cluster-id first-range liveness:1 liveness:2 node:1 store:1 node:2 sentinel store:2 system-db] from node 1 (1 fresh)
I161103 22:08:25.248187 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:26.058764 30 storage/raft_transport.go:237  [n?] stats:
         qlen   qmax   qdropped client-sent client-recv server-sent server-recv
I161103 22:08:26.062124 29 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 22:08:26.130766 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:26.130912 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:26.266958 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:26.267027 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:28.614711 39 gossip/client.go:225  [n?] received [first-range liveness:1 liveness:2 node:1 sentinel store:1 cluster-id store:2 system-db node:2] from node 1 (1 fresh)
I161103 22:08:28.614745 39 gossip/server.go:342  [n?] distantHops: 2 from 2
I161103 22:08:29.133009 11 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-0:26257 off=107.371µs, err=313.525µs, at=2016-11-03 22:08:05.107926085 +0000 UTC
I161103 22:08:29.133072 11 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:29.269728 79 rpc/clock_offset.go:117  [n?] update offset: roach-e9340988-1:26257 off=80.603µs, err=322.813µs, at=2016-11-03 22:08:08.253829212 +0000 UTC
I161103 22:08:29.270051 79 rpc/clock_offset.go:168  [n?] 2 of 2 nodes are within the maximum offset of 250ms
I161103 22:08:29.504383 62 gossip/gossip.go:1071  [n?] node has connected to cluster via gossip
I161103 22:08:29.504565 62 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage
I161103 22:08:29.634550 71 http2_client.go:1053  transport: http2Client.notifyError got notified that the client transport was broken EOF.
W161103 22:08:29.635178 62 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
W161103 22:08:29.635365 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 13 desc = transport is closing
I161103 22:08:29.635597 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/System/"node-idgen" desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.635682 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta2/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.635781 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta1/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.640728 10 /go/src/google.golang.org/grpc/clientconn.go:667  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 172.20.0.2:26257: getsockopt: connection refused"; Reconnecting to {"roach-e9340988-0:26257" <nil>}
W161103 22:08:29.640985 114 gossip/client.go:120  [n?] node 0: failed to start gossip client: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:29.693363 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/System/"node-idgen"
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.693472 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/Meta2/System/"node-idgen"
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.693540 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:08:29.693600 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-1:26257: RangeLookup [/Meta1/System/"node-idgen",/Min)
I161103 22:08:29.694661 1 kv/dist_sender.go:1106  [n?,range-lookup] RPC reply: (err: <nil>), *roachpb.RangeLookupResponse
I161103 22:08:29.694715 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 22:08:29.694764 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:08:29.694803 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-0:26257: RangeLookup [/Meta2/System/"node-idgen",/Min)
W161103 22:08:29.694877 1 kv/dist_sender.go:1136  [n?,range-lookup] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:29.784934 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I161103 22:08:29.784994 1 kv/leaseholder_cache.go:56  [n?] lookup lease holder for range 1: {1 1 1}
I161103 22:08:29.785104 1 kv/dist_sender.go:1081  [n?] sending RPC for batch: 1 Inc
I161103 22:08:29.785215 1 kv/transport.go:168  [n?] sending request to roach-e9340988-0:26257: Increment [/System/"node-idgen",/Min)
W161103 22:08:29.785519 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:29.785921 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/System/"node-idgen" desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.786170 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta2/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.786426 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta1/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.994036 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/System/"node-idgen"
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.994550 1 kv/range_cache.go:303  [n?] lookup range descriptor: key=/Meta2/System/"node-idgen"
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:29.994837 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:08:29.994987 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-1:26257: RangeLookup [/Meta1/System/"node-idgen",/Min)
I161103 22:08:29.996641 1 kv/dist_sender.go:1106  [n?,range-lookup] RPC reply: (err: <nil>), *roachpb.RangeLookupResponse
I161103 22:08:29.996711 1 kv/range_cache.go:582  [n?] adding descriptor: key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 22:08:29.996767 1 kv/dist_sender.go:1081  [n?,range-lookup] sending RPC for batch: 1 RngLookup
I161103 22:08:29.996808 1 kv/transport.go:168  [n?,range-lookup] sending request to roach-e9340988-0:26257: RangeLookup [/Meta2/System/"node-idgen",/Min)
W161103 22:08:29.996889 1 kv/dist_sender.go:1136  [n?,range-lookup] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:30.357233 1 kv/dist_sender.go:330  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I161103 22:08:30.357276 1 kv/leaseholder_cache.go:56  [n?] lookup lease holder for range 1: {1 1 1}
I161103 22:08:30.357300 1 kv/dist_sender.go:1081  [n?] sending RPC for batch: 1 Inc
I161103 22:08:30.357337 1 kv/transport.go:168  [n?] sending request to roach-e9340988-0:26257: Increment [/System/"node-idgen",/Min)
W161103 22:08:30.357425 1 kv/dist_sender.go:1136  [n?] RPC error: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:30.357642 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/System/"node-idgen" desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/11 desc=range_id:1 start_key:"" end_key:"\223" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:30.357752 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta2/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:30.357826 1 kv/range_cache.go:481  [n?] evict cached descriptor: key=/Meta1/System/"node-idgen" desc=<nil>
key=/Meta2/Table/12 desc=range_id:2 start_key:"\223" end_key:"\224" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/13 desc=range_id:3 start_key:"\224" end_key:"\225" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Table/14 desc=range_id:4 start_key:"\225" end_key:"\226" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
key=/Meta2/Max desc=range_id:5 start_key:"\226" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 22:08:30.484243 15 http2_client.go:1053  transport: http2Client.notifyError got notified that the client transport was broken EOF.
I161103 22:08:30.490524 78 /go/src/google.golang.org/grpc/clientconn.go:667  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 172.20.0.3:26257: getsockopt: connection refused"; Reconnecting to {"roach-e9340988-1:26257" <nil>}
W161103 22:08:30.645086 136 gossip/client.go:120  [n?] node 0: failed to start gossip client: rpc error: code = 14 desc = grpc: the connection is unavailable
I161103 22:08:30.678968 10 /go/src/google.golang.org/grpc/clientconn.go:667  grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp: lookup roach-e9340988-0 on 127.0.0.11:53: no such host"; Reconnecting to {"roach-e9340988-0:26257" <nil>}
I161103 22:08:31.062696 29 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)