Error: http request timed out

[iprigger]

All,

Since ~one week it's really frustrating with PBS. I get tons of failed backups with the below error:

ERROR: Backup of VM XXY failed - proxmox-backup-client failed: Error: http request timed out

There have not been any network nor any server changes in the last 6-8 weeks. I do updates on a regular basis - and the servers concerning have been restarted since the first occurrence of this error.

Although I have >7 PVE Servers there is a maximum of two backups running at the same time... all servers are connected using 10GBE.

The error itself would only be half as bad but in some of those occurrences the VM being backed up during this error hangs (I already shredded a postgresql db because of this).

VERY annoying. VERY frustrating. VERY dangerous.

I will have to revert back to the vzdump backups if this doesn't clear up...

Kind Regards
Tobias

 

[t.lamprecht]

Hi,

can you please post your pveversion -v and proxmox-backup-manager versions --verbose (both available also over the webinterface).

It may be that you run an older QEMU version which has this issue.

Although I have >7 PVE Servers there is a maximum of two backups running at the same time... all servers are connected using 10GBE.

All LAN connected (i.e., very low latency?).

How does the PBS servers storage looks like?

 

[iprigger]

Hi,

can you please post your pveversion -v and proxmox-backup-manager versions --verbose (both available also over the webinterface).

It may be that you run an older QEMU version which has this issue.

All LAN connected (i.e., very low latency?).

How does the PBS servers storage looks like?

Hi Tom,

Should be on the newest version... but let's see.

Proxmox Version:

proxmox-ve: 6.3-1 (running kernel: 5.4.73-1-pve)
pve-manager: 6.3-3 (running version: 6.3-3/eee5f901)
pve-kernel-5.4: 6.3-3
pve-kernel-helper: 6.3-3
pve-kernel-5.3: 6.1-6
pve-kernel-5.4.78-2-pve: 5.4.78-2
pve-kernel-5.4.73-1-pve: 5.4.73-1
pve-kernel-4.15: 5.4-8
pve-kernel-5.3.18-3-pve: 5.3.18-3
pve-kernel-4.15.18-20-pve: 4.15.18-46
pve-kernel-4.15.18-12-pve: 4.15.18-36
ceph-fuse: 12.2.13-pve1
corosync: 3.1.0-pve1
criu: 3.11-3
glusterfs-client: 5.5-3
ifupdown: residual config
ifupdown2: 3.0.0-1+pve3
ksm-control-daemon: 1.3-1
libjs-extjs: 6.0.1-10
libknet1: 1.20-pve1
libproxmox-acme-perl: 1.0.7
libproxmox-backup-qemu0: 1.0.2-1
libpve-access-control: 6.1-3
libpve-apiclient-perl: 3.1-3
libpve-common-perl: 6.3-2
libpve-guest-common-perl: 3.1-4
libpve-http-server-perl: 3.1-1
libpve-storage-perl: 6.3-4
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 4.0.3-1
lxcfs: 4.0.6-pve1
novnc-pve: 1.1.0-1
proxmox-backup-client: 1.0.8-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.4-3
pve-cluster: 6.2-1
pve-container: 3.3-2
pve-docs: 6.3-1
pve-edk2-firmware: 2.20200531-1
pve-firewall: 4.1-3
pve-firmware: 3.1-3
pve-ha-manager: 3.1-1
pve-i18n: 2.2-2
pve-qemu-kvm: 5.1.0-8
pve-xtermjs: 4.7.0-3
qemu-server: 6.3-3
smartmontools: 7.1-pve2
spiceterm: 3.1-1
vncterm: 1.6-2
zfsutils-linux: 0.8.5-pve1

And proxmox backup:

