etcd panic on close notify

[armstrongli]

ETCD Version:

2017-07-13 22:40:33.607988 I | etcdmain: etcd Version: 3.1.9
2017-07-13 22:40:33.607992 I | etcdmain: Git SHA: 0f4a535
2017-07-13 22:40:33.607995 I | etcdmain: Go Version: go1.7.6
2017-07-13 22:40:33.607998 I | etcdmain: Go OS/Arch: linux/amd64
2017-07-13 22:40:33.608002 I | etcdmain: setting maximum number of CPUs to 32, total number of available CPUs is 32

Hardware configuration:

• 10CPUs
• 20GB memory
• SSD disk

Logs are shown here:

2017-07-13 22:12:41.267108 I | mvcc: finished scheduled compaction at 625679800 (took 120.928714ms)
2017-07-13 22:13:50.550056 I | wal: segmented wal file /var/etcd/data/member/wal/0000000000002acc-000000025294c5d4.wal is created
2017-07-13 22:13:51.252966 I | pkg/fileutil: purged file /var/etcd/data/member/wal/0000000000002ac7-000000025294133f.wal successfully
2017-07-13 22:15:48.102371 I | etcdserver: start to snapshot (applied: 9975419616, lastsnap: 9975409615)
2017-07-13 22:15:48.360742 I | etcdserver: saved snapshot at index 9975419616
2017-07-13 22:15:48.361207 I | etcdserver: compacted raft log at 9975414616
2017-07-13 22:15:50.013703 I | pkg/fileutil: purged file /var/etcd/data/member/snap/0000000000004e25-0000000252940f8b.snap successfully
2017-07-13 22:17:41.152970 I | mvcc: store.index: compact 625686222
2017-07-13 22:17:41.280013 I | mvcc: finished scheduled compaction at 625686222 (took 122.653867ms)
2017-07-13 22:19:57.659186 I | wal: segmented wal file /var/etcd/data/member/wal/0000000000002acd-000000025294f127.wal is created
2017-07-13 22:20:21.271076 I | pkg/fileutil: purged file /var/etcd/data/member/wal/0000000000002ac8-00000002529436e1.wal successfully
2017-07-13 22:21:31.775436 I | etcdserver: start to snapshot (applied: 9975429617, lastsnap: 9975419616)
2017-07-13 22:21:32.042521 I | etcdserver: saved snapshot at index 9975429617
2017-07-13 22:21:32.042905 I | etcdserver: compacted raft log at 9975424617
2017-07-13 22:21:50.020228 I | pkg/fileutil: purged file /var/etcd/data/member/snap/0000000000004e25-000000025294369c.snap successfully
2017-07-13 22:22:41.164304 I | mvcc: store.index: compact 625694084
2017-07-13 22:22:41.289408 I | mvcc: finished scheduled compaction at 625694084 (took 120.812138ms)
2017-07-13 22:26:24.079952 I | wal: segmented wal file /var/etcd/data/member/wal/0000000000002ace-00000002529514c8.wal is created
2017-07-13 22:26:51.300622 I | pkg/fileutil: purged file /var/etcd/data/member/wal/0000000000002ac9-0000000252945aad.wal successfully
2017-07-13 22:27:41.199879 I | mvcc: store.index: compact 625700697
2017-07-13 22:27:41.335152 I | mvcc: finished scheduled compaction at 625700697 (took 131.7406ms)
2017-07-13 22:28:37.062786 I | etcdserver: start to snapshot (applied: 9975439618, lastsnap: 9975429617)
2017-07-13 22:28:37.311109 I | etcdserver: saved snapshot at index 9975439618
2017-07-13 22:28:37.311560 I | etcdserver: compacted raft log at 9975434618
2017-07-13 22:28:50.028700 I | pkg/fileutil: purged file /var/etcd/data/member/snap/0000000000004e25-0000000252945dad.snap successfully
2017-07-13 22:32:41.187660 I | mvcc: store.index: compact 625706880
2017-07-13 22:32:41.309822 I | mvcc: finished scheduled compaction at 625706880 (took 118.462846ms)
2017-07-13 22:32:51.086093 I | wal: segmented wal file /var/etcd/data/member/wal/0000000000002acf-0000000252953887.wal is created
2017-07-13 22:32:51.328341 I | pkg/fileutil: purged file /var/etcd/data/member/wal/0000000000002aca-0000000252947e14.wal successfully
2017-07-13 22:35:44.219815 I | etcdserver: start to snapshot (applied: 9975449619, lastsnap: 9975439618)
2017-07-13 22:35:44.507831 I | etcdserver: saved snapshot at index 9975449619
2017-07-13 22:35:44.508101 I | etcdserver: compacted raft log at 9975444619
2017-07-13 22:35:50.035376 I | pkg/fileutil: purged file /var/etcd/data/member/snap/0000000000004e25-00000002529484be.snap successfully
2017-07-13 22:37:41.198975 I | mvcc: store.index: compact 625713120
2017-07-13 22:37:41.326292 I | mvcc: finished scheduled compaction at 625713120 (took 122.681022ms)
2017-07-13 22:39:19.067367 I | wal: segmented wal file /var/etcd/data/member/wal/0000000000002ad0-0000000252955b74.wal is created
2017-07-13 22:39:21.363074 I | pkg/fileutil: purged file /var/etcd/data/member/wal/0000000000002acb-000000025294a190.wal successfully
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x580cb5]

goroutine 20641038 [running]:
panic(0xd168c0, 0xc420016050)
        /usr/local/go/src/runtime/panic.go:500 +0x1a1
net/http.(*http2responseWriter).CloseNotify.func1(0xc4262c4980, 0xc442177960)
        /usr/local/go/src/net/http/h2_bundle.go:4700 +0x25
created by net/http.(*http2responseWriter).CloseNotify
        /usr/local/go/src/net/http/h2_bundle.go:4702 +0xda

[heyitsanthony]

This is a runtime bug fixed by golang/go#17868 but it was close to the 1.8 release so it wasn't backported into 1.7. Is it worth cutting 3.1.10 with 1.8? /cc @gyuho @xiang90

[gyuho]

This should be fixed by https://github.com/coreos/etcd/releases/tag/v3.1.10 as @heyitsanthony explained.