teamcity: failed tests on master: testrace/TestMonotonicInserts, testrace/TestMonotonicInserts/distsql=on #16610
Description
The following tests appear to have failed:
--- FAIL: testrace/TestMonotonicInserts (18.640s)
null
--- FAIL: testrace/TestMonotonicInserts/distsql=on (9.080s)
monotonic_insert_test.go:216: 'val' column is not unique: 32 results, but 31 distinct:
ok {val:-1 sts:0 node:-1 tb:-1}
ok {val:0 sts:1497902871889821682.0000000000 node:0 tb:0}
ok {val:1 sts:1497902872117376985.0000000000 node:1 tb:0}
ok {val:2 sts:1497902872118628485.0000000001 node:1 tb:0}
ok {val:3 sts:1497902872118628485.0000000002 node:2 tb:0}
ok {val:4 sts:1497902872260716424.0000000001 node:1 tb:0}
ok {val:5 sts:1497902872688864242.0000000000 node:0 tb:0}
ok {val:6 sts:1497902872923524742.0000000000 node:1 tb:0}
ok {val:7 sts:1497902872947994331.0000000000 node:1 tb:0}
ok {val:8 sts:1497902872997395210.0000000001 node:2 tb:0}
ok {val:9 sts:1497902873167135838.0000000000 node:0 tb:0}
ok {val:9 sts:1497902873509064392.0000000000 node:0 tb:0} <<<<----
ok {val:10 sts:1497902873567146467.0000000001 node:2 tb:0}
ok {val:11 sts:1497902873890081330.0000000001 node:1 tb:0}
ok {val:12 sts:1497902873968422796.0000000000 node:2 tb:0}
ok {val:13 sts:1497902874284912861.0000000001 node:2 tb:0}
ok {val:14 sts:1497902874284912861.0000000003 node:1 tb:0}
ok {val:15 sts:1497902874555218146.0000000001 node:2 tb:0}
ok {val:16 sts:1497902874555218146.0000000002 node:2 tb:0}
ok {val:17 sts:1497902874749186863.0000000001 node:1 tb:0}
ok {val:18 sts:1497902874884876305.0000000000 node:0 tb:0}
ok {val:19 sts:1497902875168815184.0000000001 node:1 tb:0}
ok {val:20 sts:1497902875168815184.0000000002 node:1 tb:0}
ok {val:21 sts:1497902875436083670.0000000001 node:0 tb:0}
ok {val:22 sts:1497902875436083670.0000000002 node:0 tb:0}
ok {val:23 sts:1497902875903349371.0000000001 node:2 tb:0}
ok {val:24 sts:1497902876597891975.0000000000 node:1 tb:0}
ok {val:25 sts:1497902877088565066.0000000001 node:0 tb:0}
ok {val:26 sts:1497902877174831629.0000000001 node:2 tb:0}
ok {val:27 sts:1497902877430503620.0000000001 node:2 tb:0}
ok {val:28 sts:1497902877723610095.0000000001 node:0 tb:0}
ok {val:29 sts:1497902877919169011.0000000001 node:0 tb:0}
------- Stdout: -------
W170619 20:07:49.179742 73508 server/status/runtime.go:111 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I170619 20:07:49.184478 73508 server/config.go:479 [n?] 1 storage engine initialized
I170619 20:07:49.184522 73508 server/config.go:481 [n?] RocksDB cache size: 512 MiB
I170619 20:07:49.184567 73508 server/config.go:481 [n?] store 0: in-memory, size 100 MiB
I170619 20:07:49.185602 73508 server/node.go:450 [n?] store [n0,s0] not bootstrapped
I170619 20:07:49.208893 73508 server/node.go:385 [n?] **** cluster 11d978db-400a-4cba-94ef-fcaa09831d7e has been created
I170619 20:07:49.208987 73508 server/node.go:386 [n?] **** add additional nodes by specifying --join=127.0.0.1:45103
I170619 20:07:49.224657 73508 storage/store.go:1262 [n1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I170619 20:07:49.225039 73508 server/node.go:463 [n1] initialized store [n1,s1]: {Capacity:536870912 Available:536870912 RangeCount:1 LeaseCount:0}
I170619 20:07:49.225229 73508 server/node.go:347 [n1] node ID 1 initialized
I170619 20:07:49.225463 73508 gossip/gossip.go:297 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:45103" > attrs:<> locality:<>
I170619 20:07:49.229849 73508 storage/stores.go:296 [n1] read 0 node addresses from persistent storage
I170619 20:07:49.230023 73508 server/node.go:604 [n1] connecting to gossip network to verify cluster ID...
I170619 20:07:49.230117 73508 server/node.go:629 [n1] node connected via gossip and verified as part of cluster "11d978db-400a-4cba-94ef-fcaa09831d7e"
I170619 20:07:49.230494 73508 server/node.go:401 [n1] node=1: started with [[]=] engine(s) and attributes []
I170619 20:07:49.234088 73508 sql/executor.go:358 [n1] creating distSQLPlanner with address {tcp 127.0.0.1:45103}
I170619 20:07:49.237801 73698 storage/replica_command.go:2695 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I170619 20:07:49.262043 73508 server/server.go:760 [n1] starting https server at 127.0.0.1:58037
I170619 20:07:49.262164 73508 server/server.go:761 [n1] starting grpc/postgres server at 127.0.0.1:45103
I170619 20:07:49.262220 73508 server/server.go:762 [n1] advertising CockroachDB node at 127.0.0.1:45103
I170619 20:07:49.328097 73698 storage/replica_command.go:2695 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/tsd [r3]
I170619 20:07:49.426750 73698 storage/replica_command.go:2695 [split,n1,s1,r3/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r4]
I170619 20:07:49.467882 73508 sql/event_log.go:101 [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN uniqueid SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I170619 20:07:49.491862 73698 storage/replica_command.go:2695 [split,n1,s1,r4/1:/{System/tse-Max}] initiating a split of this range at key /Table/0 [r5]
I170619 20:07:49.506965 73508 sql/lease.go:349 [n1] publish: descID=12 (eventlog) version=2 mtime=2017-06-19 20:07:49.506861498 +0000 UTC
I170619 20:07:49.526665 73698 storage/replica_command.go:2695 [split,n1,s1,r5/1:/{Table/0-Max}] initiating a split of this range at key /Table/11 [r6]
I170619 20:07:49.564741 73698 storage/replica_command.go:2695 [split,n1,s1,r6/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r7]
I170619 20:07:49.616760 73698 storage/replica_command.go:2695 [split,n1,s1,r7/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r8]
I170619 20:07:49.637169 73508 server/server.go:874 [n1] done ensuring all necessary migrations have run
I170619 20:07:49.637316 73508 server/server.go:876 [n1] serving sql connections
I170619 20:07:49.657545 73939 sql/event_log.go:101 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:45103} Attrs: Locality:} ClusterID:11d978db-400a-4cba-94ef-fcaa09831d7e StartedAt:1497902869230155316 LastUp:1497902869230155316}
I170619 20:07:49.682837 73698 storage/replica_command.go:2695 [split,n1,s1,r8/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r9]
I170619 20:07:49.754831 73698 storage/replica_command.go:2695 [split,n1,s1,r9/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r10]
W170619 20:07:49.852085 73508 server/status/runtime.go:111 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W170619 20:07:49.856245 73508 gossip/gossip.go:1196 [n?] no incoming or outgoing connections
I170619 20:07:49.857468 73508 server/config.go:479 [n?] 1 storage engine initialized
I170619 20:07:49.857519 73508 server/config.go:481 [n?] RocksDB cache size: 512 MiB
I170619 20:07:49.857554 73508 server/config.go:481 [n?] store 0: in-memory, size 100 MiB
I170619 20:07:49.858700 73508 server/node.go:450 [n?] store [n0,s0] not bootstrapped
I170619 20:07:49.858846 73508 storage/stores.go:296 [n?] read 0 node addresses from persistent storage
I170619 20:07:49.858936 73508 server/node.go:604 [n?] connecting to gossip network to verify cluster ID...
I170619 20:07:49.908610 74068 gossip/client.go:131 [n?] started gossip client to 127.0.0.1:45103
I170619 20:07:49.909244 74085 gossip/server.go:234 [n1] received initial cluster-verification connection from {tcp 127.0.0.1:59491}
I170619 20:07:49.912140 73508 server/node.go:629 [n?] node connected via gossip and verified as part of cluster "11d978db-400a-4cba-94ef-fcaa09831d7e"
I170619 20:07:49.912901 74130 storage/stores.go:312 [n?] wrote 1 node addresses to persistent storage
I170619 20:07:49.922583 73508 kv/dist_sender.go:370 [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I170619 20:07:49.926668 73508 server/node.go:340 [n?] new node allocated ID 2
I170619 20:07:49.926931 73508 gossip/gossip.go:297 [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:59491" > attrs:<> locality:<>
I170619 20:07:49.927628 73508 server/node.go:401 [n2] node=2: started with [[]=] engine(s) and attributes []
I170619 20:07:49.929844 73508 sql/executor.go:358 [n2] creating distSQLPlanner with address {tcp 127.0.0.1:59491}
I170619 20:07:49.932278 74106 storage/stores.go:312 [n1] wrote 1 node addresses to persistent storage
I170619 20:07:49.957605 73508 server/server.go:760 [n2] starting https server at 127.0.0.1:42857
I170619 20:07:49.957729 73508 server/server.go:761 [n2] starting grpc/postgres server at 127.0.0.1:59491
I170619 20:07:49.957780 73508 server/server.go:762 [n2] advertising CockroachDB node at 127.0.0.1:59491
I170619 20:07:49.971621 73508 server/server.go:874 [n2] done ensuring all necessary migrations have run
I170619 20:07:49.971960 73508 server/server.go:876 [n2] serving sql connections
I170619 20:07:49.975145 74149 server/node.go:585 [n2] bootstrapped store [n2,s2]
W170619 20:07:50.038275 73508 server/status/runtime.go:111 Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W170619 20:07:50.042380 73508 gossip/gossip.go:1196 [n?] no incoming or outgoing connections
I170619 20:07:50.044667 73508 server/config.go:479 [n?] 1 storage engine initialized
I170619 20:07:50.044753 73508 server/config.go:481 [n?] RocksDB cache size: 512 MiB
I170619 20:07:50.044788 73508 server/config.go:481 [n?] store 0: in-memory, size 100 MiB
I170619 20:07:50.046894 73508 server/node.go:450 [n?] store [n0,s0] not bootstrapped
I170619 20:07:50.047008 73508 storage/stores.go:296 [n?] read 0 node addresses from persistent storage
I170619 20:07:50.047097 73508 server/node.go:604 [n?] connecting to gossip network to verify cluster ID...
I170619 20:07:50.056178 74290 sql/event_log.go:101 [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:59491} Attrs: Locality:} ClusterID:11d978db-400a-4cba-94ef-fcaa09831d7e StartedAt:1497902869927387719 LastUp:1497902869927387719}
I170619 20:07:50.109690 74309 gossip/client.go:131 [n?] started gossip client to 127.0.0.1:45103
I170619 20:07:50.111704 74342 gossip/server.go:234 [n1] received initial cluster-verification connection from {tcp 127.0.0.1:34305}
I170619 20:07:50.114876 73508 server/node.go:629 [n?] node connected via gossip and verified as part of cluster "11d978db-400a-4cba-94ef-fcaa09831d7e"
I170619 20:07:50.115867 74266 storage/stores.go:312 [n?] wrote 1 node addresses to persistent storage
I170619 20:07:50.118241 74267 storage/stores.go:312 [n?] wrote 2 node addresses to persistent storage
I170619 20:07:50.121526 73508 kv/dist_sender.go:370 [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I170619 20:07:50.126041 73508 server/node.go:340 [n?] new node allocated ID 3
I170619 20:07:50.126297 73508 gossip/gossip.go:297 [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:34305" > attrs:<> locality:<>
I170619 20:07:50.127019 73508 server/node.go:401 [n3] node=3: started with [[]=] engine(s) and attributes []
I170619 20:07:50.129259 74389 storage/stores.go:312 [n1] wrote 2 node addresses to persistent storage
I170619 20:07:50.133041 73508 sql/executor.go:358 [n3] creating distSQLPlanner with address {tcp 127.0.0.1:34305}
I170619 20:07:50.133252 74286 storage/stores.go:312 [n2] wrote 2 node addresses to persistent storage
I170619 20:07:50.156516 73508 server/server.go:760 [n3] starting https server at 127.0.0.1:50023
I170619 20:07:50.156651 73508 server/server.go:761 [n3] starting grpc/postgres server at 127.0.0.1:34305
I170619 20:07:50.156735 73508 server/server.go:762 [n3] advertising CockroachDB node at 127.0.0.1:34305
I170619 20:07:50.181869 74315 server/node.go:585 [n3] bootstrapped store [n3,s3]
I170619 20:07:50.184765 73508 server/server.go:874 [n3] done ensuring all necessary migrations have run
I170619 20:07:50.184882 73508 server/server.go:876 [n3] serving sql connections
I170619 20:07:50.190280 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot f70d24c2 at index 24
I170619 20:07:50.230669 74326 sql/event_log.go:101 [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:34305} Attrs: Locality:} ClusterID:11d978db-400a-4cba-94ef-fcaa09831d7e StartedAt:1497902870126752034 LastUp:1497902870126752034}
I170619 20:07:50.257532 73504 storage/store.go:3393 [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot to (n3,s3):?: kv pairs: 37, log entries: 14, rate-limit: 8.0 MiB/sec, 7ms
I170619 20:07:50.260491 74396 storage/replica_raftstorage.go:639 [n3,s3,r5/?:{-}] applying preemptive snapshot at index 24 (id=f70d24c2, encoded size=17189, 1 rocksdb batches, 14 log entries)
I170619 20:07:50.261985 74396 storage/replica_raftstorage.go:647 [n3,s3,r5/?:/Table/{0-11}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.265118 73504 storage/replica_command.go:3600 [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/Table/{0-11} [(n1,s1):1, next=2]
I170619 20:07:50.292510 74579 storage/replica.go:2884 [n1,s1,r5/1:/Table/{0-11}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]
I170619 20:07:50.300607 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot beb46798 at index 39
I170619 20:07:50.312071 74595 storage/raft_transport.go:456 [n3] raft transport stream to node 1 established
I170619 20:07:50.356217 73504 storage/store.go:3393 [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 32, log entries: 22, rate-limit: 8.0 MiB/sec, 4ms
I170619 20:07:50.358758 74538 storage/replica_raftstorage.go:639 [n2,s2,r2/?:{-}] applying preemptive snapshot at index 39 (id=beb46798, encoded size=122878, 1 rocksdb batches, 22 log entries)
I170619 20:07:50.361817 74538 storage/replica_raftstorage.go:647 [n2,s2,r2/?:/System/{-tsd}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.366923 73504 storage/replica_command.go:3600 [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, next=2]
I170619 20:07:50.393461 74645 storage/replica.go:2884 [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]
I170619 20:07:50.400402 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 2dd8b7b8 at index 49
I170619 20:07:50.404212 73504 storage/store.go:3393 [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 34, log entries: 39, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:50.418088 74541 storage/replica_raftstorage.go:639 [n2,s2,r1/?:{-}] applying preemptive snapshot at index 49 (id=2dd8b7b8, encoded size=23554, 1 rocksdb batches, 39 log entries)
I170619 20:07:50.421718 74541 storage/replica_raftstorage.go:647 [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.422428 74635 storage/raft_transport.go:456 [n2] raft transport stream to node 1 established
I170619 20:07:50.428120 73504 storage/replica_command.go:3600 [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I170619 20:07:50.445719 74674 storage/replica.go:2884 [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]
I170619 20:07:50.449883 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot b4d7acae at index 19
I170619 20:07:50.453183 73504 storage/store.go:3393 [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:50.454966 74615 storage/replica_raftstorage.go:639 [n3,s3,r9/?:{-}] applying preemptive snapshot at index 19 (id=b4d7acae, encoded size=5750, 1 rocksdb batches, 9 log entries)
I170619 20:07:50.456236 74615 storage/replica_raftstorage.go:647 [n3,s3,r9/?:/Table/1{4-5}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.459085 73504 storage/replica_command.go:3600 [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r9:/Table/1{4-5} [(n1,s1):1, next=2]
I170619 20:07:50.483495 74694 storage/replica.go:2884 [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]
I170619 20:07:50.487592 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot 144bfe27 at index 31
I170619 20:07:50.497625 73504 storage/store.go:3393 [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 88, log entries: 21, rate-limit: 8.0 MiB/sec, 6ms
I170619 20:07:50.499115 74713 storage/replica_raftstorage.go:639 [n2,s2,r8/?:{-}] applying preemptive snapshot at index 31 (id=144bfe27, encoded size=28892, 1 rocksdb batches, 21 log entries)
I170619 20:07:50.500828 74713 storage/replica_raftstorage.go:647 [n2,s2,r8/?:/Table/1{3-4}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.503556 73504 storage/replica_command.go:3600 [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r8:/Table/1{3-4} [(n1,s1):1, next=2]
I170619 20:07:50.526925 74617 storage/replica.go:2884 [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]
I170619 20:07:50.532082 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot 8034fdb8 at index 27
I170619 20:07:50.546356 73504 storage/store.go:3393 [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 908, log entries: 2, rate-limit: 8.0 MiB/sec, 14ms
I170619 20:07:50.548331 74716 storage/replica_raftstorage.go:639 [n3,s3,r3/?:{-}] applying preemptive snapshot at index 27 (id=8034fdb8, encoded size=120409, 1 rocksdb batches, 2 log entries)
I170619 20:07:50.550315 74716 storage/replica_raftstorage.go:647 [n3,s3,r3/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I170619 20:07:50.553198 73504 storage/replica_command.go:3600 [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/ts{d-e} [(n1,s1):1, next=2]
I170619 20:07:50.582780 74704 storage/replica.go:2884 [n1,s1,r3/1:/System/ts{d-e}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]
I170619 20:07:50.586307 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot 5fa56b14 at index 11
I170619 20:07:50.598725 73504 storage/store.go:3393 [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 1, rate-limit: 8.0 MiB/sec, 12ms
I170619 20:07:50.600733 74657 storage/replica_raftstorage.go:639 [n2,s2,r10/?:{-}] applying preemptive snapshot at index 11 (id=5fa56b14, encoded size=476, 1 rocksdb batches, 1 log entries)
I170619 20:07:50.601783 74657 storage/replica_raftstorage.go:647 [n2,s2,r10/?:/{Table/15-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.616733 73504 storage/replica_command.go:3600 [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r10:/{Table/15-Max} [(n1,s1):1, next=2]
I170619 20:07:50.646421 74734 storage/replica.go:2884 [n1,s1,r10/1:/{Table/15-Max}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]
I170619 20:07:50.650809 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot 3e49b666 at index 17
I170619 20:07:50.654473 73504 storage/store.go:3393 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 7, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:50.655816 74665 storage/replica_raftstorage.go:639 [n3,s3,r4/?:{-}] applying preemptive snapshot at index 17 (id=3e49b666, encoded size=6315, 1 rocksdb batches, 7 log entries)
I170619 20:07:50.657442 74665 storage/replica_raftstorage.go:647 [n3,s3,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.660275 73504 storage/replica_command.go:3600 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/{System/tse-Table/0} [(n1,s1):1, next=2]
I170619 20:07:50.716113 74759 storage/replica.go:2884 [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]
I170619 20:07:50.721644 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot 1f43e5f3 at index 29
I170619 20:07:50.725941 73504 storage/store.go:3393 [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 30, log entries: 19, rate-limit: 8.0 MiB/sec, 4ms
I170619 20:07:50.727273 74762 storage/replica_raftstorage.go:639 [n3,s3,r7/?:{-}] applying preemptive snapshot at index 29 (id=1f43e5f3, encoded size=20161, 1 rocksdb batches, 19 log entries)
I170619 20:07:50.728904 74762 storage/replica_raftstorage.go:647 [n3,s3,r7/?:/Table/1{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.732225 73504 storage/replica_command.go:3600 [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r7:/Table/1{2-3} [(n1,s1):1, next=2]
I170619 20:07:50.771623 74742 storage/replica.go:2884 [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA (n3,s3):2: [(n1,s1):1 (n3,s3):2]
I170619 20:07:50.777530 73504 storage/replica_raftstorage.go:442 [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot ddfa459a at index 16
I170619 20:07:50.783995 73504 storage/store.go:3393 [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 6, rate-limit: 8.0 MiB/sec, 5ms
I170619 20:07:50.786351 74671 storage/replica_raftstorage.go:639 [n2,s2,r6/?:{-}] applying preemptive snapshot at index 16 (id=ddfa459a, encoded size=5314, 1 rocksdb batches, 6 log entries)
I170619 20:07:50.787537 74671 storage/replica_raftstorage.go:647 [n2,s2,r6/?:/Table/1{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.793447 73504 storage/replica_command.go:3600 [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, next=2]
I170619 20:07:50.816945 74852 storage/replica.go:2884 [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA (n2,s2):2: [(n1,s1):1 (n2,s2):2]
I170619 20:07:50.819447 73504 storage/queue.go:724 [n1,replicate] purgatory is now empty
I170619 20:07:50.820867 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot 260088b1 at index 29
I170619 20:07:50.824731 73699 storage/store.go:3393 [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot to (n2,s2):?: kv pairs: 39, log entries: 19, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:50.826458 74813 storage/replica_raftstorage.go:639 [n2,s2,r5/?:{-}] applying preemptive snapshot at index 29 (id=260088b1, encoded size=20192, 1 rocksdb batches, 19 log entries)
I170619 20:07:50.828133 74813 storage/replica_raftstorage.go:647 [n2,s2,r5/?:/Table/{0-11}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.832535 73699 storage/replica_command.go:3600 [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r5:/Table/{0-11} [(n1,s1):1, (n3,s3):2, next=3]
I170619 20:07:50.870318 74885 storage/replica.go:2884 [n1,s1,r5/1:/Table/{0-11}] proposing ADD_REPLICA (n2,s2):3: [(n1,s1):1 (n3,s3):2 (n2,s2):3]
I170619 20:07:50.877182 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot d6a5987d at index 32
I170619 20:07:50.884704 74827 storage/replica_raftstorage.go:639 [n2,s2,r7/?:{-}] applying preemptive snapshot at index 32 (id=d6a5987d, encoded size=22201, 1 rocksdb batches, 22 log entries)
I170619 20:07:50.886478 74827 storage/replica_raftstorage.go:647 [n2,s2,r7/?:/Table/1{2-3}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:50.887579 73699 storage/store.go:3393 [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 31, log entries: 22, rate-limit: 8.0 MiB/sec, 9ms
I170619 20:07:50.889375 73699 storage/replica_command.go:3600 [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r7:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, next=3]
I170619 20:07:50.919131 74751 storage/replica.go:2884 [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA (n2,s2):3: [(n1,s1):1 (n3,s3):2 (n2,s2):3]
I170619 20:07:50.936636 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot b03e2f56 at index 19
I170619 20:07:50.961147 73699 storage/store.go:3393 [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 9, rate-limit: 8.0 MiB/sec, 16ms
I170619 20:07:50.962719 74842 storage/replica_raftstorage.go:639 [n3,s3,r6/?:{-}] applying preemptive snapshot at index 19 (id=b03e2f56, encoded size=7354, 1 rocksdb batches, 9 log entries)
I170619 20:07:50.964037 74842 storage/replica_raftstorage.go:647 [n3,s3,r6/?:/Table/1{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:50.967034 73699 storage/replica_command.go:3600 [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r6:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I170619 20:07:51.011379 74920 storage/replica.go:2884 [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]
I170619 20:07:51.020760 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot 6d68a541 at index 30
I170619 20:07:51.037577 73699 storage/store.go:3393 [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 909, log entries: 5, rate-limit: 8.0 MiB/sec, 16ms
I170619 20:07:51.039765 74930 storage/replica_raftstorage.go:639 [n2,s2,r3/?:{-}] applying preemptive snapshot at index 30 (id=6d68a541, encoded size=122518, 1 rocksdb batches, 5 log entries)
I170619 20:07:51.041828 74930 storage/replica_raftstorage.go:647 [n2,s2,r3/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I170619 20:07:51.049483 73699 storage/replica_command.go:3600 [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r3:/System/ts{d-e} [(n1,s1):1, (n3,s3):2, next=3]
I170619 20:07:51.079724 74889 storage/replica.go:2884 [n1,s1,r3/1:/System/ts{d-e}] proposing ADD_REPLICA (n2,s2):3: [(n1,s1):1 (n3,s3):2 (n2,s2):3]
I170619 20:07:51.087177 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot 2e631b87 at index 53
I170619 20:07:51.093370 73699 storage/store.go:3393 [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 139, log entries: 43, rate-limit: 8.0 MiB/sec, 5ms
I170619 20:07:51.095534 74925 storage/replica_raftstorage.go:639 [n3,s3,r8/?:{-}] applying preemptive snapshot at index 53 (id=2e631b87, encoded size=56050, 1 rocksdb batches, 43 log entries)
I170619 20:07:51.098344 74925 storage/replica_raftstorage.go:647 [n3,s3,r8/?:/Table/1{3-4}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170619 20:07:51.101535 73699 storage/replica_command.go:3600 [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r8:/Table/1{3-4} [(n1,s1):1, (n2,s2):2, next=3]
I170619 20:07:51.124844 74926 storage/replica.go:2884 [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]
I170619 20:07:51.130589 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot 111f120f at index 43
I170619 20:07:51.144470 73699 storage/store.go:3393 [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 33, log entries: 2, rate-limit: 8.0 MiB/sec, 13ms
I170619 20:07:51.147599 74849 storage/replica_raftstorage.go:639 [n3,s3,r2/?:{-}] applying preemptive snapshot at index 43 (id=111f120f, encoded size=48909, 1 rocksdb batches, 2 log entries)
I170619 20:07:51.151119 74849 storage/replica_raftstorage.go:647 [n3,s3,r2/?:/System/{-tsd}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I170619 20:07:51.154273 73699 storage/replica_command.go:3600 [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r2:/System/{-tsd} [(n1,s1):1, (n2,s2):2, next=3]
I170619 20:07:51.186860 74973 storage/replica.go:2884 [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]
I170619 20:07:51.194999 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot 71d686a6 at index 24
I170619 20:07:51.199733 73699 storage/store.go:3393 [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 14, rate-limit: 8.0 MiB/sec, 4ms
I170619 20:07:51.201027 74984 storage/replica_raftstorage.go:639 [n2,s2,r9/?:{-}] applying preemptive snapshot at index 24 (id=71d686a6, encoded size=8753, 1 rocksdb batches, 14 log entries)
I170619 20:07:51.202639 74984 storage/replica_raftstorage.go:647 [n2,s2,r9/?:/Table/1{4-5}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:51.205548 73699 storage/replica_command.go:3600 [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r9:/Table/1{4-5} [(n1,s1):1, (n3,s3):2, next=3]
I170619 20:07:51.246006 74956 storage/replica.go:2884 [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA (n2,s2):3: [(n1,s1):1 (n3,s3):2 (n2,s2):3]
I170619 20:07:51.253367 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot cf624802 at index 80
I170619 20:07:51.268018 73699 storage/store.go:3393 [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 51, log entries: 70, rate-limit: 8.0 MiB/sec, 14ms
I170619 20:07:51.271348 74896 storage/replica_raftstorage.go:639 [n3,s3,r1/?:{-}] applying preemptive snapshot at index 80 (id=cf624802, encoded size=39830, 1 rocksdb batches, 70 log entries)
I170619 20:07:51.274351 74896 storage/replica_raftstorage.go:647 [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I170619 20:07:51.277944 73699 storage/replica_command.go:3600 [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n2,s2):2, next=3]
I170619 20:07:51.299239 74990 storage/replica.go:2884 [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]
I170619 20:07:51.309182 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot 32b3bcc2 at index 23
I170619 20:07:51.313173 73699 storage/store.go:3393 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 13, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:51.330393 75059 storage/replica_raftstorage.go:639 [n2,s2,r4/?:{-}] applying preemptive snapshot at index 23 (id=32b3bcc2, encoded size=9931, 1 rocksdb batches, 13 log entries)
I170619 20:07:51.339397 75059 storage/replica_raftstorage.go:647 [n2,s2,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I170619 20:07:51.351587 73699 storage/replica_command.go:3600 [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r4:/{System/tse-Table/0} [(n1,s1):1, (n3,s3):2, next=3]
I170619 20:07:51.385364 75005 storage/replica.go:2884 [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA (n2,s2):3: [(n1,s1):1 (n3,s3):2 (n2,s2):3]
I170619 20:07:51.392959 73699 storage/replica_raftstorage.go:442 [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot ea917de9 at index 14
I170619 20:07:51.396714 73699 storage/store.go:3393 [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 4, rate-limit: 8.0 MiB/sec, 3ms
I170619 20:07:51.398785 74941 storage/replica_raftstorage.go:639 [n3,s3,r10/?:{-}] applying preemptive snapshot at index 14 (id=ea917de9, encoded size=2520, 1 rocksdb batches, 4 log entries)
I170619 20:07:51.408156 74941 storage/replica_raftstorage.go:647 [n3,s3,r10/?:/{Table/15-Max}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170619 20:07:51.412572 73699 storage/replica_command.go:3600 [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r10:/{Table/15-Max} [(n1,s1):1, (n2,s2):2, next=3]
I170619 20:07:51.442646 75032 storage/replica.go:2884 [n1,s1,r10/1:/{Table/15-Max}] proposing ADD_REPLICA (n3,s3):3: [(n1,s1):1 (n2,s2):2 (n3,s3):3]
I170619 20:07:51.464205 74215 storage/replica_proposal.go:397 [n2,s2,r4/3:/{System/tse-Table/0}] new range lease repl=(n2,s2):3 start=1497902871.449875070,0 epo=1 pro=1497902871.449883570,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497902878.221887319,0 pro=1497902869.221935019,0
I170619 20:07:51.544973 75063 storage/raft_transport.go:456 [n2] raft transport stream to node 3 established
I170619 20:07:51.597959 75138 storage/raft_transport.go:456 [n3] raft transport stream to node 2 established
I170619 20:07:51.710210 75098 sql/event_log.go:101 [client=127.0.0.1:41598,user=root,n1] Event: "create_database", target: 50, info: {DatabaseName:mono Statement:CREATE DATABASE mono User:root}
I170619 20:07:51.714498 73698 storage/replica_command.go:2695 [split,n1,s1,r10/1:/{Table/15-Max}] initiating a split of this range at key /Table/50 [r11]
I170619 20:07:51.798122 75098 sql/event_log.go:101 [client=127.0.0.1:41598,user=root,n1] Event: "create_table", target: 51, info: {TableName:mono.mono Statement:CREATE TABLE IF NOT EXISTS mono.mono (val INT, sts STRING, node INT, tb INT) User:root}
I170619 20:07:51.801561 73698 storage/replica_command.go:2695 [split,n1,s1,r11/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r12]
I170619 20:07:51.877963 75229 sql/monotonic_insert_test.go:136 001.002: begin
I170619 20:07:51.878484 75226 sql/monotonic_insert_test.go:136 002.000: begin
I170619 20:07:51.878960 75227 sql/monotonic_insert_test.go:136 003.001: begin
I170619 20:07:51.879429 75224 sql/monotonic_insert_test.go:136 004.001: begin
I170619 20:07:51.879538 75228 sql/monotonic_insert_test.go:136 005.001: begin
I170619 20:07:51.880026 75225 sql/monotonic_insert_test.go:136 006.002: begin
I170619 20:07:51.889499 75226 sql/monotonic_insert_test.go:136 002.000: attempt 1
I170619 20:07:51.897013 75226 sql/monotonic_insert_test.go:136 002.000: read max val
I170619 20:07:51.914194 75226 sql/monotonic_insert_test.go:136 002.000: read max row for val=-1
I170619 20:07:51.950376 75226 sql/monotonic_insert_test.go:136 002.000: insert
I170619 20:07:51.988326 75226 sql/monotonic_insert_test.go:136 002.000: commit
I170619 20:07:51.991692 75228 sql/monotonic_insert_test.go:136 005.001: attempt 1
I170619 20:07:51.992819 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:51.995285 75224 sql/monotonic_insert_test.go:136 004.001: attempt 1
I170619 20:07:51.996436 75224 sql/monotonic_insert_test.go:136 004.001: read max val
I170619 20:07:52.002139 75226 sql/monotonic_insert_test.go:136 002.000: done
I170619 20:07:52.002523 75189 sql/monotonic_insert_test.go:136 007.001: begin
I170619 20:07:52.013255 75227 sql/monotonic_insert_test.go:136 003.001: attempt 1
I170619 20:07:52.015239 75227 sql/monotonic_insert_test.go:136 003.001: read max val
I170619 20:07:52.021898 75229 sql/monotonic_insert_test.go:136 001.002: attempt 1
I170619 20:07:52.025294 75229 sql/monotonic_insert_test.go:136 001.002: read max val
I170619 20:07:52.032776 75225 sql/monotonic_insert_test.go:136 006.002: attempt 1
I170619 20:07:52.033939 75225 sql/monotonic_insert_test.go:136 006.002: read max val
I170619 20:07:52.117054 75189 sql/monotonic_insert_test.go:136 007.001: attempt 1
I170619 20:07:52.118263 75189 sql/monotonic_insert_test.go:136 007.001: read max val
I170619 20:07:52.153666 75382 sql/mon/mem_usage.go:536 [client=127.0.0.1:37015,user=root,n2,Agg] distsql: memory usage increases to 20 KiB (+10240)
I170619 20:07:52.154645 75189 sql/monotonic_insert_test.go:136 007.001: read max row for val=0
I170619 20:07:52.155545 75224 sql/monotonic_insert_test.go:136 004.001: read max row for val=0
I170619 20:07:52.155631 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=0
I170619 20:07:52.158230 75227 sql/monotonic_insert_test.go:136 003.001: read max row for val=0
I170619 20:07:52.166262 75189 sql/monotonic_insert_test.go:136 007.001: insert
I170619 20:07:52.170294 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:52.172822 75227 sql/monotonic_insert_test.go:136 003.001: insert
I170619 20:07:52.180164 75225 sql/monotonic_insert_test.go:136 006.002: read max row for val=0
I170619 20:07:52.182001 75229 sql/monotonic_insert_test.go:136 001.002: read max row for val=0
I170619 20:07:52.182795 75224 sql/monotonic_insert_test.go:136 004.001: insert
I170619 20:07:52.208867 75189 sql/monotonic_insert_test.go:136 007.001: commit
I170619 20:07:52.213361 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:52.224718 75189 sql/monotonic_insert_test.go:136 007.001: done
I170619 20:07:52.225051 75407 sql/monotonic_insert_test.go:136 008.002: begin
I170619 20:07:52.234377 75224 sql/monotonic_insert_test.go:136 004.001: commit
I170619 20:07:52.235653 75227 sql/monotonic_insert_test.go:136 003.001: commit
I170619 20:07:52.254100 75228 sql/monotonic_insert_test.go:136 005.001: attempt 2
I170619 20:07:52.254249 75224 sql/monotonic_insert_test.go:136 004.001: attempt 2
I170619 20:07:52.255362 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:52.255591 75224 sql/monotonic_insert_test.go:136 004.001: read max val
I170619 20:07:52.259981 75227 sql/monotonic_insert_test.go:136 003.001: attempt 2
I170619 20:07:52.261225 75227 sql/monotonic_insert_test.go:136 003.001: read max val
I170619 20:07:52.325950 75224 sql/monotonic_insert_test.go:136 004.001: read max row for val=1
I170619 20:07:52.326969 75407 sql/monotonic_insert_test.go:136 008.002: attempt 1
I170619 20:07:52.328060 75407 sql/monotonic_insert_test.go:136 008.002: read max val
I170619 20:07:52.351971 75224 sql/monotonic_insert_test.go:136 004.001: insert
I170619 20:07:52.367682 75224 sql/monotonic_insert_test.go:136 004.001: commit
I170619 20:07:52.379823 75224 sql/monotonic_insert_test.go:136 004.001: done
I170619 20:07:52.380221 75441 sql/monotonic_insert_test.go:136 009.002: begin
I170619 20:07:52.457426 75229 sql/monotonic_insert_test.go:136 001.002: insert
I170619 20:07:52.462405 75225 sql/monotonic_insert_test.go:136 006.002: insert
I170619 20:07:52.471740 75227 sql/monotonic_insert_test.go:136 003.001: read max row for val=2
I170619 20:07:52.475606 75229 sql/monotonic_insert_test.go:136 001.002: commit
I170619 20:07:52.476293 75225 sql/monotonic_insert_test.go:136 006.002: commit
I170619 20:07:52.497607 75229 sql/monotonic_insert_test.go:136 001.002: attempt 2
I170619 20:07:52.498987 75229 sql/monotonic_insert_test.go:136 001.002: read max val
I170619 20:07:52.499375 75225 sql/monotonic_insert_test.go:136 006.002: attempt 2
I170619 20:07:52.500626 75225 sql/monotonic_insert_test.go:136 006.002: read max val
I170619 20:07:52.512586 75441 sql/monotonic_insert_test.go:136 009.002: attempt 1
I170619 20:07:52.514009 75441 sql/monotonic_insert_test.go:136 009.002: read max val
I170619 20:07:52.562054 75229 sql/monotonic_insert_test.go:136 001.002: read max row for val=2
I170619 20:07:52.568445 75229 sql/monotonic_insert_test.go:136 001.002: insert
I170619 20:07:52.579792 75229 sql/monotonic_insert_test.go:136 001.002: commit
I170619 20:07:52.593653 75229 sql/monotonic_insert_test.go:136 001.002: done
I170619 20:07:52.594031 75638 sql/monotonic_insert_test.go:136 010.001: begin
I170619 20:07:52.595610 75638 sql/monotonic_insert_test.go:136 010.001: attempt 1
I170619 20:07:52.596694 75638 sql/monotonic_insert_test.go:136 010.001: read max val
I170619 20:07:52.612571 75227 sql/monotonic_insert_test.go:136 003.001: insert
I170619 20:07:52.613182 75225 sql/monotonic_insert_test.go:136 006.002: read max row for val=3
I170619 20:07:52.626258 75227 sql/monotonic_insert_test.go:136 003.001: commit
I170619 20:07:52.639726 75227 sql/monotonic_insert_test.go:136 003.001: attempt 3
I170619 20:07:52.641725 75227 sql/monotonic_insert_test.go:136 003.001: read max val
I170619 20:07:52.648580 75227 sql/monotonic_insert_test.go:136 003.001: read max row for val=3
I170619 20:07:52.654298 75227 sql/monotonic_insert_test.go:136 003.001: insert
I170619 20:07:52.668982 75227 sql/monotonic_insert_test.go:136 003.001: commit
I170619 20:07:52.684534 75227 sql/monotonic_insert_test.go:136 003.001: done
I170619 20:07:52.684889 75716 sql/monotonic_insert_test.go:136 011.000: begin
I170619 20:07:52.685138 74226 storage/replica_proposal.go:397 [n2,s2,r11/2:/Table/5{0-1}] new range lease repl=(n2,s2):2 start=1497902872.662908653,0 epo=1 pro=1497902872.662935353,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497902878.221887319,0 pro=1497902869.221935019,0
I170619 20:07:52.688527 75716 sql/monotonic_insert_test.go:136 011.000: attempt 1
I170619 20:07:52.690506 75716 sql/monotonic_insert_test.go:136 011.000: read max val
I170619 20:07:52.699576 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=2
I170619 20:07:52.714833 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:52.717484 75225 sql/monotonic_insert_test.go:136 006.002: insert
I170619 20:07:52.733261 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:52.754531 75225 sql/monotonic_insert_test.go:136 006.002: commit
I170619 20:07:52.755363 75228 sql/monotonic_insert_test.go:136 005.001: attempt 3
I170619 20:07:52.756559 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:52.764600 75225 sql/monotonic_insert_test.go:136 006.002: attempt 3
I170619 20:07:52.765667 75225 sql/monotonic_insert_test.go:136 006.002: read max val
I170619 20:07:52.843084 75716 sql/monotonic_insert_test.go:136 011.000: read max row for val=4
I170619 20:07:52.854319 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=4
I170619 20:07:52.855756 75638 sql/monotonic_insert_test.go:136 010.001: read max row for val=4
I170619 20:07:52.862273 75225 sql/monotonic_insert_test.go:136 006.002: read max row for val=4
I170619 20:07:52.868270 75716 sql/monotonic_insert_test.go:136 011.000: insert
I170619 20:07:52.871071 75638 sql/monotonic_insert_test.go:136 010.001: insert
I170619 20:07:52.886775 75407 sql/monotonic_insert_test.go:136 008.002: read max row for val=4
I170619 20:07:52.895512 75225 sql/monotonic_insert_test.go:136 006.002: insert
I170619 20:07:52.895665 75716 sql/monotonic_insert_test.go:136 011.000: commit
I170619 20:07:52.895800 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:52.898085 75441 sql/monotonic_insert_test.go:136 009.002: read max row for val=4
I170619 20:07:52.899950 75407 sql/monotonic_insert_test.go:136 008.002: insert
I170619 20:07:52.908089 75638 sql/monotonic_insert_test.go:136 010.001: commit
I170619 20:07:52.927567 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:52.945140 75716 sql/monotonic_insert_test.go:136 011.000: done
I170619 20:07:52.945584 75782 sql/monotonic_insert_test.go:136 012.001: begin
I170619 20:07:52.947596 75782 sql/monotonic_insert_test.go:136 012.001: attempt 1
I170619 20:07:52.949065 75407 sql/monotonic_insert_test.go:136 008.002: commit
I170619 20:07:52.949446 75782 sql/monotonic_insert_test.go:136 012.001: read max val
I170619 20:07:52.957134 75638 sql/monotonic_insert_test.go:136 010.001: attempt 2
I170619 20:07:52.958291 75638 sql/monotonic_insert_test.go:136 010.001: read max val
I170619 20:07:52.960721 75228 sql/monotonic_insert_test.go:136 005.001: attempt 4
I170619 20:07:52.962956 75225 sql/monotonic_insert_test.go:136 006.002: commit
I170619 20:07:52.965339 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:52.968846 75638 sql/monotonic_insert_test.go:136 010.001: pq: restart transaction: HandledRetryableTxnError: ReadWithinUncertaintyIntervalError: read at time 1497902872.690916541,1 encountered previous write with future timestamp 1497902872.758972612,1 within uncertainty interval
I170619 20:07:52.969264 75407 sql/monotonic_insert_test.go:136 008.002: attempt 2
I170619 20:07:52.969386 75638 sql/monotonic_insert_test.go:136 010.001: attempt 3
I170619 20:07:52.970417 75407 sql/monotonic_insert_test.go:136 008.002: read max val
I170619 20:07:52.970562 75638 sql/monotonic_insert_test.go:136 010.001: read max val
I170619 20:07:52.977744 75225 sql/monotonic_insert_test.go:136 006.002: attempt 4
I170619 20:07:52.980315 75225 sql/monotonic_insert_test.go:136 006.002: read max val
I170619 20:07:52.981374 75407 sql/monotonic_insert_test.go:136 008.002: pq: restart transaction: HandledRetryableTxnError: ReadWithinUncertaintyIntervalError: read at time 1497902872.690916541,1 encountered previous write with future timestamp 1497902872.758972612,1 within uncertainty interval
I170619 20:07:52.981942 75407 sql/monotonic_insert_test.go:136 008.002: attempt 3
I170619 20:07:52.983270 75407 sql/monotonic_insert_test.go:136 008.002: read max val
I170619 20:07:53.075040 75441 sql/monotonic_insert_test.go:136 009.002: insert
I170619 20:07:53.088447 75638 sql/monotonic_insert_test.go:136 010.001: read max row for val=5
I170619 20:07:53.089996 75441 sql/monotonic_insert_test.go:136 009.002: commit
I170619 20:07:53.101085 75441 sql/monotonic_insert_test.go:136 009.002: attempt 2
I170619 20:07:53.115897 75441 sql/monotonic_insert_test.go:136 009.002: read max val
I170619 20:07:53.122398 75441 sql/monotonic_insert_test.go:136 009.002: pq: restart transaction: HandledRetryableTxnError: ReadWithinUncertaintyIntervalError: read at time 1497902872.923524742,1 encountered previous write with future timestamp 1497902872.973266320,1 within uncertainty interval
I170619 20:07:53.122895 75441 sql/monotonic_insert_test.go:136 009.002: attempt 3
I170619 20:07:53.123934 75441 sql/monotonic_insert_test.go:136 009.002: read max val
I170619 20:07:53.131883 75638 sql/monotonic_insert_test.go:136 010.001: insert
I170619 20:07:53.141701 75638 sql/monotonic_insert_test.go:136 010.001: commit
I170619 20:07:53.164698 75638 sql/monotonic_insert_test.go:136 010.001: done
I170619 20:07:53.165078 75986 sql/monotonic_insert_test.go:136 013.000: begin
I170619 20:07:53.166827 75986 sql/monotonic_insert_test.go:136 013.000: attempt 1
I170619 20:07:53.168170 75986 sql/monotonic_insert_test.go:136 013.000: read max val
I170619 20:07:53.182357 75782 sql/monotonic_insert_test.go:136 012.001: read max row for val=6
I170619 20:07:53.205779 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=5
I170619 20:07:53.207357 75782 sql/monotonic_insert_test.go:136 012.001: insert
I170619 20:07:53.217881 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:53.220741 75782 sql/monotonic_insert_test.go:136 012.001: commit
I170619 20:07:53.235362 75782 sql/monotonic_insert_test.go:136 012.001: done
I170619 20:07:53.235735 75996 sql/monotonic_insert_test.go:136 014.002: begin
I170619 20:07:53.236938 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:53.238047 75996 sql/monotonic_insert_test.go:136 014.002: attempt 1
I170619 20:07:53.241392 75996 sql/monotonic_insert_test.go:136 014.002: read max val
I170619 20:07:53.247356 75228 sql/monotonic_insert_test.go:136 005.001: attempt 5
I170619 20:07:53.248461 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:53.304313 75225 sql/monotonic_insert_test.go:136 006.002: read max row for val=5
I170619 20:07:53.311309 75225 sql/monotonic_insert_test.go:136 006.002: insert
I170619 20:07:53.324224 75225 sql/monotonic_insert_test.go:136 006.002: commit
I170619 20:07:53.334438 75225 sql/monotonic_insert_test.go:136 006.002: attempt 5
I170619 20:07:53.335751 75225 sql/monotonic_insert_test.go:136 006.002: read max val
I170619 20:07:53.373802 75225 sql/monotonic_insert_test.go:136 006.002: read max row for val=7
I170619 20:07:53.382782 75225 sql/monotonic_insert_test.go:136 006.002: insert
I170619 20:07:53.395337 75407 sql/monotonic_insert_test.go:136 008.002: read max row for val=7
I170619 20:07:53.396734 75225 sql/monotonic_insert_test.go:136 006.002: commit
I170619 20:07:53.404600 75407 sql/monotonic_insert_test.go:136 008.002: insert
I170619 20:07:53.411518 75225 sql/monotonic_insert_test.go:136 006.002: done
I170619 20:07:53.411853 76074 sql/monotonic_insert_test.go:136 015.000: begin
I170619 20:07:53.434081 75407 sql/monotonic_insert_test.go:136 008.002: commit
I170619 20:07:53.453808 75407 sql/monotonic_insert_test.go:136 008.002: attempt 4
I170619 20:07:53.457434 75407 sql/monotonic_insert_test.go:136 008.002: read max val
I170619 20:07:53.485942 75441 sql/monotonic_insert_test.go:136 009.002: read max row for val=8
I170619 20:07:53.491378 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=7
I170619 20:07:53.492657 75441 sql/monotonic_insert_test.go:136 009.002: insert
I170619 20:07:53.505327 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:53.507820 76074 sql/monotonic_insert_test.go:136 015.000: attempt 1
I170619 20:07:53.510011 76074 sql/monotonic_insert_test.go:136 015.000: read max val
I170619 20:07:53.516856 75441 sql/monotonic_insert_test.go:136 009.002: commit
I170619 20:07:53.529343 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:53.547220 75441 sql/monotonic_insert_test.go:136 009.002: attempt 4
I170619 20:07:53.550612 75441 sql/monotonic_insert_test.go:136 009.002: read max val
I170619 20:07:53.562465 75228 sql/monotonic_insert_test.go:136 005.001: attempt 6
I170619 20:07:53.563662 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:53.613156 75441 sql/monotonic_insert_test.go:136 009.002: read max row for val=8
I170619 20:07:53.630706 75996 sql/monotonic_insert_test.go:136 014.002: read max row for val=8
I170619 20:07:53.649469 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=8
I170619 20:07:53.651112 75407 sql/monotonic_insert_test.go:136 008.002: read max row for val=8
I170619 20:07:53.653533 76074 sql/monotonic_insert_test.go:136 015.000: read max row for val=8
I170619 20:07:53.658426 75441 sql/monotonic_insert_test.go:136 009.002: insert
I170619 20:07:53.661173 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:53.662488 75996 sql/monotonic_insert_test.go:136 014.002: insert
I170619 20:07:53.662680 76074 sql/monotonic_insert_test.go:136 015.000: insert
I170619 20:07:53.667672 75407 sql/monotonic_insert_test.go:136 008.002: insert
I170619 20:07:53.669581 75986 sql/monotonic_insert_test.go:136 013.000: read max row for val=8
I170619 20:07:53.683979 75441 sql/monotonic_insert_test.go:136 009.002: commit
I170619 20:07:53.688068 75996 sql/monotonic_insert_test.go:136 014.002: commit
I170619 20:07:53.692714 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:53.693095 76074 sql/monotonic_insert_test.go:136 015.000: commit
I170619 20:07:53.700653 75407 sql/monotonic_insert_test.go:136 008.002: commit
I170619 20:07:53.703382 75441 sql/monotonic_insert_test.go:136 009.002: attempt 5
I170619 20:07:53.704567 75441 sql/monotonic_insert_test.go:136 009.002: read max val
I170619 20:07:53.709096 75996 sql/monotonic_insert_test.go:136 014.002: attempt 2
I170619 20:07:53.710185 75996 sql/monotonic_insert_test.go:136 014.002: read max val
I170619 20:07:53.721599 76074 sql/monotonic_insert_test.go:136 015.000: done
I170619 20:07:53.721926 76257 sql/monotonic_insert_test.go:136 016.001: begin
I170619 20:07:53.725715 76257 sql/monotonic_insert_test.go:136 016.001: attempt 1
I170619 20:07:53.726875 76257 sql/monotonic_insert_test.go:136 016.001: read max val
I170619 20:07:53.727862 75228 sql/monotonic_insert_test.go:136 005.001: attempt 7
I170619 20:07:53.733070 75407 sql/monotonic_insert_test.go:136 008.002: attempt 5
I170619 20:07:53.733777 75996 sql/monotonic_insert_test.go:136 014.002: pq: restart transaction: HandledRetryableTxnError: ReadWithinUncertaintyIntervalError: read at time 1497902873.510411091,1 encountered previous write with future timestamp 1497902873.567146467,1 within uncertainty interval
I170619 20:07:53.735547 75407 sql/monotonic_insert_test.go:136 008.002: read max val
I170619 20:07:53.739179 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:53.743026 75996 sql/monotonic_insert_test.go:136 014.002: attempt 3
I170619 20:07:53.744356 75996 sql/monotonic_insert_test.go:136 014.002: read max val
W170619 20:07:53.747455 76202 storage/replica.go:2525 [n1,s1,r1/1:/{Min-System/}] context cancellation after 0.0s of attempting command RequestLease [/Min,/Min)
W170619 20:07:53.818378 76279 storage/replica.go:1923 [n1,s1,r12/1:/{Table/51-Max}] context canceled before command queue: 1 QueryTxn
I170619 20:07:53.839549 75441 sql/monotonic_insert_test.go:136 009.002: read max row for val=9
I170619 20:07:53.845844 75441 sql/monotonic_insert_test.go:136 009.002: insert
I170619 20:07:53.858742 75441 sql/monotonic_insert_test.go:136 009.002: commit
I170619 20:07:53.872806 75441 sql/monotonic_insert_test.go:136 009.002: done
I170619 20:07:53.873200 76305 sql/monotonic_insert_test.go:136 017.001: begin
I170619 20:07:53.874812 76305 sql/monotonic_insert_test.go:136 017.001: attempt 1
I170619 20:07:53.875999 76305 sql/monotonic_insert_test.go:136 017.001: read max val
I170619 20:07:53.882758 75986 sql/monotonic_insert_test.go:136 013.000: insert
I170619 20:07:53.905814 74451 storage/replica_proposal.go:397 [n3,s3,r12/3:/{Table/51-Max}] new range lease repl=(n3,s3):3 start=1497902873.890081330,0 epo=1 pro=1497902873.890092030,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1497902878.221887319,0 pro=1497902869.221935019,0
I170619 20:07:53.932891 75986 sql/monotonic_insert_test.go:136 013.000: commit
I170619 20:07:53.965583 75986 sql/monotonic_insert_test.go:136 013.000: done
I170619 20:07:53.965895 76438 sql/monotonic_insert_test.go:136 018.002: begin
I170619 20:07:53.968139 76438 sql/monotonic_insert_test.go:136 018.002: attempt 1
I170619 20:07:53.968502 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=9
I170619 20:07:53.969636 76438 sql/monotonic_insert_test.go:136 018.002: read max val
I170619 20:07:53.977428 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:53.988518 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:54.013624 75228 sql/monotonic_insert_test.go:136 005.001: attempt 8
I170619 20:07:54.014813 75228 sql/monotonic_insert_test.go:136 005.001: read max val
I170619 20:07:54.073926 75228 sql/monotonic_insert_test.go:136 005.001: read max row for val=10
I170619 20:07:54.082300 75228 sql/monotonic_insert_test.go:136 005.001: insert
I170619 20:07:54.094216 75228 sql/monotonic_insert_test.go:136 005.001: commit
I170619 20:07:54.112670 75228 sql/monotonic_insert_test.go:136 005.001: done
I170619 20:07:54.113041 76500 sql/monotonic_insert_test.go:136 019.000: begin
I170619 20:07:54.114499 76500 sql/monotonic_insert_test.go:136 019.000: attempt 1
I170619 20:07:54.115685 76500 sql/monotonic_insert_test.go:136 019.000: read max val
I170619 20:07:54.136984 76438 sql/monotonic_insert_test.go:136 018.002: read max row for val=11
I170619 20:07:54.147044 76438 sql/monotonic_insert_test.go:136 018.002: insert
I170619 20:07:54.171952 76438 sql/monotonic_insert_test.go:136 018.002: commit
I170619 20:07:54.182635 76438 sql/monotonic_insert_test.go:136 018.002: done
I170619 20:07:54.183032 76549 sql/monotonic_insert_test.go:136 020.001: begin
I170619 20:07:54.184632 76549 sql/monotonic_insert_test.go:136 020.001: attempt 1
I170619 20:07:54.185794 76549 sql/monotonic_insert_test.go:136 020.001: read max val
I170619 20:07:54.211004 75996 sql/monotonic_insert_test.go:136 014.002: read max row for val=10
I170619 20:07:54.219745 75407 sql/monotonic_insert_test.go:136 008.002: read max row for val=10
I170619 20:07:54.235096 75996 sql/monotonic_insert_test.go:136 014.002: insert
I170619 20:07:54.250200 75407 sql/monotonic_insert_test.go:136 008.002: insert
I170619 20:07:54.256528 75996 sql/monotonic_insert_test.go:136 014.002: commit
E170619 20:07:54.262273 76341 sql/distsqlrun/tablereader.go:195 [n1,TableReader=51] scan error: ReadWithinUncertaintyIntervalError: read at time 1497902873.876345835,0 encountered previous write with future timestamp 1497902874.017770775,1 within uncertainty interval
I170619 20:07:54.262477 76342 sql/distsqlrun/aggregator.go:244 [n1,Agg] accumulate error ReadWithinUncertaintyInte
Please assign, take a look and update the issue accordingly.