continously print log "fileutil: file already locked"

[BlueBlue-Lee]

etcd version: v3.5.6

etcd cluster status:

$ etcdctl endpoint health --cluster
https://10.166.72.41:xxx is healthy: successfully committed proposal: took = 1.566653ms
https://10.166.72.61:xxx is healthy: successfully committed proposal: took = 950.661µs
https://10.166.72.51:xxx is healthy: successfully committed proposal: took = 1.001659ms

$ etcdctl endpoint status --cluster
https://10.166.72.41:xxx, 3d29925759, 3.5.6, 218 MB, false, 20, 10707739
https://10.166.72.61:xxx, 49fcf39fe2e, 3.5.6, 218 MB, false, 20, 10707743
https://10.166.72.51:xxx, 4cdc1a0fbd, 3.5.6, 218 MB, true, 20, 10707744

etcd log:

{"level":"warn","ts":"2023-01-13T17:36:24.665+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:36:54.666+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:37:24.666+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:37:54.668+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:38:24.668+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"info","ts":"2023-01-13T17:38:47.925+0800","caller":"mvcc/index.go:214","msg":"compact tree index","revision":1406923}
{"level":"info","ts":"2023-01-13T17:38:48.072+0800","caller":"mvcc/kvstore_compaction.go:66","msg":"finished scheduled compaction","compact-revision":1406923,"took":"142.486587ms","hash":80862412}
{"level":"info","ts":"2023-01-13T17:38:48.073+0800","caller":"mvcc/hash.go:137","msg":"storing new hash","hash":80862412,"revision":1406923,"compact-revision":1406756}
{"level":"warn","ts":"2023-01-13T17:38:54.669+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:39:24.669+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:39:54.670+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:40:24.671+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}
{"level":"warn","ts":"2023-01-13T17:40:54.671+0800","caller":"fileutil/purge.go:72","msg":"failed to lock file","path":"/data/etcd/member/wal/0000000000000259-0000000000155556.wal","error":"fileutil: file already locked"}

I can read/write etcd normaly, but etcd continously print warning log. Anyone can tell me the reason and fix solution? Thanks a lot.

[ptabor]

Guessing:

• Filesystem that does not support locking ?
• Another instance of etcd running on the same directory (e.g. STOPPED as a process in background)

[BlueBlue-Lee]

• Ext4 filesystem. And I have another etcd cluster run on same disk but different directory, there are not this warning log in another etcd cluster.
• I use lsof to get processes who lock the wal file. Only one process 2479800 lock the file with u mode(for a read and write lock of any length).

lsof | grep "00000000000080e-00000000000c33a9.wal" --color
etcd      2479800                          root   10u      REG               8,33   64164640   47448313 /data/etcd/member/wal/000000000000080e-00000000000c33a9.wal
etcd      2479800 2479824 etcd             root   10u      REG               8,33   64164640   47448313 /data/etcd/member/wal/000000000000080e-00000000000c33a9.wal
etcd      2479800 2479826 etcd             root   10u      REG               8,33   64164640   47448313 /data/etcd/member/wal/000000000000080e-00000000000c33a9.wal
etcd      2479800 2479828 etcd             root   10u      REG               8,33   64164640   47448313 /data/etcd/member/wal/000000000000080e-00000000000c33a9.wal
etcd      2479800 2479830 etcd             root   10u      REG               8,33   64164640   47448313 /data/etcd/member/wal/000000000000080e-00000000000c33a9.wal
... ...

• /data/etcd/member/wal/0000000000000259-0000000000155556.wal is the oldest wal file for my etcd cluster. etcd want to purge it but can not. Can I delete this file manually to recover from this error?

[BlueBlue-Lee]

Any suggestions?

[BlueBlue-Lee]

I know the reason. commit 5746d6 involve this . If --snapshot-count set big and --max-wals set small, and value size is big, this error log easily happened.

etcd can remove this error log or user can modify command param --snapshot-count and --max-wals

[ptabor]

I would also consider conditional severity of the log-line depending on the context:

• If just created file cannot be locked -> It's ERROR
• If that's check before deletion -> it should be INFO -> as it's a normal protection behavior of the system.
  [ And dependency on correctness of locking shows that etcd must not be used on NFS / other FS not supporting flocking ]