proxmox-backup             1.0-4        running kernel: 5.9.11-1
proxmox-backup-server      1.0.8-1      running version: 1.0.8
pve-kernel-5.4             6.3-3
pve-kernel-helper          6.3-3
pve-kernel-libc-dev        5.9.11-1
pve-kernel-5.4.78-2-pve    5.4.78-2
pve-kernel-5.4.65-1-pve    5.4.65-1
ifupdown2                  3.0.0-1+pve3
libjs-extjs                6.0.1-10
proxmox-backup-docs        1.0.8-1
proxmox-backup-client      1.0.8-1
proxmox-mini-journalreader 1.1-1
proxmox-widget-toolkit     2.4-4
pve-xtermjs                4.7.0-3
smartmontools              7.1-pve2
zfsutils-linux             0.8.5-pve1

All LAN-Connected (multiple 10G), Storage is an internal SATA RAID with currently 2x 4TB. I do have some repositories on a CIFS Mounted NAS (10Gig as well). The one that failed here is the internal storage...

CU
Tobias

 

[aroundmyroom]

Same issues as Tobias and also same versions

Just looking through some logs



I cannot see at which point the http request timed out

Cause when I look for the backup itself

It states ok ..

 

[fabian]

the error is likely from the log upload, which happens after the backup itself has been finalized.. do the affected snapshots contain a client log file?

 

[aroundmyroom]

how to find the client log file? than I can check

This is what I see from PBS



2021-02-23T10:08:06+01:00: starting new backup on datastore 'Store1': "ct/101/2021-02-23T09:08:00Z"
2021-02-23T10:08:06+01:00: download 'index.json.blob' from previous backup.
2021-02-23T10:08:06+01:00: add blob "/Backups/ct/101/2021-02-23T09:08:00Z/pct.conf.blob" (276 bytes, comp: 276)
2021-02-23T10:08:06+01:00: created new dynamic index 1 ("ct/101/2021-02-23T09:08:00Z/catalog.pcat1.didx")
2021-02-23T10:08:07+01:00: register chunks in 'root.pxar.didx' from previous backup.
2021-02-23T10:08:07+01:00: download 'root.pxar.didx' from previous backup.
2021-02-23T10:08:07+01:00: created new dynamic index 2 ("ct/101/2021-02-23T09:08:00Z/root.pxar.didx")
2021-02-23T10:11:04+01:00: Upload statistics for 'root.pxar.didx'
2021-02-23T10:11:04+01:00: UUID: 688487a6a72943058f1d262ab147c325
2021-02-23T10:11:04+01:00: Checksum: e4fe8100b1b1897cd02a6535c2bbc66ee0e94781a8b9b5b839b871439f381a0c
2021-02-23T10:11:04+01:00: Size: 1783293969
2021-02-23T10:11:04+01:00: Chunk count: 475
2021-02-23T10:11:04+01:00: Upload size: 181382206 (10%)
2021-02-23T10:11:04+01:00: Duplicates: 449+0 (94%)
2021-02-23T10:11:04+01:00: Compression: 27%
2021-02-23T10:11:04+01:00: successfully closed dynamic index 2
2021-02-23T10:11:04+01:00: Upload statistics for 'catalog.pcat1.didx'
2021-02-23T10:11:04+01:00: UUID: 6dc1c6de8c6941c7b8e00908002e6abf
2021-02-23T10:11:04+01:00: Checksum: 6651e67350c9a7a8f40aab89f3de0db0bdc539702a81b6ab84463425931a2371
2021-02-23T10:11:04+01:00: Size: 824323
2021-02-23T10:11:04+01:00: Chunk count: 2
2021-02-23T10:11:04+01:00: Upload size: 824323 (100%)
2021-02-23T10:11:04+01:00: Compression: 36%
2021-02-23T10:11:04+01:00: successfully closed dynamic index 1
2021-02-23T10:11:04+01:00: add blob "/Backups/ct/101/2021-02-23T09:08:00Z/index.json.blob" (372 bytes, comp: 372)
2021-02-23T10:11:04+01:00: successfully finished backup
2021-02-23T10:11:04+01:00: backup finished successfully
2021-02-23T10:11:04+01:00: TASK OK

and the verification




