panic when two snapshots are received in short period

[serathius]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via etcd maintainers.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

https://github.com/etcd-io/etcd/actions/runs/9188844320/job/25269542381

{"level":"panic","ts":"2024-05-22T10:31:40.994846Z","caller":"etcdserver/server.go:1010","msg":"failed to open snapshot backend","error":"failed to find database snapshot file (snap: snapshot file doesn't exist)","stacktrace":"go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applySnapshot\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:1010\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applyAll\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:947\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).run.func6\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:840\ngo.etcd.io/etcd/pkg/v3/schedule.job.Do\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:41\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:206\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).run\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:187"}
2024-05-22T10:31:41.0044258Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.994887Z","caller":"etcdserver/server.go:984","msg":"applied snapshot","current-snapshot-index":1590,"current-applied-index":1590,"incoming-leader-snapshot-index":1857,"incoming-leader-snapshot-term":2}
2024-05-22T10:31:41.0060472Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"panic","ts":"2024-05-22T10:31:40.994904Z","caller":"schedule/schedule.go:202","msg":"execute job failed","job":"server_applyAll","panic":"failed to open snapshot backend","stacktrace":"go.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob.func1\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:202\nruntime.gopanic\n\truntime/panic.go:770\ngo.uber.org/zap/zapcore.CheckWriteAction.OnWrite\n\tgo.uber.org/zap@v1.27.0/zapcore/entry.go:196\ngo.uber.org/zap/zapcore.(*CheckedEntry).Write\n\tgo.uber.org/zap@v1.27.0/zapcore/entry.go:262\ngo.uber.org/zap.(*Logger).Panic\n\tgo.uber.org/zap@v1.27.0/logger.go:285\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applySnapshot\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:1010\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applyAll\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:947\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).run.func6\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:840\ngo.etcd.io/etcd/pkg/v3/schedule.job.Do\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:41\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:206\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).run\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:187"}
2024-05-22T10:31:41.0074671Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): panic: failed to open snapshot backend [recovered]
2024-05-22T10:31:41.0077589Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): 	panic: execute job failed

What did you expect to happen?

Etcd not to panic

How can we reproduce it (as minimally and precisely as possible)?

TODO

Anything else we need to know?

No response

Etcd version (please run commands below)

v3.6

Etcd configuration (command line flags or environment variables)

Details

paste your configuration here

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

Details

$ etcdctl member list -w table
# paste output here

$ etcdctl --endpoints=<member list> endpoint status -w table
# paste output here

Relevant log output

No response

[serathius]

cc @ahrtr @MadhavJivrajani @siyuanfoundation @fuweid

Can someone take a look and double check my findings?

[ahrtr]

Root cause

The member/follower test-0 received two snapshots from the leader in a very short period.

• Received the first snapshot (with index 1857) at 10:31:39.902927Z;
• Received the second snapshot (with index 2639) at 10:31:40.9904380Z

Note that the all the three members were running with --snapshot-count=100, so it's easily to trigger a snapshot from a leader to a slow follower.

When it received the second snapshot, it released/removed the first snapshot (see below code); but it hadn't finished applying the first snapshot, according ran into the issue failed to find database snapshot file (snap: snapshot file doesn't exist), and paniced.

etcd/server/etcdserver/api/snap/snapshotter.go

Lines 273 to 278 in f903a9b

	if index < snap.Metadata.Index {
	s.lg.Info("found orphaned .snap.db file; deleting", zap.String("path", filename))
	if rmErr := os.Remove(filepath.Join(s.dir, filename)); rmErr != nil && !os.IsNotExist(rmErr) {
	s.lg.Error("failed to remove orphaned .snap.db file", zap.String("path", filename), zap.String("error", rmErr.Error()))
	}
	}

See also the extracted key log messages below,

