flake: TestStoreWatch panicked

[smarterclayton]

https://ci.openshift.redhat.com/jenkins/job/test_pull_requests_origin_check_future/455/consoleFull#
-4669372365898c58db7602c31c0eab717

16:30:38 In suite "github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/registry/generic/registry", test case "TestStoreWatch" failed:
16:30:38 === RUN   TestStoreWatch
16:30:38 2017-02-22 21:26:46.973907 I | integration: launching node8086719234727585616 (unix://localhost:node8086719234727585616.sock.bridge)
16:30:38 2017-02-22 21:26:46.979865 I | etcdserver: name = node8086719234727585616
16:30:38 2017-02-22 21:26:46.979935 I | etcdserver: data dir = /openshifttmp/etcd262931388
16:30:38 2017-02-22 21:26:46.979996 I | etcdserver: member dir = /openshifttmp/etcd262931388/member
16:30:38 2017-02-22 21:26:46.980045 I | etcdserver: heartbeat = 10ms
16:30:38 2017-02-22 21:26:46.980108 I | etcdserver: election = 100ms
16:30:38 2017-02-22 21:26:46.980154 I | etcdserver: snapshot count = 0
16:30:38 2017-02-22 21:26:46.980212 I | etcdserver: advertise client URLs = unix://127.0.0.1:21042.26872.sock
16:30:38 2017-02-22 21:26:46.980272 I | etcdserver: initial advertise peer URLs = unix://127.0.0.1:21041.26872.sock
16:30:38 2017-02-22 21:26:46.980339 I | etcdserver: initial cluster = node8086719234727585616=unix://127.0.0.1:21041.26872.sock
16:30:38 2017-02-22 21:26:46.987704 I | etcdserver: starting member e99b8932edff9624 in cluster 1cb96a0da8cb3761
16:30:38 2017-02-22 21:26:46.987828 I | raft: e99b8932edff9624 became follower at term 0
16:30:38 2017-02-22 21:26:46.987915 I | raft: newRaft e99b8932edff9624 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
16:30:38 2017-02-22 21:26:46.987983 I | raft: e99b8932edff9624 became follower at term 1
16:30:38 2017-02-22 21:26:47.115464 I | etcdserver: set snapshot count to default 10000
16:30:38 2017-02-22 21:26:47.115554 I | etcdserver: starting server... [version: 3.1.0, cluster version: to_be_decided]
16:30:38 2017-02-22 21:26:47.119722 I | etcdserver/membership: added member e99b8932edff9624 [unix://127.0.0.1:21041.26872.sock] to cluster 1cb96a0da8cb3761
16:30:38 2017-02-22 21:26:47.120002 I | integration: launched node8086719234727585616 (unix://localhost:node8086719234727585616.sock.bridge)
16:30:38 2017-02-22 21:26:47.199988 I | raft: e99b8932edff9624 is starting a new election at term 1
16:30:38 2017-02-22 21:26:47.200086 I | raft: e99b8932edff9624 became candidate at term 2
16:30:38 2017-02-22 21:26:47.200156 I | raft: e99b8932edff9624 received MsgVoteResp from e99b8932edff9624 at term 2
16:30:38 2017-02-22 21:26:47.200253 I | raft: e99b8932edff9624 became leader at term 2
16:30:38 2017-02-22 21:26:47.200320 I | raft: raft.node: e99b8932edff9624 elected leader e99b8932edff9624 at term 2
16:30:38 2017-02-22 21:26:47.204093 I | etcdserver: published {Name:node8086719234727585616 ClientURLs:[unix://127.0.0.1:21042.26872.sock]} to cluster 1cb96a0da8cb3761
16:30:38 2017-02-22 21:26:47.204429 I | etcdserver: setting up the initial cluster version to 3.1
16:30:38 2017-02-22 21:26:47.207578 N | etcdserver/membership: set the initial cluster version to 3.1
16:30:38 E0222 21:26:47.220457   26872 watcher.go:172] failed to sync with latest state: context canceled
16:30:38 2017-02-22 21:26:47.222456 I | integration: terminating node8086719234727585616 (unix://localhost:node8086719234727585616.sock.bridge)
16:30:38 2017-02-22 21:26:47.223183 I | etcdserver/api/v3rpc: transport: http2Server.HandleStreams failed to read frame: read unix localhost:node8086719234727585616.sock->@: use of closed network connection
16:30:38 2017-02-22 21:26:47.223672 I | etcdserver/api/v3rpc: transport: http2Server.HandleStreams failed to read frame: read unix localhost:node8086719234727585616.sock->@: use of closed network connection
16:30:38 panic: assertion failed: tx closed
16:30:38 goroutine 2144 [running]:
16:30:38 panic(0x1953ec0, 0xc420439ee0)
16:30:38 	/usr/local/go/src/runtime/panic.go:500 +0x1ae
16:30:38 github.com/openshift/origin/vendor/github.com/boltdb/bolt._assert(0xc420b82000, 0x1b9b65f, 0x9, 0x0, 0x0, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/boltdb/bolt/db.go:1026 +0x112
16:30:38 github.com/openshift/origin/vendor/github.com/boltdb/bolt.(*Cursor).seek(0xc420be2d90, 0x259e3ac, 0x3, 0x3, 0x0, 0x0, 0xc420a9c980, 0xc420be2dc8, 0x14b4884, 0xc420be2fb8, ...)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/boltdb/bolt/cursor.go:155 +0xd9
16:30:38 github.com/openshift/origin/vendor/github.com/boltdb/bolt.(*Bucket).Bucket(0xc420b82018, 0x259e3ac, 0x3, 0x3, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/boltdb/bolt/bucket.go:112 +0x1ee
16:30:38 github.com/openshift/origin/vendor/github.com/boltdb/bolt.(*Tx).Bucket(0xc420b82000, 0x259e3ac, 0x3, 0x3, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/boltdb/bolt/tx.go:101 +0x5d
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc/backend.(*batchTx).UnsafeRange(0xc420b188a0, 0x259e3ac, 0x3, 0x3, 0xc420ad5200, 0x11, 0x12, 0xc420ad5220, 0x11, 0x12, ...)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc/backend/batch_tx.go:88 +0x9f
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc.(*store).rangeKeys(0xc42022d520, 0xc420372300, 0xf, 0x10, 0xc420372330, 0xf, 0x10, 0x0, 0x0, 0x43e600, ...)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc/kvstore.go:524 +0x351
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc.(*store).Range(0xc42022d520, 0xc420372300, 0xf, 0x10, 0xc420372330, 0xf, 0x10, 0x0, 0x0, 0x0, ...)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc/kvstore.go:155 +0xe3
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/mvcc.(*watchableStore).Range(0xc420ad0510, 0xc420372300, 0xf, 0x10, 0xc420372330, 0xf, 0x10, 0x0, 0x0, 0xc420be3300, ...)
16:30:38 	<autogenerated>:53 +0xf7
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver.(*applierV3backend).Range(0xc42002c030, 0xffffffffffffffff, 0xc42028ba40, 0x10, 0xc420372330, 0xf)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/apply.go:284 +0x13a5
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).Range.func2()
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/v3_server.go:113 +0x9d
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).doSerialize(0xc420ac6000, 0x7ff72a5cea58, 0xc420987ef0, 0xc420ad5020, 0xc420be3670, 0x0, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/v3_server.go:680 +0x15a
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).Range(0xc420ac6000, 0x7ff72a5cea58, 0xc420987ef0, 0xc42028ba40, 0x25b5f20, 0xc4000002c5, 0xf14443)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/v3_server.go:114 +0x39c
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/api/v3rpc.(*kvServer).Range(0xc42114e100, 0x7ff72a5cea58, 0xc420987ef0, 0xc42028ba40, 0x1a4d3e0, 0xf12600, 0x25b9f80)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/api/v3rpc/key.go:50 +0x115
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/api/v3rpc.(*quotaKVServer).Range(0xc42114e140, 0x7ff72a5cea58, 0xc420987ef0, 0xc42028ba40, 0x3, 0x25bc4a0, 0xc4202d5580)
16:30:38 	<autogenerated>:20 +0x87
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/etcdserverpb._KV_Range_Handler.func1(0x7ff72a5cea58, 0xc420987ef0, 0x1aa53e0, 0xc42028ba40, 0xc420ade9b0, 0x8, 0x1a34c80, 0x1a34c80)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/etcdserverpb/rpc.pb.go:2287 +0xe9
16:30:38 github.com/openshift/origin/vendor/github.com/grpc-ecosystem/go-grpc-prometheus.UnaryServerInterceptor(0x7ff72a5cea58, 0xc420987ef0, 0x1aa53e0, 0xc42028ba40, 0xc420b2ffa0, 0xc420b2ffc0, 0xc42005a400, 0x7ff72d70b960, 0x0, 0xc420b2ff80)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/grpc-ecosystem/go-grpc-prometheus/server.go:29 +0xd0
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/api/v3rpc.newUnaryInterceptor.func1(0x7ff72a5cea58, 0xc420987ef0, 0x1aa53e0, 0xc42028ba40, 0xc420b2ffa0, 0xc420b2ffc0, 0x7ff729b78698, 0x0, 0x0, 0xc42005a400)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/api/v3rpc/interceptor.go:57 +0x106
16:30:38 github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/etcdserverpb._KV_Range_Handler(0x1a4d3e0, 0xc42114e140, 0x7ff72a5cea58, 0xc420987ef0, 0xc420ade960, 0xc4204581e0, 0x0, 0x0, 0x0, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/github.com/coreos/etcd/etcdserver/etcdserverpb/rpc.pb.go:2289 +0x1db
16:30:38 github.com/openshift/origin/vendor/google.golang.org/grpc.(*Server).processUnaryRPC(0xc420198840, 0x25bc620, 0xc42001ac60, 0xc420a42ff0, 0xc420b28270, 0x2607860, 0xc420987ec0, 0x0, 0x0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/google.golang.org/grpc/server.go:638 +0x10c8
16:30:38 github.com/openshift/origin/vendor/google.golang.org/grpc.(*Server).handleStream(0xc420198840, 0x25bc620, 0xc42001ac60, 0xc420a42ff0, 0xc420987ec0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/google.golang.org/grpc/server.go:796 +0xf9d
16:30:38 github.com/openshift/origin/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1(0xc420458920, 0xc420198840, 0x25bc620, 0xc42001ac60, 0xc420a42ff0)
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/google.golang.org/grpc/server.go:449 +0xb9
16:30:38 created by github.com/openshift/origin/vendor/google.golang.org/grpc.(*Server).serveStreams.func1
16:30:38 	/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/google.golang.org/grpc/server.go:450 +0xbb
16:30:38 In suite "github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/security/apparmor", test case "TestGetAppArmorFS" was skipped:

[derekwaynecarr]

@marun -- can you help track down this flake?

[derekwaynecarr]

The panic is driven by this assertion:

https://github.com/openshift/origin/blob/release-1.5/vendor/github.com/boltdb/bolt/cursor.go#L155

This looks the same as this issue currently open in etcd:

etcd-io/etcd#7322

[derekwaynecarr]

so similar to the above, somewhere a db is being closed while not waiting for tx to finish.

i am inclined to make this a p2 since it has not been reported outside of this test case.

[derekwaynecarr]

which is the exact same as this upstream issue:

kubernetes/kubernetes#34953

[0xmichalis]

https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin_unit/203/consoleFull#79199702058b6e51eb7608a5981914356

[mfojtik]

fresh logs:

https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/17746/test_pull_request_origin_unit/6934/

[openshift-bot]

Issues go stale after 90d of inactivity.

Mark the issue as fresh by commenting /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.
Exclude this issue from closing by commenting /lifecycle frozen.

If this issue is safe to close now please do so with /close.

/lifecycle stale

[openshift-bot]

Stale issues rot after 30d of inactivity.

Mark the issue as fresh by commenting /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.
Exclude this issue from closing by commenting /lifecycle frozen.

If this issue is safe to close now please do so with /close.

/lifecycle rotten
/remove-lifecycle stale

[openshift-bot]

Rotten issues close after 30d of inactivity.

Reopen the issue by commenting /reopen.
Mark the issue as fresh by commenting /remove-lifecycle rotten.
Exclude this issue from closing again by commenting /lifecycle frozen.

/close