Task viewer: Datastore Store1:ct/101/6034C5F0 - Verification

OutputStatus

Stop
2021-02-23T10:11:04+01:00: Automatically verifying newly added snapshot
2021-02-23T10:11:04+01:00: verify Store1:ct/101/2021-02-23T09:08:00Z
2021-02-23T10:11:04+01:00: check pct.conf.blob
2021-02-23T10:11:04+01:00: check root.pxar.didx
2021-02-23T10:13:00+01:00: verified 817.49/1674.33 MiB in 116.10 seconds, speed 7.04/14.42 MiB/s (0 errors)
2021-02-23T10:13:00+01:00: check catalog.pcat1.didx
2021-02-23T10:13:01+01:00: verified 0.29/0.79 MiB in 0.12 seconds, speed 2.36/6.40 MiB/s (0 errors)
2021-02-23T10:13:01+01:00: TASK OK

 

[elterminatore]

Same Issue here (sporadically for a few days):

1001: 2021-02-24 01:45:02 INFO: Starting Backup of VM 1001 (qemu)
1001: 2021-02-24 01:45:02 INFO: status = running
1001: 2021-02-24 01:45:02 INFO: VM Name: xx.xx.xx.xx.xx
1001: 2021-02-24 01:45:02 INFO: include disk 'scsi0' 'ssd_vm:vm-1001-disk-0' 8G
1001: 2021-02-24 01:45:02 INFO: backup mode: snapshot
1001: 2021-02-24 01:45:02 INFO: bandwidth limit: 8000 KB/s
1001: 2021-02-24 01:45:02 INFO: ionice priority: 7
1001: 2021-02-24 01:45:02 INFO: creating Proxmox Backup Server archive 'vm/1001/2021-02-24T00:45:02Z'
1001: 2021-02-24 01:45:02 INFO: enabling encryption
1001: 2021-02-24 01:45:03 INFO: started backup task 'da6021f2-064e-4242-9e02-78d6d2a262e5'
1001: 2021-02-24 01:45:03 INFO: resuming VM again
1001: 2021-02-24 01:45:03 INFO: scsi0: dirty-bitmap status: OK (140.0 MiB of 8.0 GiB dirty)
1001: 2021-02-24 01:45:03 INFO: using fast incremental mode (dirty-bitmap), 140.0 MiB dirty of 8.0 GiB total
1001: 2021-02-24 01:45:06 INFO: 17% (24.0 MiB of 140.0 MiB) in 3s, read: 8.0 MiB/s, write: 2.7 MiB/s
1001: 2021-02-24 01:45:09 INFO: 37% (52.0 MiB of 140.0 MiB) in 6s, read: 9.3 MiB/s, write: 6.7 MiB/s
1001: 2021-02-24 01:45:12 INFO: 48% (68.0 MiB of 140.0 MiB) in 9s, read: 5.3 MiB/s, write: 5.3 MiB/s
1001: 2021-02-24 01:45:15 INFO: 62% (88.0 MiB of 140.0 MiB) in 12s, read: 6.7 MiB/s, write: 6.7 MiB/s
1001: 2021-02-24 01:45:18 INFO: 77% (108.0 MiB of 140.0 MiB) in 15s, read: 6.7 MiB/s, write: 6.7 MiB/s
1001: 2021-02-24 01:45:21 INFO: 94% (132.0 MiB of 140.0 MiB) in 18s, read: 8.0 MiB/s, write: 8.0 MiB/s
1001: 2021-02-24 01:45:23 INFO: 100% (140.0 MiB of 140.0 MiB) in 20s, read: 4.0 MiB/s, write: 4.0 MiB/s
1001: 2021-02-24 01:45:23 INFO: backup was done incrementally, reused 7.89 GiB (98%)
1001: 2021-02-24 01:45:23 INFO: transferred 140.00 MiB in 20 seconds (7.0 MiB/s)
1001: 2021-02-24 01:45:43 ERROR: Backup of VM 1001 failed - proxmox-backup-client failed: Error: http request timed out