2024-05-22T10:31:39.9556224Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:39.902927Z","caller":"rafthttp/http.go:286","msg":"received and saved database snapshot","local-member-id":"eabdbb777cf498cb","remote-snapshot-sender-id":"ac4ec652f10e5b49","incoming-snapshot-index":1857,"incoming-snapshot-size-bytes":163840,"incoming-snapshot-size":"164 kB","download-took":"1.42184ms"}
...
2024-05-22T10:31:40.9904380Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.916679Z","caller":"rafthttp/http.go:286","msg":"received and saved database snapshot","local-member-id":"eabdbb777cf498cb","remote-snapshot-sender-id":"ac4ec652f10e5b49","incoming-snapshot-index":2639,"incoming-snapshot-size-bytes":221184,"incoming-snapshot-size":"221 kB","download-took":"3.01444ms"}
...

2024-05-22T10:31:40.9996050Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.988704Z","caller":"etcdserver/server.go:976","msg":"applying snapshot","current-snapshot-index":1590,"current-applied-index":1590,"incoming-leader-snapshot-index":1857,"incoming-leader-snapshot-term":2}
2024-05-22T10:31:41.0003572Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.989977Z","caller":"etcdserver/raft.go:266","msg":"applied incoming Raft snapshot","snapshot-index":2639}
2024-05-22T10:31:41.0009745Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.99009Z","caller":"snap/snapshotter.go:274","msg":"found orphaned .snap.db file; deleting","path":"0000000000000741.snap.db"}
2024-05-22T10:31:41.0019185Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"warn","ts":"2024-05-22T10:31:40.994788Z","caller":"snap/db.go:87","msg":"failed to find [SNAPSHOT-INDEX].snap.db","snapshot-index":1857,"snapshot-file-path":"/tmp/TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize34029954203/001/member/snap/0000000000000741.snap.db","error":"snap: snapshot file doesn't exist"}
2024-05-22T10:31:41.0032765Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"panic","ts":"2024-05-22T10:31:40.994846Z","caller":"etcdserver/server.go:1010","msg":"failed to open snapshot backend","error":"failed to find database snapshot file (snap: snapshot file doesn't exist)","stacktrace":"go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applySnapshot\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:1010\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).applyAll\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:947\ngo.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).run.func6\n\tgo.etcd.io/etcd/server/v3/etcdserver/server.go:840\ngo.etcd.io/etcd/pkg/v3/schedule.job.Do\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:41\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:206\ngo.etcd.io/etcd/pkg/v3/schedule.(*fifo).run\n\tgo.etcd.io/etcd/pkg/v3@v3.6.0-alpha.0/schedule/schedule.go:187"}
2024-05-22T10:31:41.0044258Z /home/runner/actions-runner/_work/etcd/etcd/bin/etcd (TestRobustnessExploratoryKubernetesHighTrafficClusterOfSize3-test-0) (40381): {"level":"info","ts":"2024-05-22T10:31:40.994887Z","caller":"etcdserver/server.go:984","msg":"applied snapshot","current-snapshot-index":1590,"current-applied-index":1590,"incoming-leader-snapshot-index":1857,"incoming-leader-snapshot-term":2}

Impact

Should be minor.

• The default value for --snapshot-count is 10000 in main(3.6), and 100000 for 3.5 and 3.4, so it shouldn't be easy to reproduce in production.
• Even it's reproduced, it can automatically reload the latest snapshot, and everything will be running well again.

Potential solutions

