etcdserver: wait purge file loop to exit before stopping raft

[jingyih]

To prevent purgeFile loop from accidentally acquiring file lock and remove them during server shutdown.

Keyword: "open wal error: wal: file not found"

Issue
Normally, server's raft node holds file lock on all the needed wal files. The file lock is only released when a new snapshot is created and the old wal files are no longer needed [1]. During server shutdown, there is a chance that the raft node stops before the purge file loop exists. On stop, raft node closes all the wal files and therefore releases the file lock. So there is a chance that the purge file loop might acquire the file lock [2] and remove some wal files that are still needed by the server. When this happens, server cannot restart due to error:
C | etcdserver: open wal error: wal: file not found.

Ref:
[1]

etcd/wal/wal.go

Line 731 in 84e2788

func (w *WAL) ReleaseLockTo(index uint64) error {

[2]

etcd/pkg/fileutil/purge.go

Line 51 in 84e2788

l, err := TryLockFile(f, os.O_WRONLY, PrivateFileMode)

Fix
This PR solves the issue by making sure the purge file loop exists before server signals the stopping of raft node.

Reproduce of the orignal issue

Change purgeFileInterval to a very small number (e.g. 1 * time.Nanosecond) so that it is easier to reproduce. Put a lot of data into the server and stop it. There is high probability that purge file loop will remove some of the wal files that are still needed by the server.

Example server log of a local reproduce:

$ bin/etcd
[WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
2019-10-30 14:36:23.860668 I | etcdmain: etcd Version: 3.5.0-pre
2019-10-30 14:36:23.860701 I | etcdmain: Git SHA: 84e2788c2
2019-10-30 14:36:23.860705 I | etcdmain: Go Version: go1.12.5
2019-10-30 14:36:23.860709 I | etcdmain: Go OS/Arch: linux/amd64
2019-10-30 14:36:23.860714 I | etcdmain: setting maximum number of CPUs to 12, total number of available CPUs is 12
2019-10-30 14:36:23.860721 W | etcdmain: no data-dir provided, using default data-dir ./default.etcd
2019-10-30 14:36:23.860753 N | etcdmain: the server is already initialized as member before, starting as etcd member...
[WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
2019-10-30 14:36:23.861257 I | embed: name = default
2019-10-30 14:36:23.861266 I | embed: data dir = default.etcd
2019-10-30 14:36:23.861271 I | embed: member dir = default.etcd/member
2019-10-30 14:36:23.861286 I | embed: heartbeat = 100ms
2019-10-30 14:36:23.861292 I | embed: election = 1000ms
2019-10-30 14:36:23.861295 I | embed: snapshot count = 100000
2019-10-30 14:36:23.861302 I | embed: advertise client URLs = http://localhost:2379
2019-10-30 14:36:23.861306 I | embed: initial advertise peer URLs = http://localhost:2380
2019-10-30 14:36:23.861310 I | embed: initial cluster = 
2019-10-30 14:36:24.204015 I | etcdserver: restarting member 8e9e05c52164694d in cluster cdf818194e3a8c32 at commit index 24314
raft2019/10/30 14:36:24 INFO: 8e9e05c52164694d switched to configuration voters=()
raft2019/10/30 14:36:24 INFO: 8e9e05c52164694d became follower at term 10
raft2019/10/30 14:36:24 INFO: newRaft 8e9e05c52164694d [peers: [], term: 10, commit: 24314, applied: 0, lastindex: 24314, lastterm: 10]
2019-10-30 14:36:24.295636 W | auth: simple token is not cryptographically signed
2019-10-30 14:36:24.299999 I | etcdserver: starting server... [version: 3.5.0-pre, cluster version: to_be_decided]
raft2019/10/30 14:36:24 INFO: 8e9e05c52164694d switched to configuration voters=(10276657743932975437)
2019-10-30 14:36:24.300750 I | etcdserver/membership: added member 8e9e05c52164694d [http://localhost:2380] to cluster cdf818194e3a8c32
2019-10-30 14:36:24.300899 N | etcdserver/membership: set the initial cluster version to 3.5
2019-10-30 14:36:24.300976 I | etcdserver/api: enabled capabilities for version 3.5
2019-10-30 14:36:24.302847 I | embed: listening for peers on 127.0.0.1:2380
raft2019/10/30 14:36:25 INFO: 8e9e05c52164694d is starting a new election at term 10
raft2019/10/30 14:36:25 INFO: 8e9e05c52164694d became candidate at term 11
raft2019/10/30 14:36:25 INFO: 8e9e05c52164694d received MsgVoteResp from 8e9e05c52164694d at term 11
raft2019/10/30 14:36:25 INFO: 8e9e05c52164694d became leader at term 11
raft2019/10/30 14:36:25 INFO: raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 11
2019-10-30 14:36:25.915244 I | embed: ready to serve client requests
2019-10-30 14:36:25.915333 I | etcdserver: published {Name:default ClientURLs:[http://localhost:2379]} to cluster cdf818194e3a8c32
2019-10-30 14:36:25.915973 N | embed: serving insecure client requests on 127.0.0.1:2379, this is strongly discouraged!
2019-10-30 14:36:52.184118 I | wal: segmented wal file default.etcd/member/wal/0000000000000005-0000000000007623.wal is created
2019-10-30 14:37:17.038924 I | wal: segmented wal file default.etcd/member/wal/0000000000000006-0000000000008dbf.wal is created
2019-10-30 14:37:41.839027 I | wal: segmented wal file default.etcd/member/wal/0000000000000007-000000000000a55b.wal is created
2019-10-30 14:38:06.700599 I | wal: segmented wal file default.etcd/member/wal/0000000000000008-000000000000bcf7.wal is created
2019-10-30 14:38:31.649956 I | wal: segmented wal file default.etcd/member/wal/0000000000000009-000000000000d493.wal is created
2019-10-30 14:38:56.522412 I | wal: segmented wal file default.etcd/member/wal/000000000000000a-000000000000ec2f.wal is created
2019-10-30 14:39:21.491050 I | wal: segmented wal file default.etcd/member/wal/000000000000000b-00000000000103cb.wal is created
^C2019-10-30 14:39:45.699365 N | pkg/osutil: received interrupt signal, shutting down...
2019-10-30 14:39:45.699515 I | etcdserver: skipped leadership transfer for single voting member cluster
2019-10-30 14:39:45.708620 I | pkg/fileutil: purged file default.etcd/member/wal/0000000000000000-0000000000000000.wal successfully
2019-10-30 14:39:45.715352 I | pkg/fileutil: purged file default.etcd/member/wal/0000000000000001-00000000000017a1.wal successfully
 
 
$ bin/etcd
[WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
2019-10-30 14:39:52.853558 I | etcdmain: etcd Version: 3.5.0-pre
2019-10-30 14:39:52.853591 I | etcdmain: Git SHA: 84e2788c2
2019-10-30 14:39:52.853595 I | etcdmain: Go Version: go1.12.5
2019-10-30 14:39:52.853600 I | etcdmain: Go OS/Arch: linux/amd64
2019-10-30 14:39:52.853605 I | etcdmain: setting maximum number of CPUs to 12, total number of available CPUs is 12
2019-10-30 14:39:52.853612 W | etcdmain: no data-dir provided, using default data-dir ./default.etcd
2019-10-30 14:39:52.853651 N | etcdmain: the server is already initialized as member before, starting as etcd member...
[WARNING] Deprecated '--logger=capnslog' flag is set; use '--logger=zap' flag instead
2019-10-30 14:39:52.853982 I | embed: name = default
2019-10-30 14:39:52.853988 I | embed: data dir = default.etcd
2019-10-30 14:39:52.853993 I | embed: member dir = default.etcd/member
2019-10-30 14:39:52.853998 I | embed: heartbeat = 100ms
2019-10-30 14:39:52.854002 I | embed: election = 1000ms
2019-10-30 14:39:52.854006 I | embed: snapshot count = 100000
2019-10-30 14:39:52.854013 I | embed: advertise client URLs = http://localhost:2379
2019-10-30 14:39:52.854018 I | embed: initial advertise peer URLs = http://localhost:2380
2019-10-30 14:39:52.854024 I | embed: initial cluster = 
2019-10-30 14:39:53.031440 C | etcdserver: open wal error: wal: file not found

[codecov-io]

Codecov Report

Merging #11308 into master will decrease coverage by 0.37%.
The diff coverage is 94.44%.

@@            Coverage Diff             @@
##           master   #11308      +/-   ##
==========================================
- Coverage   64.05%   63.68%   -0.38%     
==========================================
  Files         403      403              
  Lines       37953    37966      +13     
==========================================
- Hits        24312    24179     -133     
- Misses      11980    12142     +162     
+ Partials     1661     1645      -16

Impacted Files	Coverage Δ
etcdserver/server.go	69.39% <100%> (+1.4%)	⬆️
pkg/fileutil/purge.go	66% <87.5%> (+0.09%)	⬆️
auth/store.go	47.38% <0%> (-20.95%)	⬇️
etcdserver/api/v3rpc/util.go	51.61% <0%> (-16.13%)	⬇️
auth/jwt.go	56.19% <0%> (-12.39%)	⬇️
pkg/adt/interval_tree.go	84.21% <0%> (-3.01%)	⬇️
client/client.go	41.83% <0%> (-2.29%)	⬇️
etcdserver/api/v3rpc/key.go	78.87% <0%> (-1.41%)	⬇️
etcdserver/api/v3rpc/watch.go	78.43% <0%> (-1.31%)	⬇️
clientv3/op.go	72.08% <0%> (-1.25%)	⬇️
... and 21 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 84e2788...c447955. Read the comment docs.

[jingyih]

cc @wenjiaswe

[gyuho]

lgtm good catch!

[jingyih]

@gyuho I think we should backport this fix?

[gyuho]

@jingyih Yes, let's backport!

[jpbetz]

LGTM. Thanks for jumping on this @jingyih. yes, please backport. Severity is high.