I can't say which pveversion numbers because i've updated 20 minutes before this post. (These must be the versions that were current until yesterday)

Cheerz

 

[fabian]

you can see whether a client log is included by looking at the files contained in a backup snapshot (e.g., in the PBS GUI, datastore -> content -> expand group, expand snapshot)

 

[elterminatore]

nope... the client log is not included when the job failed with this error:



two days before, the client log is available. but i can't view or download it even though a download button is present. the "size" column is also empty for the client log

 

[fabian]

thanks! are you monitoring the PVE/PBS systems? if so, anything interesting visible around the time of the failed log upload? network latency/load, system load would be especially interesting.. how are the two connected?

we'll likely bump the request timeouts and make a client log upload failure non-fatal on the PVE side..

 

[elterminatore]

no monitoring :-(
but also no changes in the whole system. it's running since the first pbs beta.
pbs is running as a vm too. the datastore is connected via iscsi on a freenas box.
its a small 3-node cluster with ceph and identical hardware.
in the past, very rare i got the error "qmp command 'backup' failed - got timeout" for a few vms.
but since one or two weeks i get nearly daily "proxmox-backup-client failed: Error: http request timed out" for a few vms. now when i looked this up, i noticed that these errors only came from one of the three hosts. today i installed all fresh updates and rebooted... maybe it helped.

 

[elterminatore]

two days before, the client log is available. but i can't view or download it even though a download button is present. the "size" column is also empty for the client log

is that right ? there is a download button but no download available? where can i take a look into the client log on pbs?

 

[fabian]

for encrypted backups, the client log is currently broken (https://bugzilla.proxmox.com/show_bug.cgi?id=3285). it's stored correctly, but both the GUI (does not know it's encrypted, so attempts a decode+download which does not work) and the client (only works on regular files referenced directly in the archive, and the log is special as it's added after the backup has been finalized) can't handle it..

 

[aroundmyroom]

here also the client log file not stored.
Initially I had 3 concurrent backups at one time from my cluster (every machine at same time) but due to previous issues I backup machine by machine, and lxc/vm after lxc/vm I have about 5 to 8 LXC/VMs on that machine some are good and some fail. And its during the day as there is not much going on over that network. if it would an issue on the network it would not be only the client log

 

[fabian]

https://git.proxmox.com/?p=proxmox-backup.git;a=commit;h=a941bbd0c9dfd2dd804780658f17c4f6e154efe2 the timeout got raised in git already, so the next released versions of proxmox-backup-client (>1.0.8) and libproxmox-backup-qemu0 (>1.0.3) should not exhibit this behaviour anymore..

 

[elterminatore]

https://git.proxmox.com/?p=proxmox-backup.git;a=commit;h=a941bbd0c9dfd2dd804780658f17c4f6e154efe2 the timeout got raised in git already, so the next released versions of proxmox-backup-client (>1.0.8) and libproxmox-backup-qemu0 (>1.0.3) should not exhibit this behaviour anymore..

was the timeout behavior changed in a previous version?

 

[t.lamprecht]

was the timeout behavior changed in a previous version?

Yes, there was none before https://git.proxmox.com/?p=proxmox-backup.git;a=commit;h=4799280ccd87d04602e50768e50bce2f804c4cae leading to some indefinite hangs in certain edge cases.

 

[iprigger]

thanks! are you monitoring the PVE/PBS systems? if so, anything interesting visible around the time of the failed log upload? network latency/load, system load would be especially interesting.. how are the two connected?

we'll likely bump the request timeouts and make a client log upload failure non-fatal on the PVE side..

Hi,

Yes I am... and no, there is nothing out of the ordinary... Even when I try a single vm backup it fails with the same error.

Tobias

 

[aroundmyroom]

can confirm today that my backup now shows all OK in the email after todays updates which were pushed the last 1 or 2 days ..
so the issue with the time-out probably solved it

 

[t.lamprecht]

Thanks for your feedback!