[PVE-User] vzdump backup timing out

Sat Nov 7 16:46:14 CET 2015

Hello, 

I'm having trouble with the vzdump backup process timing out. It works fine when I run backup manually, but when a scheduled run happens it times out every time. I'm running Proxmox 3.4-11. Here is the log file output 

VMID 	NAME 	STATUS 	TIME 	SIZE 	FILENAME 
101 	vm-101 
	FAILED 	00:12:07 	VM 101 qmp command 'query-backup' failed - got timeout 
102 	vm-102 
	FAILED 	01:24:37 	VM 102 qmp command 'query-backup' failed - got timeout 
TOTAL 	01:36:44 	0KB 	

Detailed backup logs: 

vzdump 101 102 --mailnotification always --quiet 1 --mailto user at email.com --mode snapshot --compress lzo --storage vmbackup

101: Nov 07 05:00:01 INFO: Starting Backup of VM 101 (qemu)
101: Nov 07 05:00:01 INFO: status = running
101: Nov 07 05:00:01 INFO: update VM 101: -lock backup
101: Nov 07 05:00:01 INFO: backup mode: snapshot
101: Nov 07 05:00:01 INFO: ionice priority: 7
101: Nov 07 05:00:01 INFO: snapshots found (not included into backup)
101: Nov 07 05:00:01 INFO: creating archive '/mnt/vmbackup/vmbackup/dump/vzdump-qemu-101-2015_11_07-05_00_01.vma.lzo'
101: Nov 07 05:00:01 INFO: started backup task '3570da3c-12cf-4729-9a2c-54d3ce6d5999'
101: Nov 07 05:00:04 INFO: status: 0% (89784320/966367641600), sparse 0% (18362368), duration 3, 29/23 MB/s
101: Nov 07 05:12:01 ERROR: VM 101 qmp command 'query-backup' failed - got timeout 101: Nov 07 05:12:01 INFO: aborting backup job
101: Nov 07 05:12:08 ERROR: Backup of VM 101 failed - VM 101 qmp command 'query-backup' failed - got timeout 102: Nov 07 05:12:08 INFO: Starting Backup of VM 102 (qemu)
102: Nov 07 05:12:08 INFO: status = running
102: Nov 07 05:12:08 INFO: update VM 102: -lock backup
102: Nov 07 05:12:08 INFO: backup mode: snapshot
102: Nov 07 05:12:08 INFO: ionice priority: 7
102: Nov 07 05:12:08 INFO: snapshots found (not included into backup)
102: Nov 07 05:12:08 INFO: creating archive '/mnt/vmbackup/vmbackup/dump/vzdump-qemu-102-2015_11_07-05_12_08.vma.lzo'
102: Nov 07 05:12:08 INFO: started backup task 'b68d833a-5d30-4c86-96af-7bc51eba2a40'
102: Nov 07 05:12:11 INFO: status: 0% (155910144/34359738368), sparse 0% (32190464), duration 3, 51/41 MB/s
102: Nov 07 05:12:14 INFO: status: 1% (480772096/34359738368), sparse 0% (257622016), duration 6, 108/33 MB/s
102: Nov 07 05:12:19 INFO: status: 2% (757596160/34359738368), sparse 0% (327237632), duration 11, 55/41 MB/s
102: Nov 07 05:12:24 INFO: status: 3% (1072496640/34359738368), sparse 1% (442957824), duration 16, 62/39 MB/s
102: Nov 07 05:12:27 INFO: status: 4% (1520762880/34359738368), sparse 2% (778567680), duration 19, 149/37 MB/s
102: Nov 07 05:12:30 INFO: status: 6% (2307260416/34359738368), sparse 4% (1399537664), duration 22, 262/55 MB/s
102: Nov 07 05:12:33 INFO: status: 15% (5380374528/34359738368), sparse 12% (4320960512), duration 25, 1024/50 MB/s
102: Nov 07 05:12:36 INFO: status: 16% (5709234176/34359738368), sparse 12% (4320960512), duration 28, 109/109 MB/s
102: Nov 07 05:12:39 INFO: status: 17% (6025576448/34359738368), sparse 12% (4320960512), duration 31, 105/105 MB/s
102: Nov 07 05:12:42 INFO: status: 18% (6337789952/34359738368), sparse 12% (4320960512), duration 34, 104/104 MB/s
102: Nov 07 05:12:45 INFO: status: 19% (6534725632/34359738368), sparse 12% (4321046528), duration 37, 65/65 MB/s
102: Nov 07 05:12:49 INFO: status: 20% (6898581504/34359738368), sparse 12% (4451659776), duration 41, 90/58 MB/s
102: Nov 07 05:12:54 INFO: status: 21% (7218397184/34359738368), sparse 12% (4453482496), duration 46, 63/63 MB/s
102: Nov 07 05:12:58 INFO: status: 22% (7628783616/34359738368), sparse 12% (4453482496), duration 50, 102/102 MB/s
102: Nov 07 05:13:01 INFO: status: 23% (7951286272/34359738368), sparse 12% (4453539840), duration 53, 107/107 MB/s
102: Nov 07 05:13:04 INFO: status: 24% (8299151360/34359738368), sparse 12% (4453539840), duration 56, 115/115 MB/s
102: Nov 07 05:13:07 INFO: status: 25% (8620933120/34359738368), sparse 12% (4453539840), duration 59, 107/107 MB/s
102: Nov 07 05:13:11 INFO: status: 26% (9005498368/34359738368), sparse 13% (4578058240), duration 63, 96/65 MB/s
102: Nov 07 05:13:15 INFO: status: 27% (9389604864/34359738368), sparse 14% (4811132928), duration 67, 96/37 MB/s
102: Nov 07 05:13:18 INFO: status: 32% (11152326656/34359738368), sparse 18% (6514954240), duration 70, 587/19 MB/s
102: Nov 07 05:13:22 INFO: status: 37% (12923699200/34359738368), sparse 23% (8167755776), duration 74, 442/29 MB/s
102: Nov 07 05:13:25 INFO: status: 44% (15330770944/34359738368), sparse 30% (10496708608), duration 77, 802/26 MB/s
102: Nov 07 05:13:28 INFO: status: 45% (15584067584/34359738368), sparse 30% (10590322688), duration 80, 84/53 MB/s
102: Nov 07 05:13:31 INFO: status: 51% (17590910976/34359738368), sparse 36% (12529782784), duration 83, 668/22 MB/s
102: Nov 07 05:13:37 INFO: status: 52% (18109235200/34359738368), sparse 37% (12835610624), duration 89, 86/35 MB/s
102: Nov 07 05:13:40 INFO: status: 63% (21735669760/34359738368), sparse 47% (16426790912), duration 92, 1208/11 MB/s
102: Nov 07 05:13:43 INFO: status: 69% (24018681856/34359738368), sparse 54% (18647670784), duration 95, 761/20 MB/s
102: Nov 07 05:13:46 INFO: status: 70% (24122163200/34359738368), sparse 54% (18647748608), duration 98, 34/34 MB/s
102: Nov 07 05:13:54 INFO: status: 71% (24424153088/34359738368), sparse 54% (18647949312), duration 106, 37/37 MB/s
102: Nov 07 05:14:01 INFO: status: 72% (24744361984/34359738368), sparse 54% (18655653888), duration 113, 45/44 MB/s
102: Nov 07 05:14:11 INFO: status: 73% (25091178496/34359738368), sparse 54% (18660720640), duration 123, 34/34 MB/s
102: Nov 07 05:14:19 INFO: status: 74% (25450774528/34359738368), sparse 54% (18667048960), duration 131, 44/44 MB/s
102: Nov 07 05:14:25 INFO: status: 75% (25770065920/34359738368), sparse 54% (18693558272), duration 137, 53/48 MB/s
102: Nov 07 05:14:32 INFO: status: 76% (26179338240/34359738368), sparse 54% (18852700160), duration 144, 58/35 MB/s
102: Nov 07 05:14:36 INFO: status: 77% (26544570368/34359738368), sparse 54% (18874642432), duration 148, 91/85 MB/s
102: Nov 07 05:14:39 INFO: status: 78% (27035369472/34359738368), sparse 55% (19177672704), duration 151, 163/62 MB/s
102: Nov 07 05:14:42 INFO: status: 79% (27337424896/34359738368), sparse 55% (19177672704), duration 154, 100/100 MB/s
102: Nov 07 05:14:45 INFO: status: 80% (27601862656/34359738368), sparse 55% (19180879872), duration 157, 88/87 MB/s
102: Nov 07 06:36:38 ERROR: VM 102 qmp command 'query-backup' failed - got timeout 102: Nov 07 06:36:38 INFO: aborting backup job
102: Nov 07 06:36:45 ERROR: Backup of VM 102 failed - VM 102 qmp command 'query-backup' failed - got timeout 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.proxmox.com/pipermail/pve-user/attachments/20151107/88250fcd/attachment.htm>