--- FAIL: test/TestImportPgDump/read_data_only (0.000s)
Test ended in panic.

------- Stdout: -------
I180827 20:41:54.053559 52667 storage/replica_command.go:298  [n1,s1,r23/1:/{Table/52-Max}] initiating a split of this range at key /Table/53/1/106 [r24]
I180827 20:41:54.062208 52385 storage/replica_range_lease.go:554  [replicate,n1,s1,r23/1:/Table/5{2-3/1/106}] transferring lease to s2
I180827 20:41:54.063407 52385 storage/replica_range_lease.go:617  [replicate,n1,s1,r23/1:/Table/5{2-3/1/106}] done transferring lease to s2: <nil>
I180827 20:41:54.063498 51617 storage/replica_proposal.go:210  [n2,s2,r23/3:/Table/5{2-3/1/106}] new range lease repl=(n2,s2):3 seq=3 start=1535402514.062230012,0 epo=1 pro=1535402514.062232488,0 following repl=(n1,s1):1 seq=2 start=1535402512.768597075,0 exp=1535402521.769064687,0 pro=1535402512.769088099,0
I180827 20:41:54.077824 52355 storage/replica_command.go:298  [n1,s1,r24/1:/{Table/53/1/1…-Max}] initiating a split of this range at key /Table/53/2/"\x15\x8f\xe8\u007f\\\xf3\xdf\xf0nP\xdb\xd3\xe8\x1b\"B1K\xa8l+\x96/l\v\x9e\x0e\x91\xa0D\x96\xc0J\xf1\xa1͠\xd2̃\x05\xe3\xe2?ET蛂\x00\xe5\xb0\x1a\x8e\x13Zu\xfd\xf2\x81w^\xb7\xbdH\xb8\xe4\a\x9c\xfd\x99{\xb4\"\xe5Q\x9c\x17\x85\x97\xf7Ëb\x0f\xff\xb0-vmO\xe1\xfb\xc3\xf3\xab0\xa0\x05u\x1c\xb0{B\xeamp\xbd\x8f\x99?\x87\x0f\xb2e\xe3ؿ2LN\x03\x17\xa7\x9f\xd3\x0f\x15$\x02I\xd2\xd7\x04R\x193\x9d\xddX\u007f\x01A\xcc\xde`Pm:\xdbe\xfd\xa6\a\xf8i\x88\xa7\xee\xacӸ\xbf2\x84y\xcd\n\xe6]L)\xca\xd9`x\xb4\x1b|\xe8\x13\x82\x1a(/* 3`J\xe1ٰ\xe6AdN!-\xd9"/"ॹॹ;,✅\nπ<\t\nπ\tॹπ✅a\n,\nᐿ�\nॹ✅�ॹ�\"✅ॹ\\<\"\n;a\\\n,✅π\n<\n<\nॹπᐿ�ᐿ;,�\tᐿ\nᐿaᐿ,\nπ�\t\\<ॹ\\π;π�π\"<;\"�\\<�,<�\\a�<\nॹaᐿaॹ�\\ᐿπ,✅ᐿ\"<✅✅a\t�ॹ\t<π;�ॹ\\ᐿ;✅\r\\,;\\ᐿॹ\nॹᐿππ\nᐿ\nᐿaπ\\\nπ\r\"✅�π\nπ\rॹπ\"ॹ✅a\ra�✅\nπ;ॹ✅\n;ॹ,�\nπ\rπᐿa\\\\ᐿ,π<ᐿ✅\n�,\r\nᐿ✅\n<�ᐿ\"\"✅,,\"\n<\n✅\rπa�π\n<\\ॹ\nॹ�;\ra��✅ᐿ\n,\t�;,π<\r��\r\\�\n✅\r✅�;\\\n\n,\nॹ✅π\n,\n✅\t,�<\nπ\t;aπ\n<a<\n\tπ\r\"\\✅\n\n\n<ᐿπaπ\\�\"<✅\\a,✅\n✅\n<\"\"\n\n\r\rᐿ�\\\tᐿᐿ;\n\rᐿa\\π<\n\\\n\n\";\r\r\raπ\"\r�ॹa\r�\"\n\"✅ππ✅�\t�ᐿ\tᐿ\\\r�ᐿ<\\\nᐿπ✅\tॹ<π\ta\"✅\t,ॹa✅ᐿ;\\\r✅\\,ॹ\"a\n<ॹ\\\n<\"π\\\\ᐿ\n✅\nᐿ\n,\n\r\t\n\r\n<aᐿ;ᐿ;ᐿ\r;✅a<a,,<\t\n\\ππ\\\"✅\n\\a\n\tπa<\r<π\n✅\\π<ॹ,\t;<aaaπॹᐿaॹaॹ�,\"\t,ॹ;\\<✅a\nᐿ\"\nπ\\aᐿ�ᐿ<ॹ;\\<ᐿ\nᐿ\n\"aᐿᐿπ,\"\r✅ॹ\n,<\r<\n<<,ᐿᐿa,\rᐿ<;π\\�,\"\rπ�\nππ�,✅;�\ra<;\r�ᐿ\tπ;\"πᐿ\\�a\"ᐿ\\;\\ॹ\";ॹ;;✅\tॹ\r\n<\t\n\t<aॹ\tᐿ\n\"ॹᐿ\t✅✅�ॹ;;<�\t,\n\r\n\n\ta\"\\<\rπᐿa\t<\na;\t\"\nπ<πॹ\r\n<\n✅ᐿॹ✅�<,;✅\"\n<�π<✅<<✅\\;\n\"\rᐿ\t�\n\n\r\t,ॹ�\"\rᐿᐿᐿ,\"π\nπ\",a\"\"<�\t\\πॹ\n\taॹᐿ\tπॹ,\n✅\rπa\r<<,\n\nᐿ;\t\\<\tᐿ\n\n�\"ॹ<\n\r\nᐿ\n�\n\nπᐿ;\nॹ\n\"π<\"\r\r\n\r\\ᐿ;;πॹ;�\r✅�,✅\r\r�,a;ᐿ\\ॹ\"\t\r✅;\t<,π,�\t\"πaᐿ��\\ॹ\"\n\tᐿ\t,ॹ✅�ᐿ✅\tᐿ,ॹ✅;;�\r\n✅ᐿ�\nπa;\\,✅ॹ<ᐿ\nπ\n\"\n;a\t\\π\n<\r\r\rπ\"\n\nᐿ<<ᐿ\"\n,\n\"ॹπaᐿπ��\r\n�ᐿॹ,\na\n\rॹ<�ॹ\"\n\t\r\n,π\n�,<ॹ,<\n<�✅ᐿ\r✅a✅<\r;,�a�\\\nॹ<\\<✅ॹ\"\nॹ\r�\ta;\"\\ᐿ\n\n✅\"\r;✅\t,a✅✅<\"ᐿ\t�π\\✅✅�<;\"✅π✅ॹ,\nπ\n��<,\ta\r�✅ᐿ\nॹπ\nᐿॹ✅;\nॹ\t\r\\\nᐿ�ᐿ\n\tᐿ,\r\\;<<a,\"π,\tᐿ\nπ<a\"ॹ\\aa\r\r\"\";\tᐿ,ॹa\nॹ\nπ"/PrefixEnd [r25]
I180827 20:41:54.090278 52643 storage/replica_range_lease.go:554  [n1,s1,r24/1:/Table/53/{1/106-2/"\x15…}] transferring lease to s3
I180827 20:41:54.091255 52643 storage/replica_range_lease.go:617  [n1,s1,r24/1:/Table/53/{1/106-2/"\x15…}] done transferring lease to s3: <nil>
I180827 20:41:54.092073 51863 storage/replica_proposal.go:210  [n3,s3,r24/2:/Table/53/{1/106-2/"\x15…}] new range lease repl=(n3,s3):2 seq=3 start=1535402514.090298269,0 epo=1 pro=1535402514.090300825,0 following repl=(n1,s1):1 seq=2 start=1535402512.768597075,0 exp=1535402521.769064687,0 pro=1535402512.769088099,0
I180827 20:41:54.094854 52702 storage/replica_command.go:298  [n1,s1,r25/1:/{Table/53/2/"…-Max}] initiating a split of this range at key /Table/53/2/"\xc0\t\x13\xe0*c\xe4\xcfS-\x9b,\xe2\x82\xfa\xd8Z\xf6\x99\x81\\\x18ŕ\xea\x80Db\xa7\x94\xf7Q#\x13\\\xc7(\xc4=\xaaZ\xa2Hա}\xdeI\x06\x840I\xa9\x95\xcbи\r#iH\x97F~\x10\xe4<\xb2\xefFb\xac\xee\xf90H5\xd7D\xe4:\xf0Ae\xe3\xd1<\xd1\xf7\xb9\xad\xea\xd9\xe0r\xbc\xa6\xae\x92\xfb\xb5,\xc2\U0010f26eD\xe0 \xc5\x06\xfa\x04{\xf7\xe8\xbfZQ\xa3\x05M\xbb\xa8\xbe\xf4\xc4\x0f\xe9|s{|\x8fr\xad\xdaWĢ\x9e\xdf\x17\x9f\x02\xf3п\xd3\xea\xfd\x8ew3\xb8@7ꇘN%\n\xe0@jq\xb3\xb0&y\xe3K0ȼ_s\x1e\x15\x98\xe7\xbf6\xeb\xef}$dd/\xaa\xf1\xcb.U\x8f\xd4r"/"<a✅ᐿ<\n\n\nॹ\",\n\"πॹᐿ,\rᐿ\nॹ�ॹ<\naᐿᐿ,\"ॹ\"\\✅\n�✅<\n\r<\\<\"\\π;<✅,;✅ॹa\r✅ᐿ;ᐿ\r\\�\\�,ᐿ\r\n,�✅,\t;\\\"π,;ᐿa\nॹ✅\n;ॹ<\\\n;<ᐿॹ\n\r<\n�\\\",ॹ✅,\n\"✅ᐿ\raa\n\n\t;�π<,\",ᐿ<ᐿ\\ᐿ✅;\t<π\"\"ॹ<\t\n,,π\"\t�✅\r;;ॹ,ᐿ\tॹ✅ॹ,\nᐿ\n\\;\n\nπa<✅aπ\t;✅\r;�✅;a\t\n✅ππ\t\rॹ\n\\<✅✅<\r✅\t\r✅<π\n;\n\"\"��ॹ\r,ᐿ\naॹᐿπ\\π\n\n,�\t<�a\nπ\\✅,πॹ\",πᐿa,ᐿᐿa\r<\ta\t\nॹ\n\r✅\r;πa✅�\t�π\",πa\n<✅\"a\t�\r<ᐿa,\naᐿॹᐿ\rॹᐿa�\"\\a✅\"\"✅✅ᐿ\t\"ॹ<\n\"\nπ✅✅\n\\ॹ\t;ᐿ\"a,ॹ\"aॹᐿᐿ\n,\\\nॹॹ,;ॹ;\\\n\n\t\n,\naॹπ\r\"\n\t✅ॹ\r\tᐿ✅;\r\ta�ᐿ\t\t\nπᐿ<ॹ\tᐿ\na\nᐿ\tππ<<π\t✅;\r\"ॹ\n\na�<ᐿ\r\nᐿᐿ\";a<\rॹ\\πॹ\tᐿ\n\nᐿπ;\t;;✅ᐿ✅✅<�ॹ;\tᐿ,,\t,π✅\nᐿॹ;\r\"ᐿa,ᐿᐿᐿa\nॹ<aॹ\r,;π<<\nπa�\n\\\r,ॹπ�\n\"ᐿππ\n✅ॹπ\ra,πॹ\n\t<;πᐿᐿ✅ॹ\t�a✅\r�\"a,π��,ॹa\n\\\rॹ\nॹ\"π\"π\ta�<π�\r;a,a\r<πᐿ\na<\r\t\nॹ\\\\\n\\<�\\�aπa;\r\\,,\nॹ\"✅;\"\n✅ᐿ✅a\n<ππ\tπ<a\t�\\<\"✅\\\nᐿ;\r\t✅�✅π\r\r\r\n\",ᐿ;ॹ\nᐿ\r\"\naa\"\n\t<,✅<a\\\n\"ॹᐿ\n\\\t\t\r\"ॹ<,,π�\"ॹ<ॹ,\\ᐿ<\\π\"\\<ᐿ\n\rॹ\na\t\nπ;\\π\\✅\r,\r�\",,;;,<\n\t\"\\\r\r\"ॹ✅ॹ�\n�✅�\n�\\\n\n\rᐿॹ\tπa<;;\n\n�a\n\\ॹॹ\t;\n<\t\\<ॹॹ�✅π\t\"<\n\tᐿπᐿ\"\"�;\t;ॹ<π<✅\nππ<\"\rॹ�πᐿ�\rπ,<,<ᐿ<;;�,\t<<ᐿ\t<\tॹ,π,<\\a\t;\n\r�a✅\r\r\t\nᐿᐿ✅\r;\n;�;\r✅\n,;✅ᐿ,\\\n<,<\\\t\n;<\\aᐿ\r,\n;\\\r�\rॹ\\\t\";\t�;\n,\ta✅\r\t\r,\n\\\t\nᐿ✅\\\"\naᐿ\\\\\";\r<�✅;aॹ\t\t\\\t\tᐿ�\r,\"\n\"\taᐿ\na\rππॹ\nπᐿ\rॹ\nॹ\tπ,π\r<\"\n,�\na;�\\✅,<\"\"�\nππ\t\nπaॹaa✅\\;\\a\r\rᐿ,\\�;\\ᐿᐿ<a\"\r;π\"\\ᐿπ\tπॹ;\\a\ra;\t\n\\�\r<\t<ॹ\r✅\na\t\t<\n\n✅π\nᐿ✅\\<,\nπ\rᐿ✅a\"\r\"\n✅ॹ\\�\r\n\\�\nॹ\\<\\<\n\n\n"/PrefixEnd [r26]
I180827 20:41:54.112580 52726 storage/replica_range_lease.go:554  [n1,s1,r25/1:/Table/53/2/"\x{15\x8…-c0\t\…}] transferring lease to s3
I180827 20:41:54.113319 52726 storage/replica_range_lease.go:617  [n1,s1,r25/1:/Table/53/2/"\x{15\x8…-c0\t\…}] done transferring lease to s3: <nil>
I180827 20:41:54.113657 51850 storage/replica_proposal.go:210  [n3,s3,r25/2:/Table/53/2/"\x{15\x8…-c0\t\…}] new range lease repl=(n3,s3):2 seq=3 start=1535402514.112607829,0 epo=1 pro=1535402514.112610518,0 following repl=(n1,s1):1 seq=2 start=1535402512.768597075,0 exp=1535402521.769064687,0 pro=1535402512.769088099,0
I180827 20:41:54.117098 52757 storage/replica_command.go:298  [n1,s1,r26/1:/{Table/53/2/"…-Max}] initiating a split of this range at key /Table/53/3/";π,\\✅✅ᐿπ✅,�a\r<\nπᐿॹ;π\\,✅\nᐿॹ✅�,\r�\r\r\r,;\r;ᐿ,\n\nᐿaπ\r,,✅\na,a\\<✅\"✅\\,,a\"π\r\n�✅π\"ॹπ;\nπ;<,<\n;<\n\tॹ\rπ\r,a\\\t�\n\r\\ᐿ<\t,\n\\ᐿa\t\t\n\nπ\t\\\n\\πa;π\r\rᐿ\",a<\"\n�\r\ta\r\t�\r\t✅\t;ᐿᐿ��\nᐿᐿ\\,ᐿᐿ\na\"ᐿ\"\"aa\n;✅π\nॹ\\\"\"�✅ॹॹ\\\nॹ\t\nॹ✅,\n\"πᐿ\n\n;<<;\r\tᐿ�,,\\\n\n\n\n\nπ�;\n;,\"✅\r;a\n\\;aa\n\n\n;\n\n<<ॹ�\nπa�πॹaॹ\r\n;✅✅,;ᐿ\n;π\"\\πᐿ\n\"\n\\a\\aπ✅ᐿ\n<\",\tॹ\r<;\";\nππ\"�\n\n\t,π\\\\<\\\t;ॹπ\\,;�✅ॹ,\r<\n✅�;ᐿ\",;✅\n\nॹॹ\r\n✅\n<<\n\"\",a\t\r\r,ॹ\t�;�,π\\\t,;\\\"✅\t\n\n\nᐿ\n<\\\rᐿ,;�\nπ\r\\<ᐿᐿ\n<✅ᐿaॹ�✅\n\t,π\"\r<<\n\nπ\tπ✅\n<\\πॹaᐿ\t;�ॹॹ,\"\n\\a\n,\"πॹ,\r,ॹॹ\\\";�\n\\π✅\n\"ππ\n✅�πॹ,\r✅\n;π;ᐿ\"\nᐿ✅\rॹ;;\n\"ॹ\"�\"a\n\rπ\n<\n\t\"aπ\t;\\\n\";\"π,\ta\t\n\nᐿ<,;�<ᐿ\"\\ᐿᐿa,\n;;ॹॹ\tॹπa�ᐿ\ra,π<✅\tᐿᐿ\n,✅\ra�\"\r\r\",;π�<;\n<;ᐿ\"�;ᐿ;�;✅\t\\<\\<;πa✅\rॹ\\\\\\ᐿ\n;\r\t\n\\\r\"✅\n\tπ✅\"\"<\r\rπ\r<,\n,\\✅ᐿᐿ�\t�,ππ;ᐿ\t�\"\\ππ\"ॹ,πa<\n\n<��\rॹॹ\t,\r\"ॹ✅✅\n\n;\\ॹ;π<\"�\t�<\"ᐿॹॹ;\n<\n\r\na\t�ॹᐿa\n,\"\t\r\"\n,\r<,\"\tᐿ\\\n<,;<\"\t\n\nᐿ,ᐿ\tπ✅\n,\r,\n\t<,�\\;<\\a\nπ\t,\t�ॹ\t\n�a✅\n✅\nॹ\";\r\t✅<\tᐿ\n\tᐿॹ✅\"\r\rॹ✅π\n\n,\t\\\t\\;\"a\t,ॹॹ\"aॹ\n,\n✅�\t\nॹᐿ\n\r✅<πॹ\n✅\tॹ\"ॹ\"�\r\\;\\✅;ॹπ;\n\nᐿ<\r<\"ॹ\n,\n;π\nॹ\ta✅\n�;ᐿ\"a�✅π\r✅ॹ,\n\n\",✅\nᐿ\n<�\r\nπᐿ\"πॹᐿ\r�\n<,✅a\\ॹ\r✅<;πᐿ✅ॹ<\"<✅\"π,\\\rπ\\<\"<\"π\n✅<;\\�\tॹ\n\n\r<\n\rᐿ\nᐿaॹaॹ\\\r<<\n\r\n�\ta,\nॹॹᐿ\n,π✅<;\\\nπॹπᐿॹ<;\"a\r<;\t\t<,;�π\n<✅ॹॹ\tᐿ\rᐿaaaॹ\t\\,ᐿ✅\n\\ॹ<\"π\t\r\"\tᐿ\n\ta\t,<ππ;\n\\\r�\n,\n\n\\ᐿa\nॹᐿa\n\t\n\t\n✅\"ᐿ\"\r\n\n\"�\r\n\n<<π\ra✅\\<ᐿ�\n\n✅�a✅�"/105 [r27]
I180827 20:41:54.137397 52716 storage/store_snapshot.go:615  [raftsnapshot,n3,s3,r25/2:/Table/53/2/"\x{15\x8…-c0\t\…}] sending Raft snapshot 547ab8d0 at applied index 21
I180827 20:41:54.140430 52716 storage/store_snapshot.go:657  [raftsnapshot,n3,s3,r25/2:/Table/53/2/"\x{15\x8…-c0\t\…}] streamed snapshot to (n2,s2):3: kv pairs: 14, log entries: 2, rate-limit: 8.0 MiB/sec, 22ms
I180827 20:41:54.140860 52705 storage/replica_raftstorage.go:784  [n2,s2,r25/3:/Table/53/2/"\x{15\x8…-c0\t\…}] applying Raft snapshot at index 21 (id=547ab8d0, encoded size=31270, 1 rocksdb batches, 2 log entries)
I180827 20:41:54.162696 52705 storage/replica_raftstorage.go:790  [n2,s2,r25/3:/Table/53/2/"\x{15\x8…-c0\t\…}] applied Raft snapshot in 22ms [clear=0ms batch=0ms entries=21ms commit=0ms]
I180827 20:41:54.166103 52791 storage/replica_range_lease.go:554  [n1,s1,r26/1:/Table/53/{2/"\xc0…-3/";π,…}] transferring lease to s3
I180827 20:41:54.167118 51903 storage/replica_proposal.go:210  [n3,s3,r26/2:/Table/53/{2/"\xc0…-3/";π,…}] new range lease repl=(n3,s3):2 seq=3 start=1535402514.166156675,0 epo=1 pro=1535402514.166159831,0 following repl=(n1,s1):1 seq=2 start=1535402512.768597075,0 exp=1535402521.769064687,0 pro=1535402512.769088099,0
I180827 20:41:54.167216 52791 storage/replica_range_lease.go:617  [n1,s1,r26/1:/Table/53/{2/"\xc0…-3/";π,…}] done transferring lease to s3: <nil>
I180827 20:41:54.172711 52589 storage/replica_command.go:298  [n1,s1,r27/1:/{Table/53/3/"…-Max}] initiating a split of this range at key /Table/54 [r28]
I180827 20:41:54.182740 52807 storage/replica_range_lease.go:554  [n1,s1,r27/1:/Table/5{3/3/";π…-4}] transferring lease to s2
I180827 20:41:54.183947 52807 storage/replica_range_lease.go:617  [n1,s1,r27/1:/Table/5{3/3/";π…-4}] done transferring lease to s2: <nil>
I180827 20:41:54.184954 51646 storage/replica_proposal.go:210  [n2,s2,r27/3:/Table/5{3/3/";π…-4}] new range lease repl=(n2,s2):3 seq=3 start=1535402514.182761052,0 epo=1 pro=1535402514.182764040,0 following repl=(n1,s1):1 seq=2 start=1535402512.768597075,0 exp=1535402521.769064687,0 pro=1535402512.769088099,0
--- FAIL: test/TestImportPgDump (0.000s)
Test ended in panic.

------- Stdout: -------
W180827 20:41:52.746991 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:52.757923 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:52.758132 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:52.758156 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:52.761168 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:52.761191 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:52.761204 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180827 20:41:52.767725 50862 server/node.go:373  [n?] **** cluster d5e53e69-a109-4eb6-91bf-29e74ae744ba has been created
I180827 20:41:52.767752 50862 server/server.go:1401  [n?] **** add additional nodes by specifying --join=127.0.0.1:41477
I180827 20:41:52.767936 50862 gossip/gossip.go:382  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:41477" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402512767856449 
I180827 20:41:52.770338 50862 storage/store.go:1541  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180827 20:41:52.770546 50862 server/node.go:476  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180827 20:41:52.770626 50862 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180827 20:41:52.770721 50862 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180827 20:41:52.770760 50862 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:52.770788 50862 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180827 20:41:52.771023 50862 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:52.771066 50862 server/server.go:1807  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:52.771159 50862 server/server.go:1538  [n1] starting https server at 127.0.0.1:42563 (use: 127.0.0.1:42563)
I180827 20:41:52.771188 50862 server/server.go:1540  [n1] starting grpc/postgres server at 127.0.0.1:41477
I180827 20:41:52.771209 50862 server/server.go:1541  [n1] advertising CockroachDB node at 127.0.0.1:41477
I180827 20:41:52.775258 51089 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:52.776337 50925 storage/replica_command.go:298  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180827 20:41:52.788832 51094 storage/replica_command.go:298  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180827 20:41:52.790188 51128 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=ec083bbe key=/Table/SystemConfigSpan/Start rw=true pri=0.01126188 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535402512.772758792,0 orig=1535402512.772758792,0 max=1535402512.772758792,0 wto=false rop=false seq=6
I180827 20:41:52.790695 51118 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180827 20:41:52.795125 51100 storage/replica_command.go:298  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180827 20:41:52.800783 51143 storage/replica_command.go:298  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180827 20:41:52.807906 51165 storage/replica_command.go:298  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180827 20:41:52.811784 51141 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180827 20:41:52.818164 50799 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180827 20:41:52.821094 51188 storage/replica_command.go:298  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180827 20:41:52.830709 51176 storage/replica_command.go:298  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180827 20:41:52.839374 51187 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:045a1c98-219f-445b-bd6b-d481f04d6b0d User:root}
I180827 20:41:52.849534 51154 storage/replica_command.go:298  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180827 20:41:52.855898 51218 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180827 20:41:52.861462 51240 storage/replica_command.go:298  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180827 20:41:52.868342 51268 storage/replica_command.go:298  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180827 20:41:52.872706 51256 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180827 20:41:52.874819 51264 storage/replica_command.go:298  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180827 20:41:52.876403 50862 server/server.go:1594  [n1] done ensuring all necessary migrations have run
I180827 20:41:52.876433 50862 server/server.go:1597  [n1] serving sql connections
I180827 20:41:52.879108 51233 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180827 20:41:52.879639 51235 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:41477} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402512767856449 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402512767856449 LastUp:1535402512767856449}
I180827 20:41:52.880318 51302 storage/replica_command.go:298  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180827 20:41:52.927701 50819 storage/replica_command.go:298  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180827 20:41:52.940165 51323 storage/replica_command.go:298  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180827 20:41:52.948539 51355 storage/replica_command.go:298  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180827 20:41:52.953658 51380 storage/replica_command.go:298  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180827 20:41:52.961237 51137 storage/replica_command.go:298  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180827 20:41:52.966548 50832 storage/replica_command.go:298  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180827 20:41:52.977113 51362 storage/replica_command.go:298  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180827 20:41:53.041315 51440 storage/replica_command.go:298  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180827 20:41:53.047478 51414 storage/replica_command.go:298  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
W180827 20:41:53.081214 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:53.089127 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:53.089322 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.089338 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.102793 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:53.102863 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:53.102878 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
W180827 20:41:53.102953 50862 gossip/gossip.go:1371  [n?] no incoming or outgoing connections
I180827 20:41:53.103001 50862 server/server.go:1403  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180827 20:41:53.115344 51458 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41477
I180827 20:41:53.125579 51530 gossip/server.go:217  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36113}
I180827 20:41:53.127987 50862 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I180827 20:41:53.128034 50862 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:53.128397 51575 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.134920 51574 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.135628 50862 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.136461 50862 server/node.go:428  [n?] new node allocated ID 2
I180827 20:41:53.136541 50862 gossip/gossip.go:382  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:36113" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402513136479434 
I180827 20:41:53.136591 50862 storage/stores.go:242  [n2] read 0 node addresses from persistent storage
I180827 20:41:53.136624 50862 storage/stores.go:261  [n2] wrote 1 node addresses to persistent storage
I180827 20:41:53.137485 51552 storage/stores.go:261  [n1] wrote 1 node addresses to persistent storage
I180827 20:41:53.139442 50862 server/node.go:672  [n2] bootstrapped store [n2,s2]
I180827 20:41:53.139577 50862 server/node.go:546  [n2] node=2: started with [] engine(s) and attributes []
I180827 20:41:53.140140 50862 server/status/recorder.go:652  [n2] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.140166 50862 server/server.go:1807  [n2] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:53.140233 50862 server/server.go:1538  [n2] starting https server at 127.0.0.1:39947 (use: 127.0.0.1:39947)
I180827 20:41:53.140246 50862 server/server.go:1540  [n2] starting grpc/postgres server at 127.0.0.1:36113
I180827 20:41:53.140256 50862 server/server.go:1541  [n2] advertising CockroachDB node at 127.0.0.1:36113
I180827 20:41:53.140624 51685 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.153945 50862 server/server.go:1594  [n2] done ensuring all necessary migrations have run
I180827 20:41:53.153974 50862 server/server.go:1597  [n2] serving sql connections
W180827 20:41:53.165268 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:53.185802 51467 server/server_update.go:67  [n2] no need to upgrade, cluster already at the newest version
I180827 20:41:53.186848 51469 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:36113} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402513136479434 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402513136479434 LastUp:1535402513136479434}
I180827 20:41:53.189622 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:53.189776 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.189808 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.207782 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:53.207807 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:53.207815 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
W180827 20:41:53.207911 50862 gossip/gossip.go:1371  [n?] no incoming or outgoing connections
I180827 20:41:53.207947 50862 server/server.go:1403  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180827 20:41:53.211471 51475 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n2 established
I180827 20:41:53.223653 51740 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41477
I180827 20:41:53.223954 51816 gossip/server.go:217  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46463}
I180827 20:41:53.224401 50862 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I180827 20:41:53.224432 50862 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:53.224690 51837 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.225445 51836 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.226030 50862 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.226699 50862 server/node.go:428  [n?] new node allocated ID 3
I180827 20:41:53.226763 50862 gossip/gossip.go:382  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:46463" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402513226706701 
I180827 20:41:53.226805 50862 storage/stores.go:242  [n3] read 0 node addresses from persistent storage
I180827 20:41:53.226851 50862 storage/stores.go:261  [n3] wrote 2 node addresses to persistent storage
I180827 20:41:53.227563 51809 storage/stores.go:261  [n1] wrote 2 node addresses to persistent storage
I180827 20:41:53.227869 51810 storage/stores.go:261  [n2] wrote 2 node addresses to persistent storage
I180827 20:41:53.228504 50862 server/node.go:672  [n3] bootstrapped store [n3,s3]
I180827 20:41:53.229044 50862 server/node.go:546  [n3] node=3: started with [] engine(s) and attributes []
I180827 20:41:53.229696 50862 server/status/recorder.go:652  [n3] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.229749 50862 server/server.go:1807  [n3] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:53.235251 50862 server/server.go:1538  [n3] starting https server at 127.0.0.1:43307 (use: 127.0.0.1:43307)
I180827 20:41:53.235271 50862 server/server.go:1540  [n3] starting grpc/postgres server at 127.0.0.1:46463
I180827 20:41:53.235283 50862 server/server.go:1541  [n3] advertising CockroachDB node at 127.0.0.1:46463
I180827 20:41:53.240284 50862 server/server.go:1594  [n3] done ensuring all necessary migrations have run
I180827 20:41:53.240307 50862 server/server.go:1597  [n3] serving sql connections
I180827 20:41:53.243124 51945 server/status/recorder.go:652  [n3,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.248117 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r20/1:/Table/{23-50}] sending preemptive snapshot 59e1afc9 at applied index 16
I180827 20:41:53.249136 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.251012 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 6, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.251369 51983 storage/replica_raftstorage.go:784  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 16 (id=59e1afc9, encoded size=2241, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.254056 51839 server/server_update.go:67  [n3] no need to upgrade, cluster already at the newest version
I180827 20:41:53.255122 51841 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:46463} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402513226706701 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402513226706701 LastUp:1535402513226706701}
I180827 20:41:53.256061 51983 storage/replica_raftstorage.go:790  [n2,s2,r20/?:/Table/{23-50}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180827 20:41:53.256605 50930 storage/replica_command.go:812  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.259565 50930 storage/replica.go:3743  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.261627 51625 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180827 20:41:53.264544 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.286630 50930 rpc/nodedialer/nodedialer.go:92  [replicate,n1,s1,r21/1:/Table/5{0-1}] connection to n3 established
I180827 20:41:53.287245 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.287799 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r21/1:/Table/5{0-1}] sending preemptive snapshot de08568a at applied index 18
I180827 20:41:53.288157 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.288623 51959 storage/replica_raftstorage.go:784  [n3,s3,r21/?:{-}] applying preemptive snapshot at index 18 (id=de08568a, encoded size=2646, 1 rocksdb batches, 8 log entries)
I180827 20:41:53.289814 51959 storage/replica_raftstorage.go:790  [n3,s3,r21/?:/Table/5{0-1}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180827 20:41:53.290329 50930 storage/replica_command.go:812  [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.293678 50930 storage/replica.go:3743  [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.294953 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r22/1:/{Table/51-Max}] sending preemptive snapshot a84e7278 at applied index 12
I180827 20:41:53.295229 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.295441 51883 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180827 20:41:53.295585 51953 storage/replica_raftstorage.go:784  [n3,s3,r22/?:{-}] applying preemptive snapshot at index 12 (id=a84e7278, encoded size=386, 1 rocksdb batches, 2 log entries)
I180827 20:41:53.295717 51953 storage/replica_raftstorage.go:790  [n3,s3,r22/?:/{Table/51-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.295955 50930 storage/replica_command.go:812  [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, next=2, gen=0]
I180827 20:41:53.298097 50930 storage/replica.go:3743  [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.301122 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r8/1:/Table/1{1-2}] sending preemptive snapshot 201bdccc at applied index 18
I180827 20:41:53.301565 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.306578 52088 storage/replica_raftstorage.go:784  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 18 (id=201bdccc, encoded size=4352, 1 rocksdb batches, 8 log entries)
I180827 20:41:53.306868 52088 storage/replica_raftstorage.go:790  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.307601 50930 storage/replica_command.go:812  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.311873 50930 storage/replica.go:3743  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.314134 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r17/1:/Table/2{0-1}] sending preemptive snapshot 53116eb2 at applied index 16
I180827 20:41:53.314317 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.314683 52103 storage/replica_raftstorage.go:784  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 16 (id=53116eb2, encoded size=2105, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.314887 52103 storage/replica_raftstorage.go:790  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.315401 50930 storage/replica_command.go:812  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.318398 50930 storage/replica.go:3743  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.319436 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r16/1:/Table/{19-20}] sending preemptive snapshot e0be8540 at applied index 16
I180827 20:41:53.319691 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.320127 52072 storage/replica_raftstorage.go:784  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 16 (id=e0be8540, encoded size=2109, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.320339 52072 storage/replica_raftstorage.go:790  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.320816 50930 storage/replica_command.go:812  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.323849 50930 storage/replica.go:3743  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.326208 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r15/1:/Table/1{8-9}] sending preemptive snapshot d259ae5c at applied index 16
I180827 20:41:53.326404 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.326731 52116 storage/replica_raftstorage.go:784  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 16 (id=d259ae5c, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.326923 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.326953 52116 storage/replica_raftstorage.go:790  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.334514 50930 storage/replica_command.go:812  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.337656 50930 storage/replica.go:3743  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.338767 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r14/1:/Table/1{7-8}] sending preemptive snapshot 9d0058d5 at applied index 16
I180827 20:41:53.339034 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.339612 52090 storage/replica_raftstorage.go:784  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 16 (id=9d0058d5, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.339831 52090 storage/replica_raftstorage.go:790  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.340173 50930 storage/replica_command.go:812  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.343121 50930 storage/replica.go:3743  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.345432 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r9/1:/Table/1{2-3}] sending preemptive snapshot 0eea2d20 at applied index 26
I180827 20:41:53.345859 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 53, log entries: 16, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.347137 52066 storage/replica_raftstorage.go:784  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 26 (id=0eea2d20, encoded size=15139, 1 rocksdb batches, 16 log entries)
I180827 20:41:53.347467 52066 storage/replica_raftstorage.go:790  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.348208 50930 storage/replica_command.go:812  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.352166 50930 storage/replica.go:3743  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.353188 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] sending preemptive snapshot 0cdee511 at applied index 39
I180827 20:41:53.353765 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 36, log entries: 29, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.354286 51723 storage/replica_raftstorage.go:784  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 39 (id=0cdee511, encoded size=98384, 1 rocksdb batches, 29 log entries)
I180827 20:41:53.354994 51723 storage/replica_raftstorage.go:790  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.355529 50930 storage/replica_command.go:812  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.358523 50930 storage/replica.go:3743  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.360250 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] sending preemptive snapshot 965d58b1 at applied index 19
I180827 20:41:53.360436 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.360789 52150 storage/replica_raftstorage.go:784  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 19 (id=965d58b1, encoded size=4003, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.361043 52150 storage/replica_raftstorage.go:790  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.361522 50930 storage/replica_command.go:812  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.364392 50930 storage/replica.go:3743  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.366422 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r12/1:/Table/1{5-6}] sending preemptive snapshot 811af376 at applied index 16
I180827 20:41:53.366638 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.367089 52137 storage/replica_raftstorage.go:784  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 16 (id=811af376, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.367359 52137 storage/replica_raftstorage.go:790  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.368127 50930 storage/replica_command.go:812  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.371691 50930 storage/replica.go:3743  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.374563 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r19/1:/Table/2{2-3}] sending preemptive snapshot 9cd02555 at applied index 16
I180827 20:41:53.374760 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.375252 52080 storage/replica_raftstorage.go:784  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 16 (id=9cd02555, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.375582 52080 storage/replica_raftstorage.go:790  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.375950 50930 storage/replica_command.go:812  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.381819 50930 storage/replica.go:3743  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.386461 52091 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n3 established
I180827 20:41:53.386637 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r10/1:/Table/1{3-4}] sending preemptive snapshot a16f4b15 at applied index 64
I180827 20:41:53.388005 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 204, log entries: 54, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.388536 52181 storage/replica_raftstorage.go:784  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 64 (id=a16f4b15, encoded size=62836, 1 rocksdb batches, 54 log entries)
I180827 20:41:53.389154 52181 storage/replica_raftstorage.go:790  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.389513 50930 storage/replica_command.go:812  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.392649 50930 storage/replica.go:3743  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.394122 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] sending preemptive snapshot 69adabc1 at applied index 23
I180827 20:41:53.394365 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.394729 52213 storage/replica_raftstorage.go:784  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 23 (id=69adabc1, encoded size=6277, 1 rocksdb batches, 13 log entries)
I180827 20:41:53.394981 52213 storage/replica_raftstorage.go:790  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.395465 50930 storage/replica_command.go:812  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.398757 50930 storage/replica.go:3743  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.399709 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r18/1:/Table/2{1-2}] sending preemptive snapshot e9df2a4a at applied index 16
I180827 20:41:53.400036 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.400391 52185 storage/replica_raftstorage.go:784  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 16 (id=e9df2a4a, encoded size=2272, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.400594 52185 storage/replica_raftstorage.go:790  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.400882 50930 storage/replica_command.go:812  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.407636 50930 storage/replica.go:3743  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.408861 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r13/1:/Table/1{6-7}] sending preemptive snapshot 6f914d55 at applied index 16
I180827 20:41:53.409071 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.409426 52218 storage/replica_raftstorage.go:784  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 16 (id=6f914d55, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.409616 52218 storage/replica_raftstorage.go:790  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.409970 50930 storage/replica_command.go:812  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.411262 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.412831 50930 storage/replica.go:3743  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.414081 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot cca961c1 at applied index 16
I180827 20:41:53.414277 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.414576 52199 storage/replica_raftstorage.go:784  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 16 (id=cca961c1, encoded size=2272, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.414816 52199 storage/replica_raftstorage.go:790  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.415293 50930 storage/replica_command.go:812  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.418111 50930 storage/replica.go:3743  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.419054 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot 3c3a015f at applied index 27
I180827 20:41:53.423022 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 1391, log entries: 2, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.423893 52201 storage/replica_raftstorage.go:784  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 27 (id=3c3a015f, encoded size=194658, 1 rocksdb batches, 2 log entries)
I180827 20:41:53.429501 52201 storage/replica_raftstorage.go:790  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=2ms commit=4ms]
I180827 20:41:53.433500 50930 storage/replica_command.go:812  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.437580 50930 storage/replica.go:3743  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.440575 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot cbd412df at applied index 21
I180827 20:41:53.440794 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 11, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.441181 52260 storage/replica_raftstorage.go:784  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 21 (id=cbd412df, encoded size=4339, 1 rocksdb batches, 11 log entries)
I180827 20:41:53.441400 52260 storage/replica_raftstorage.go:790  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.441676 50930 storage/replica_command.go:812  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.448564 52224 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n2 established
I180827 20:41:53.461587 50930 storage/replica.go:3743  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.463345 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot 114f4385 at applied index 29
I180827 20:41:53.464896 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 59, log entries: 19, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.465343 52280 storage/replica_raftstorage.go:784  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 29 (id=114f4385, encoded size=16646, 1 rocksdb batches, 19 log entries)
I180827 20:41:53.465821 52280 storage/replica_raftstorage.go:790  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.466988 50930 storage/replica_command.go:812  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.472743 50930 storage/replica.go:3743  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.474632 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r1/1:/{Min-System/}] sending preemptive snapshot 0a244018 at applied index 114
I180827 20:41:53.475250 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 73, log entries: 90, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.475827 52267 storage/replica_raftstorage.go:784  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 114 (id=0a244018, encoded size=40271, 1 rocksdb batches, 90 log entries)
I180827 20:41:53.476525 52267 storage/replica_raftstorage.go:790  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.476869 50930 storage/replica_command.go:812  [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, gen=1]
I180827 20:41:53.482912 50930 storage/replica.go:3743  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.483281 50930 storage/queue.go:873  [n1,replicate] purgatory is now empty
I180827 20:41:53.485684 52286 storage/store_snapshot.go:615  [replicate,n1,s1,r20/1:/Table/{23-50}] sending preemptive snapshot f1426c69 at applied index 19
I180827 20:41:53.487316 52286 storage/store_snapshot.go:657  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 9, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.487681 52252 storage/replica_raftstorage.go:784  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 19 (id=f1426c69, encoded size=3273, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.487932 52252 storage/replica_raftstorage.go:790  [n3,s3,r20/?:/Table/{23-50}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.488311 52286 storage/replica_command.go:812  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.503580 52286 storage/replica.go:3743  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.505707 52235 storage/store_snapshot.go:615  [replicate,n1,s1,r1/1:/{Min-System/}] sending preemptive snapshot 99036b07 at applied index 119
I180827 20:41:53.506514 52235 storage/store_snapshot.go:657  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 78, log entries: 95, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.507282 52188 storage/replica_raftstorage.go:784  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 119 (id=99036b07, encoded size=42101, 1 rocksdb batches, 95 log entries)
I180827 20:41:53.508109 52188 storage/replica_raftstorage.go:790  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.508641 52235 storage/replica_command.go:812  [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, gen=1]
I180827 20:41:53.512524 52235 storage/replica.go:3743  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.513999 52209 storage/store_snapshot.go:615  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot bb53109c at applied index 32
I180827 20:41:53.514379 52209 storage/store_snapshot.go:657  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 60, log entries: 22, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.514821 52292 storage/replica_raftstorage.go:784  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 32 (id=bb53109c, encoded size=17687, 1 rocksdb batches, 22 log entries)
I180827 20:41:53.515905 52292 storage/replica_raftstorage.go:790  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 1ms [clear=1ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.516367 52209 storage/replica_command.go:812  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.520158 52209 storage/replica.go:3743  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.521958 52312 storage/store_snapshot.go:615  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot 2ca43612 at applied index 24
I180827 20:41:53.522776 52312 storage/store_snapshot.go:657  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 14, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.523128 52239 storage/replica_raftstorage.go:784  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 24 (id=2ca43612, encoded size=5410, 1 rocksdb batches, 14 log entries)
I180827 20:41:53.523377 52239 storage/replica_raftstorage.go:790  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.523701 52312 storage/replica_command.go:812  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.525176 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 19 underreplicated ranges
I180827 20:41:53.527482 52312 storage/replica.go:3743  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.528875 52327 storage/store_snapshot.go:615  [replicate,n1,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot 731be2ae at applied index 30
I180827 20:41:53.532860 52327 storage/store_snapshot.go:657  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 1392, log entries: 5, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.533361 52316 storage/replica_raftstorage.go:784  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 30 (id=731be2ae, encoded size=195741, 1 rocksdb batches, 5 log entries)
I180827 20:41:53.535834 52316 storage/replica_raftstorage.go:790  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I180827 20:41:53.536253 52327 storage/replica_command.go:812  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.540576 52327 storage/replica.go:3743  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.545804 52341 storage/store_snapshot.go:615  [replicate,n1,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot 7497a95f at applied index 19
I180827 20:41:53.546108 52341 storage/store_snapshot.go:657  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.546590 52275 storage/replica_raftstorage.go:784  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=7497a95f, encoded size=3304, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.546960 52275 storage/replica_raftstorage.go:790  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.547386 52341 storage/replica_command.go:812  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (