Sporadic error when saving snapshots: unexpected EOF

[lomori]

When filing a bug, please include the following headings if possible. Any example text in this template can be deleted.

Overview of the Issue

I keep getting random errors when creating backups of our Consul.

$ consul snapshot save /consul/data/20191206120000-1.snap
Error verifying snapshot file: failed to read snapshot file: failed to read or write snapshot data: unexpected EOF

Reproduction Steps

Just keep creating snapshots and you can see that it sometimes fails.

$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068184
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068185
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068186
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068186
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068188
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068188
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068188
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068188
$ consul snapshot save /consul/data/20191206120000-1.snap
Error verifying snapshot file: failed to read snapshot file: failed to read or write snapshot data: unexpected EOF
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068194
$ consul snapshot save /consul/data/20191206120000-1.snap
Saved and verified snapshot to index 1068195

Consul info for both Client and Server

$ consul version
Consul v1.6.1
Protocol 2 spoken by default, understands 2 to 3 (agent will automatically use protocol >2 when speaking to compatible agents)

Client info

output from client 'consul info' command here

Server info

agent:
        check_monitors = 0
        check_ttls = 3
        checks = 3
        services = 3
build:
        prerelease =
        revision = 9be6dfc3
        version = 1.6.1
consul:
        acl = disabled
        bootstrap = false
        known_datacenters = 1
        leader = false
        leader_addr = 10.129.8.88:8300
        server = true
raft:
        applied_index = 1068318
        commit_index = 1068318
        fsm_pending = 0
        last_contact = 10.52169ms
        last_log_index = 1068318
        last_log_term = 332
        last_snapshot_index = 1061622
        last_snapshot_term = 332
        latest_configuration = [{Suffrage:Voter ID:faea4c4e-2b87-83af-b831-9b3fe9b34c58 Address:10.131.12.242:8300} {Suffrage:Voter ID:a1b1991e-8f46-45b6-a09f-3c3cd1155bba Address:10.130.13.199:8300} {Suffrage:Voter ID:3261cc81-307f-c0be-3e7a-e224704bf2a3 Address:10.129.8.88:8300} {Suffrage:Voter ID:a12d5052-dc73-b1af-ed86-313e6c0d038c Address:10.130.6.140:8300} {Suffrage:Voter ID:14e82d1e-a6f2-eba8-d2ff-cc648a5daaac Address:10.129.12.38:8300}]
        latest_configuration_index = 1047983
        num_peers = 4
        protocol_version = 3
        protocol_version_max = 3
        protocol_version_min = 0
        snapshot_version_max = 1
        snapshot_version_min = 0
        state = Follower
        term = 332
runtime:
        arch = amd64
        cpu_count = 4
        goroutines = 92
        max_procs = 4
        os = linux
        version = go1.12.1
serf_lan:
        coordinate_resets = 0
        encrypted = true
        event_queue = 0
        event_time = 19
        failed = 0
        health_score = 0
        intent_queue = 0
        left = 0
        member_time = 137
        members = 5
        query_queue = 0
        query_time = 1
serf_wan:
        coordinate_resets = 0
        encrypted = true
        event_queue = 0
        event_time = 1
        failed = 0
        health_score = 0
        intent_queue = 0
        left = 0
        member_time = 193
        members = 5
        query_queue = 0
        query_time = 1

Operating system and Environment details

OS, Architecture, and any other information you can provide about the environment.

Log Fragments

Include appropriate Client or Server log fragments. If the log is longer than a few dozen lines, please include the URL to the gist of the log instead of posting it in the issue. Use -log-level=TRACE on the client and server to capture the maximum log detail.

[benumbed]

This happens to me on 1.6.2 on Arm64. It was also happening on a different cluster that's on amd64 before I upgraded that cluster to 1.6.2, now all is quiet on that front.

Errors from the logs of the member which requested the snapshot:

2019/12/07 00:00:02 [ERR] http: Request GET /v1/snapshot, error: failed to stream snapshot: read tcp 172.xx.xx.xx:57649->172.xx.xx.xx:8300: read: connection reset by peer from=127.0.0.1:42446
http: Request GET /v1/snapshot, error: failed to stream snapshot: read tcp 172.xx.xx.xx:57649->172.xx.xx.xx:8300: read: connection reset by peer from=127.0.0.1:42446

The cluster leader's logs look normal:

2019/12/07 00:00:02 [INFO] consul.fsm: snapshot created in 182.885µs
2019/12/07 00:00:02 [INFO]  raft: Starting snapshot up to 164365
2019/12/07 00:00:02 [INFO] snapshot: Creating new snapshot at /var/lib/consul/data/raft/snapshots/940-164365-1575705602005.tmp
 consul.fsm: snapshot created in 182.885µs
 raft: Starting snapshot up to 164365
 snapshot: Creating new snapshot at /var/lib/consul/data/raft/snapshots/940-164365-1575705602005.tmp
2019/12/07 00:00:02 [INFO] snapshot: reaping snapshot /var/lib/consul/data/raft/snapshots/933-163151-1575698401708
 snapshot: reaping snapshot /var/lib/consul/data/raft/snapshots/933-163151-1575698401708
2019/12/07 00:00:02 [INFO]  raft: Compacting logs from 153522 to 154125
  raft: Compacting logs from 153522 to 154125
