teamcity: failed test: TestImportPgDump

[tbg]

The following tests appear to have failed on release-banana: test/TestImportPgDump

You may want to check for open issues.

#864629:

test/TestImportPgDump
...inutes]:
github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.(*ccResolverWrapper).watcher(0xc424cbeb40)
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/resolver_conn_wrapper.go:109 +0x182
created by github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.(*ccResolverWrapper).start
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/resolver_conn_wrapper.go:95 +0x3f

goroutine 51615 [semacquire]:
sync.runtime_notifyListWait(0xc4216f3ed0, 0x1174)
	/usr/local/go/src/runtime/sema.go:510 +0x10b
sync.(*Cond).Wait(0xc4216f3ec0)
	/usr/local/go/src/sync/cond.go:56 +0x80
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc420966480, 0x2eb2080, 0xc4226d3aa0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:197 +0x7c
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x2eb2080, 0xc4226d3aa0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:166 +0x3e
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42035d2a0, 0xc4215a8cf0, 0xc42035d290)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:199 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:192 +0xad

goroutine 51491 [select, 4 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).initRunners.func1(0x2eb2080, 0xc42144c0f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:88 +0x151
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc4251cf610, 0xc4215a8cf0, 0xc4251cf5f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:199 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:192 +0xad

goroutine 50899 [chan receive, 7 minutes]:
github.com/cockroachdb/cockroach/pkg/util/log.(*loggingT).gcDaemon(0xc4204fc780)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:1230 +0x68
created by github.com/cockroachdb/cockroach/pkg/util/log.NewSecondaryLogger
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/secondary_log.go:80 +0x288

goroutine 51583 [chan receive]:
github.com/cockroachdb/cockroach/pkg/storage/closedts/provider.(*Provider).Notify.func1(0x2eb2080, 0xc421ec4570)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/closedts/provider/provider.go:204 +0x148
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42038a0c0, 0xc42539e1b0, 0xc420310540)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:199 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:192 +0xad

goroutine 51971 [select, 7 minutes]:
github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.newClientStream.func5(0xc4216da000, 0xc42337d780, 0x2eb2080, 0xc420e695c0)
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/stream.go:321 +0xfe
created by github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.newClientStream
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/stream.go:320 +0xa76

goroutine 50888 [select, 7 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*DistSQLPlanner).initRunners.func1(0x2eb2080, 0xc4209be000)
	/go/src/github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:88 +0x151
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42055d1f0, 0xc42539e1b0, 0xc42055d1e0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:199 +0xe9
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:192 +0xad
I180827 20:41:04.554200 1 rand.go:75  Random seed: 2144118708575765637



test/TestImportPgDump
...ptive snapshot 0df534b1 at applied index 21
I180827 20:41:53.711657 52485 storage/store_snapshot.go:657  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.712336 52431 storage/replica_raftstorage.go:784  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 21 (id=0df534b1, encoded size=5384, 1 rocksdb batches, 11 log entries)
I180827 20:41:53.712589 52431 storage/replica_raftstorage.go:790  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.712941 52485 storage/replica_command.go:812  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.716662 52485 storage/replica.go:3743  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.716741 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 3 underreplicated ranges
I180827 20:41:53.719005 52448 storage/store_snapshot.go:615  [replicate,n1,s1,r22/1:/{Table/51-Max}] sending preemptive snapshot 67476018 at applied index 15
I180827 20:41:53.719195 52448 storage/store_snapshot.go:657  [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.719598 52470 storage/replica_raftstorage.go:784  [n2,s2,r22/?:{-}] applying preemptive snapshot at index 15 (id=67476018, encoded size=1418, 1 rocksdb batches, 5 log entries)
I180827 20:41:53.719793 52470 storage/replica_raftstorage.go:790  [n2,s2,r22/?:/{Table/51-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.720252 52448 storage/replica_command.go:812  [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, (n3,s3):2, next=3, gen=0]
I180827 20:41:53.724721 52448 storage/replica.go:3743  [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.726370 52456 storage/store_snapshot.go:615  [replicate,n1,s1,r21/1:/Table/5{0-1}] sending preemptive snapshot 57d2d847 at applied index 21
I180827 20:41:53.726577 52456 storage/store_snapshot.go:657  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.726928 52460 storage/replica_raftstorage.go:784  [n2,s2,r21/?:{-}] applying preemptive snapshot at index 21 (id=57d2d847, encoded size=3678, 1 rocksdb batches, 11 log entries)
I180827 20:41:53.727126 52460 storage/replica_raftstorage.go:790  [n2,s2,r21/?:/Table/5{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.727433 52456 storage/replica_command.go:812  [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.732265 52456 storage/replica.go:3743  [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.798848 52462 rpc/nodedialer/nodedialer.go:92  [consistencyChecker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180827 20:41:53.959825 52553 sql/event_log.go:126  [n1,client=127.0.0.1:57092,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:kv.import.batch_size Value:10KB User:root}
I180827 20:41:53.969828 52553 sql/event_log.go:126  [n1,client=127.0.0.1:57092,user=root] Event: "create_database", target: 52, info: {DatabaseName:foo Statement:CREATE DATABASE foo User:root}
I180827 20:41:53.970454 52505 storage/replica_command.go:298  [split,n1,s1,r22/1:/{Table/51-Max}] initiating a split of this range at key /Table/52 [r23]



test/TestImportPgDump
...1: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

Please assign, take a look and update the issue accordingly.