[Solved] Backup Failed

[bhennigar]

A few months ago, I started receiving an error message saying 1 or 2 VM's failed to backup 1-3 times a week. The error message is "ERROR: Backup of VM 105 failed - vma_co_write write error - Broken pipe". I found one thread with this problem and it seemed that updating proxmox to the latest version would correct it. I was on 3.0. I had a chance last week to shut everything down to upgrade to 3.1 and for the past week, my backups have all been running perfectly. This morning when I arrived and checked my email, I found that 1 VM failed to backup with the same error message as before. This VM had been backing up successfully ever night before the 3.1 upgrade.

Info about my backup: Backups are going to a locally attached USB hard drive. I added it to fstab as /dev/sdc1 /mnt/usb ext4 defaults 0 0

Error Log

vzdump 105 --quiet 1 --mailto myemails@mydomain.com --mode snapshot --compress lzo --storage backup-5

105: Dec 06 22:30:04 INFO: Starting Backup of VM 105 (qemu)
105: Dec 06 22:30:04 INFO: status = running
105: Dec 06 22:30:05 INFO: update VM 105: -lock backup
105: Dec 06 22:30:06 INFO: backup mode: snapshot
105: Dec 06 22:30:06 INFO: ionice priority: 7
105: Dec 06 22:30:06 INFO: creating archive '/mnt/usb/prox1/dump/vzdump-qemu-105-2013_12_06-22_30_03.vma.lzo'
105: Dec 06 22:30:06 INFO: started backup task 'f22f1069-0d6a-42ab-b09b-b8abec046366'
105: Dec 06 22:30:09 INFO: status: 0% (250019840/375809638400), sparse 0% (89997312), duration 3, 83/53 MB/s
105: Dec 06 22:30:58 INFO: status: 1% (3785424896/375809638400), sparse 0% (164864000), duration 52, 72/70 MB/s
105: Dec 06 22:31:47 INFO: status: 2% (7590903808/375809638400), sparse 0% (207331328), duration 101, 77/76 MB/s
105: Dec 06 22:32:15 INFO: status: 3% (11331895296/375809638400), sparse 0% (310702080), duration 129, 133/129 MB/s
105: Dec 06 22:32:52 INFO: status: 4% (15192752128/375809638400), sparse 0% (346030080), duration 166, 104/103 MB/s
105: Dec 06 22:33:24 INFO: status: 5% (18821414912/375809638400), sparse 0% (377634816), duration 198, 113/112 MB/s
105: Dec 06 22:34:10 INFO: status: 6% (22567714816/375809638400), sparse 0% (408408064), duration 244, 81/80 MB/s
105: Dec 06 22:34:53 INFO: status: 7% (26409959424/375809638400), sparse 0% (442224640), duration 287, 89/88 MB/s
105: Dec 06 22:35:32 INFO: status: 8% (30146428928/375809638400), sparse 0% (478523392), duration 326, 95/94 MB/s
105: Dec 06 22:35:58 INFO: status: 9% (33929953280/375809638400), sparse 0% (522891264), duration 352, 145/143 MB/s
105: Dec 06 22:36:25 INFO: status: 10% (37644795904/375809638400), sparse 0% (538243072), duration 379, 137/137 MB/s
105: Dec 06 22:36:52 INFO: status: 11% (41412460544/375809638400), sparse 0% (590237696), duration 406, 139/137 MB/s
105: Dec 06 22:37:04 INFO: status: 12% (45524647936/375809638400), sparse 1% (4047892480), duration 418, 342/54 MB/s
105: Dec 06 22:37:10 INFO: status: 13% (49427906560/375809638400), sparse 2% (7951151104), duration 424, 650/0 MB/s
105: Dec 06 22:37:15 INFO: status: 14% (52835385344/375809638400), sparse 3% (11358629888), duration 429, 681/0 MB/s
105: Dec 06 22:37:37 INFO: status: 15% (56504877056/375809638400), sparse 3% (12237139968), duration 451, 166/126 MB/s
105: Dec 06 22:38:13 INFO: status: 16% (60152479744/375809638400), sparse 3% (12245917696), duration 487, 101/101 MB/s
105: Dec 06 22:39:25 INFO: status: 17% (63930105856/375809638400), sparse 3% (12271726592), duration 559, 52/52 MB/s
105: Dec 06 22:40:36 INFO: status: 18% (67694755840/375809638400), sparse 3% (12275392512), duration 630, 53/52 MB/s
105: Dec 06 22:41:41 INFO: status: 19% (71419559936/375809638400), sparse 3% (12283990016), duration 695, 57/57 MB/s
105: Dec 06 22:42:47 INFO: status: 20% (75197972480/375809638400), sparse 3% (12284067840), duration 761, 57/57 MB/s
105: Dec 06 22:43:50 INFO: status: 21% (78964326400/375809638400), sparse 3% (12284067840), duration 824, 59/59 MB/s
105: Dec 06 22:44:59 INFO: status: 22% (82699681792/375809638400), sparse 3% (12284067840), duration 893, 54/54 MB/s
105: Dec 06 22:46:08 INFO: status: 23% (86468329472/375809638400), sparse 3% (12284125184), duration 962, 54/54 MB/s
105: Dec 06 22:47:17 INFO: status: 24% (90241630208/375809638400), sparse 3% (12301291520), duration 1031, 54/54 MB/s
105: Dec 06 22:48:50 INFO: status: 25% (93997367296/375809638400), sparse 3% (12331380736), duration 1124, 40/40 MB/s
105: Dec 06 22:49:54 INFO: status: 26% (97736720384/375809638400), sparse 3% (12404240384), duration 1188, 58/57 MB/s
105: Dec 06 22:50:58 INFO: status: 27% (101480726528/375809638400), sparse 3% (12412190720), duration 1252, 58/58 MB/s
105: Dec 06 22:52:05 INFO: status: 28% (105269035008/375809638400), sparse 3% (12415393792), duration 1319, 56/56 MB/s
105: Dec 06 22:53:20 INFO: status: 28% (108476366848/375809638400), sparse 3% (12415586304), duration 1394, 42/42 MB/s
105: Dec 06 22:53:20 ERROR: vma_co_write write error - Broken pipe
105: Dec 06 22:53:20 INFO: aborting backup job
105: Dec 06 22:53:26 ERROR: Backup of VM 105 failed - vma_co_write write error - Broken pipe

 

[mir]

Re: Backup Failed

Just a hunch: Do you use any kind of power-management which could instruct your disk to stop spinning? I guess that the slightest timeout could lead to a broken pipe. The backup job is running with ionice priority: 7 which means a power manager will have higher priority.

 

[bhennigar]

Re: Backup Failed

I don't have any kind of power-management other than what would be in Proxmox. I'm unfamiliar with ionice levels. If the priority changed, would it work better? If it is a power management issue, do you think it'd help to have a very tiny unconfigured openvz or kvm that it set to backup a couple of minutes before the production VMs just to get the USB drive to spin up first?

 

[bhennigar]

Re: Backup Failed

I found the problem and the solution is embarrassing.. The disk was out of space.