2019/12/07 00:00:02 [INFO]  raft: Snapshot to 164365 complete
 raft: Snapshot to 164365 complete

Something additional that's interesting. For the failed snapshots, every single one of them has the same exact size 32871, a little over a hundred bytes over 32K.

Example:

-rw-r----- 1 consul consul 85640 Dec 6 14:00 20191206-1400.snap
-rw-r----- 1 consul consul 32871 Dec 6 16:00 20191206-1600.snap
-rw-r----- 1 consul consul 85635 Dec 6 18:00 20191206-1800.snap
-rw-r----- 1 consul consul 32871 Dec 6 20:00 20191206-2000.snap
-rw-r----- 1 consul consul 32871 Dec 6 21:00 20191206-2100.snap
-rw-r----- 1 consul consul 32871 Dec 7 00:00 20191207-0000.snap

All the numbers around 85K are good snapshots, the rest are failures.

This does not seem to happen on the cluster leader, just the follower nodes.

[danlsgiga]

Having the same issue on 1.7.1... here's the output of the same command ran 3 times consecutively

[root@server server]# CONSUL_HTTP_TOKEN=my-token ./bin/consul snapshot save consul.snapshot
Error verifying snapshot file: failed to read snapshot file: failed to read or write snapshot data: unexpected EOF
[root@server server]# CONSUL_HTTP_TOKEN=my-token ./bin/consul snapshot save consul.snapshot
Error saving snapshot: Unexpected response code: 500 (failed to decode response: read tcp 192.168.0.1:60444->192.168.0.2:8300: read: connection reset by peer)
[root@server server]# CONSUL_HTTP_TOKEN=my-token ./bin/consul snapshot save consul.snapshot
Saved and verified snapshot to index 23436477

[agaudreault]

It also happens on Consul v1.6.4

[ChipV223]

Hi all!

Just wanted to check anyone has seen this issue when trying to create snapshots since the release of v1.7.3, which includes the following pull request that address this error.

[ChipV223]

Hi all!

Closing this as I just tried to repro this behavior with v1.9.4 by running a watch command that saved a consul snapshot every 3 seconds for 20 minutes. But do feel to re-open if you see this behavior in any of the more recent Consul releases

[wsams]

For what it's worth this is occurring in k8s 1.19 with the consul-helm chart. Consul 1.9.3

ERROR] agent.http: Request error: method=GET url=/v1/snapshot from=10.200.90.8:51322 error="failed to stream snapshot: read tcp 10.200.87.97:48112->10.200.54.76:8300: read: connection reset by peer"

[drewby08]

I'm seeing very similar behavior while running the snapshot in agent mode under Consul Enterprise 1.9.3

2021-06-16T15:12:05.528-0400 [INFO]  snapshot.license: Automated Backups feature is now licensed
2021-06-16T15:12:05.532-0400 [INFO]  license: Consul license updated
2021-06-16T15:12:05.554-0400 [INFO]  snapshot: Waiting to obtain leadership...
2021-06-16T15:12:05.570-0400 [INFO]  snapshot: Obtained leadership
2021-06-16T15:12:11.003-0400 [ERROR] snapshot: Snapshot failed (will retry at next interval): error="snapshot verification failed: failed to read snapshot file: failed to read or write snapshot data: unexpected EOF"
2021-06-16T16:06:59.728-0400 [WARN]  snapshot: Lost leadership, stopping snapshots
2021-06-16T16:06:59.749-0400 [INFO]  snapshot: Waiting to obtain leadership...
2021-06-16T16:06:59.750-0400 [ERROR] snapshot: Unable to use leader lock that was held previously and presumed lost, giving up the lock (will retry): error="Lock already held"
2021-06-16T16:06:59.752-0400 [ERROR] snapshot: Error trying to fetch lock key: error="Unexpected response code: 500"

[shomeprasanjit]

we are using consul 1.8.0 as pods using the helm chart deployment and while performing snapshot save and restore, we got the same error

Error verifying snapshot file: failed to read snapshot file: failed to read or write snapshot data: unexpected EOF

is there a fix for this yet?

Also for the workaround, can anyone verify if taking snapshot from the leader solves the problem?

@ChipV223 please re-open this issue since this is not fixed.

[Amier3]

Thanks for re-opening this @ChipV223!

This seems like a strange issue and persistent issue. I mentioned this issue to a few of the other engineers, and the recent activity on this being focused on consul in k8s leads us to believe it could be a PV issue...

Also, @benumbed noted that:

For the failed snapshots, every single one of them has the same exact size 32871, a little over a hundred bytes over 32K.

Which is making us wonder if this issue only occurs at this exact size ( or at a different, but consistent size ) for others. So my questions to @shomeprasanjit , @wsams , and @drewby08 would be:

• Are you using consul in containers? and if so how are you all handling PVs?
• Are all the failed snapshots you all are seeing the exact same size in bytes?

[shomeprasanjit]

@Amier3: Thanks for following up.

Here are your answers:

Are you using consul in containers? and if so how are you all handling PVs?

Ans) Yes we are running consul as pods as a standard helm chart. we are using gp3 EBS volumes as persistent storage. this is controlled by StatefulSet.

Are all the failed snapshots you all are seeing the exact same size in bytes?

Ans) not sure exactly, it was probably in MB's but definitely not in bytes.