• Just print an error message instead of panicking when running into failed to find database snapshot file (snap: snapshot file doesn't exist). It's the simplest solution, but it may also hide some serious problem.
• Lock the snapshot file and unlock it until it has been applied or cancelled. It may need some effort.

[serathius]

Thanks for investigation.

This reminds me of #17146

[MrDXY]

Hi team,

If I understand correctly, the issue arises when a newer snapshot message releases the .snap.db file of an older snapshot, which will be processed sometime later. This causes a failure.

I would like to propose a simple improvement to address this issue as @ahrtr suggested. The idea is to introduce a locking mechanism in the Snapshotter. The main changes will be in three places:

1. server/etcdserver/api/snap/snapshotter.go
   • Add a field to record the filenames that need to be locked.
   • When executing Snapshotter.ReleaseSnapDBs, check whether the filename is still locked.

   • etcd/server/etcdserver/api/snap/snapshotter.go

     Line 255 in 21e5876

     func (s *Snapshotter) ReleaseSnapDBs(snap raftpb.Snapshot) error {

2. server/etcdserver/api/snap/db.go
   • When Snapshotter.SaveDBFrom is called, the lock in Snapshotter will record the filename, ensuring it will not be deleted by Snapshotter.ReleaseSnapDBs.

   • etcd/server/etcdserver/api/snap/db.go

     Line 35 in 21e5876

     func (s *Snapshotter) SaveDBFrom(r io.Reader, id uint64) (int64, error) {

3. server/etcdserver/server.go
   • The filename lock will be released once serverstorage.OpenSnapshotBackend is executed.

   • etcd/server/etcdserver/server.go

     Line 1014 in 21e5876

     newbe, err := serverstorage.OpenSnapshotBackend(s.Cfg, s.snapshotter, toApply.snapshot, s.beHooks)

This approach should prevent the premature deletion of .snap.db files that are still in use by older snapshots.

Looking forward to your feedback!

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.

[serathius]

Reproduced in Antithesis

https://linuxfoundation.antithesis.com/report/HqTiW-VhiXU25CCPP8vkSUPB/3Q73gnvlcEpEb6XVWcl4H3qTOnXZ7pFAdkpbpHr8mMI.html?auth=v2.public.eyJzY29wZSI6eyJSZXBvcnRTY29wZVYxIjp7ImFzc2V0IjoiM1E3M2dudmxjRXBFYjZYVldjbDRIM3FUT25YWjdwRkFka3BicEhyOG1NSS5odG1sIiwicmVwb3J0X2lkIjoiSHFUaVctVmhpWFUyNUNDUFA4dmtTVVBCIn19LCJuYmYiOiIyMDI1LTA2LTA2VDAxOjA5OjE5Ljc1MDg1NDI2NVoifW8RMYqVcS2V3idTzyvalEO2SnPqycds-Cn710lY-wlfqYPe1MAb2U0R2wEKVwPtSsr79WcnR8yYCyZyCQNqhAc

Look under: Properties > Correctness > No Panics > execute job failed

[serathius]

What is interesting find is that Antithesis reproduced it on etcd default configuration

{"level":"info","ts":"2025-06-05T13:33:41.955394Z","caller":"embed/etcd.go:321","msg":"starting an etcd server","etcd-version":"3.7.0-alpha.0","git-sha":"3be967f","go-version":"go1.24.3","go-os":"linux","go-arch":"amd64","max-cpu-set":4,"max-cpu-available":1,"member-initialized":false,"name":"etcd2","data-dir":"/var/etcd/data","wal-dir":"","wal-dir-dedicated":"","member-dir":"/var/etcd/data/member","force-new-cluster":false,"heartbeat-interval":"100ms","election-timeout":"1s","initial-election-tick-advance":true,"snapshot-count":10000,"max-wals":5,"max-snapshots":5,"snapshot-catchup-entries":5000,"initial-advertise-peer-urls":["http://etcd2:2380"],"listen-peer-urls":["http://0.0.0.0:2380"],"advertise-client-urls":["http://etcd2.etcd:2379"],"listen-client-urls":["http://0.0.0.0:2379"],"listen-metrics-urls":[],"local-address":"","cors":["*"],"host-whitelist":["*"],"initial-cluster":"etcd0=http://etcd0:2380,etcd1=http://etcd1:2380,etcd2=http://etcd2:2380","initial-cluster-state":"new","initial-cluster-token":"etcd-cluster-1","quota-backend-bytes":2147483648,"max-request-bytes":1572864,"max-concurrent-streams":4294967295,"pre-vote":true,"feature-gates":"","initial-corrupt-check":false,"corrupt-check-time-interval":"0s","compact-check-time-interval":"1m0s","auto-compaction-mode":"periodic","auto-compaction-retention":"0s","auto-compaction-interval":"0s","discovery-token":"","discovery-endpoints":"","discovery-dial-timeout":"2s","discovery-request-timeout":"5s","discovery-keepalive-time":"2s","discovery-keepalive-timeout":"6s","discovery-insecure-transport":true,"discovery-insecure-skip-tls-verify":false,"discovery-cert":"","discovery-key":"","discovery-cacert":"","discovery-user":"","downgrade-check-interval":"5s","max-learners":1,"v2-deprecation":"write-only"}

This means it's not necessarily caused by low snapshot-count.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.