Problem with aborted copy

R

rootolf

Member
Mar 4, 2023
3
0
6
Hello,
I have a problem with the backup breaking.
The copy is done through a VPN tunnel (I also tried Wireguard, no change)
At random times I get the message:
ERROR: backup write data failed: command error: protocol canceled.
Where to look for the cause of the error (proxmox, link, backup server)?
Full copy log:
INFO: starting new backup job: vzdump 101 --prune-backups 'keep-all=1' --notes-template '{{guestname}}' --all 0 --mode stop --node pve --storage pbs-vps --mailnotification always
INFO: Starting Backup of VM 101 (qemu)
INFO: Backup started at 2025-06-16 14:35:59
INFO: status = stopped
INFO: backup mode: stop
INFO: ionice priority: 7
INFO: VM Name: windows-ok
INFO: include disk 'ide0' 'vm_4TB:101/vm-101-disk-0.raw' 461G
INFO: include disk 'ide1' 'vm_4TB:101/vm-101-disk-1.qcow2' 1725G
INFO: creating Proxmox Backup Server archive 'vm/101/2025-06-16T12:35:58Z'
INFO: starting kvm to execute backup task
INFO: enabling encryption
INFO: started backup task '727eb90c-99e6-44ed-8c49-e28aeee8bc91'
INFO: ide0: dirty-bitmap status: created new
INFO: ide1: dirty-bitmap status: created new
INFO: 0% (0.0 B of 2.1 TiB) in 3s, read: 0 B/s, write: 0 B/s
INFO: 1% (21.9 GiB of 2.1 TiB) in 55m 47s, read: 6.7 MiB/s, write: 6.6 MiB/s
INFO: 2% (43.7 GiB of 2.1 TiB) in 1h 52m 41s, read: 6.6 MiB/s, write: 6.6 MiB/s
INFO: 3% (65.6 GiB of 2.1 TiB) in 2h 34m 41s, read: 8.9 MiB/s, write: 6.5 MiB/s
INFO: 4% (87.4 GiB of 2.1 TiB) in 3h 18m 6s, read: 8.6 MiB/s, write: 6.5 MiB/s
INFO: 5% (109.3 GiB of 2.1 TiB) in 4h 14m 37s, read: 6.6 MiB/s, write: 6.6 MiB/s
INFO: 6% (131.2 GiB of 2.1 TiB) in 5h 10m 5s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 7% (153.0 GiB of 2.1 TiB) in 6h 5m 40s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 8% (174.9 GiB of 2.1 TiB) in 7h 1m 46s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 9% (196.7 GiB of 2.1 TiB) in 7h 58m 14s, read: 6.6 MiB/s, write: 6.6 MiB/s
INFO: 10% (218.6 GiB of 2.1 TiB) in 8h 54m 4s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 11% (240.5 GiB of 2.1 TiB) in 9h 49m 13s, read: 6.8 MiB/s, write: 6.7 MiB/s
INFO: 12% (262.3 GiB of 2.1 TiB) in 10h 15m 26s, read: 14.2 MiB/s, write: 6.2 MiB/s
INFO: 13% (284.2 GiB of 2.1 TiB) in 11h 11m 9s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 14% (306.0 GiB of 2.1 TiB) in 12h 6m 52s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 15% (327.9 GiB of 2.1 TiB) in 13h 1m 34s, read: 6.8 MiB/s, write: 6.8 MiB/s
INFO: 16% (349.8 GiB of 2.1 TiB) in 13h 57m 24s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 17% (371.6 GiB of 2.1 TiB) in 14h 53m 23s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 18% (393.5 GiB of 2.1 TiB) in 15h 49m 9s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 19% (415.4 GiB of 2.1 TiB) in 16h 44m 56s, read: 6.7 MiB/s, write: 6.7 MiB/s
INFO: 20% (437.2 GiB of 2.1 TiB) in 17h 42m 6s, read: 6.5 MiB/s, write: 6.5 MiB/s
INFO: 21% (459.1 GiB of 2.1 TiB) in 18h 36m 58s, read: 6.8 MiB/s, write: 6.8 MiB/s
INFO: 22% (480.9 GiB of 2.1 TiB) in 19h 35m 33s, read: 6.4 MiB/s, write: 6.4 MiB/s
INFO: 22% (481.0 GiB of 2.1 TiB) in 19h 35m 40s, read: 5.1 MiB/s, write: 5.1 MiB/s
ERROR: backup write data failed: command error: protocol canceled
INFO: aborting backup job
INFO: stopping kvm after backup task
ERROR: Backup of VM 101 failed - backup write data failed: command error: protocol canceled
INFO: Failed at 2025-06-17 10:12:03
INFO: Backup job finished with errors
TASK ERROR: job errors
Click to expand...

Proxmox: 7.4-18
Backup Server 3.4.1
 
Hi,
rootolf said:
Proxmox: 7.4-18
Click to expand...
as a first step I recommend to upgrade to the latest version, 7.4 is EOL since a long time.

Also, please share the corresponding backup task log on the PBS side, It might contain more information.
 
Hello,
thanks for reply, I am uploading the logs from PBS:
2025-06-16T14:36:20+02:00: download 'index.json.blob' from previous backup 'vm/101/2024-08-02T13:36:57Z'.
2025-06-16T14:36:20+02:00: register chunks in 'drive-ide0.img.fidx' from previous backup 'vm/101/2024-08-02T13:36:57Z'.
2025-06-16T14:36:20+02:00: download 'drive-ide0.img.fidx' from previous backup 'vm/101/2024-08-02T13:36:57Z'.
2025-06-16T14:36:20+02:00: created new fixed index 1 ("ns/Robin/vm/101/2025-06-16T12:35:58Z/drive-ide0.img.fidx")
2025-06-16T14:36:20+02:00: register chunks in 'drive-ide1.img.fidx' from previous backup 'vm/101/2024-08-02T13:36:57Z'.
2025-06-16T14:36:20+02:00: download 'drive-ide1.img.fidx' from previous backup 'vm/101/2024-08-02T13:36:57Z'.
2025-06-16T14:36:21+02:00: created new fixed index 2 ("ns/Robin/vm/101/2025-06-16T12:35:58Z/drive-ide1.img.fidx")
2025-06-16T14:36:21+02:00: add blob "/mnt/datastore/backup4TB/ns/Robin/vm/101/2025-06-16T12:35:58Z/qemu-server.conf.blob" (371 bytes, comp: 371)
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: backup failed: connection error: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: removing failed backup
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: POST /fixed_chunk: 400 Bad Request: error reading a body from connection: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
2025-06-17T10:12:00+02:00: removing backup snapshot "/mnt/datastore/backup4TB/ns/Robin/vm/101/2025-06-16T12:35:58Z"
2025-06-17T10:12:00+02:00: TASK ERROR: connection error: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:: error:0A000119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:622:
Click to expand...
 
You must log in or register to reply here.
Top Bottom