Proxmox-backup-proxy hang

thexa4

Member
Sep 24, 2015
8
2
23
I'm trying to backup containers to a PBS server but the backup seems to hang after uploading one container backup. It gets stuck after INFO: End Time: 2020-08-08T15:14:58+02:00

I've tried letting it run for a day but it made no progress. CPU usage on the backup server is low.

Code:
INFO: starting new backup job: vzdump 131 132 135 133 140 100 124 --quiet 1 --all 0 --mailnotification failure --mode snapshot --compress zstd --node pistol --storage zombie-internal1 --mailto <removed>
INFO: Starting Backup of VM 124 (lxc)
INFO: Backup started at 2020-08-08 14:31:03
INFO: status = running
INFO: CT Name: <removed>
INFO: including mount point rootfs ('/') in backup
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
/dev/rbd6
INFO: creating Proxmox Backup Server archive 'ct/124/2020-08-08T12:31:03Z'
INFO: run: lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup --crypt-mode=encrypt --keyfd=14 pct.conf:/var/tmp/vzdumptmp1984578/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --backup-type ct --backup-id 124 --backup-time 1596889863 --repository <removed>@pbs@<removed>:internal1
INFO: Starting backup: ct/124/2020-08-08T12:31:03Z
INFO: Client name: pistol
INFO: Starting protocol: 2020-08-08T14:31:05+02:00
INFO: Upload config file '/var/tmp/vzdumptmp1984578/etc/vzdump/pct.conf' to '<removed>@pbs@<removed>:internal1' as pct.conf.blob
INFO: Upload directory '/mnt/vzsnap0' to '<removed>@pbs@<removed>:internal1' as root.pxar.didx
INFO: root.pxar: had to upload 39.45 MiB of 93.68 GiB in 2631.80s, avgerage speed 15.35 KiB/s).
INFO: root.pxar: backup was done incrementally, reused 93.65 GiB (100.0%)
INFO: Uploaded backup catalog (1.10 MiB)
INFO: Duration: PT2632.556921212S
INFO: End Time: 2020-08-08T15:14:58+02:00

Code:
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: server checksum [109, 63, 118, 77, 128, 77, 176, 161, 252, 57, 167, 184, 173, 50, 223, 136, 22, 30, 134, 154, 139, 221, 104,
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Upload statistics for 'root.pxar.didx'
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: UUID: 98aba390fc164b3aaeeeb2ab5dddfdb8
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Checksum: 6d3f764d804db0a1fc39a7b8ad32df88161e869a8bdd68dd8fe9ebab5fc90209
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Size: 100592722923
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Chunk count: 25623
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Upload size: 41365581 (0%)
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Duplicates: 25616+0 (99%)
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: Compression: 46%
Aug 08 15:14:57 zombie proxmox-backup-proxy[23074]: successfully closed dynamic index 2
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: server checksum [40, 63, 164, 240, 153, 202, 72, 215, 152, 170, 222, 155, 10, 40, 202, 229, 197, 167, 184, 32, 196, 211, 67,
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Upload statistics for 'catalog.pcat1.didx'
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: UUID: c967099f9d284c17a0313e1ead9d6e4d
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Checksum: 283fa4f099ca48d798aade9b0a28cae5c5a7b820c4d3436825bc5afcf2e62fe7
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Size: 1156072
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Chunk count: 4
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Upload size: 1156072 (100%)
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Duplicates: 0+2 (50%)
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Compression: 31%
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: successfully closed dynamic index 1
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: add blob "/internal1/ct/124/2020-08-08T12:31:03Z/index.json.blob" (411 bytes, comp: 411)
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: successfully finished backup
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: backup finished successfully
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: TASK OK
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: Detected stopped UPID UPID:zombie:00005A22:00D31DDA:00000001:5F2E9B09:backup:internal1_ct_124:<removed>@pbs:
Aug 08 15:14:58 zombie proxmox-backup-proxy[23074]: unregister worker

While the backup job hangs, the PBS web interface gives a connection error overlay. Restarting the proxmox-backup-proxy service lets the task continue:
Code:
INFO: remove vzdump snapshot
2020-08-08 17:15:18.211 7f23ceffd700 -1 librbd::object_map::InvalidateRequest: 0x7f23d8008360 should_complete: r=0
Removing snap: 100% complete...done.
INFO: Finished Backup of VM 124 (02:44:16)
INFO: Backup finished at 2020-08-08 17:15:19
INFO: Starting Backup of VM 131 (lxc)
...

Is there anything I can do to debug this?

Code:
root@shandy:~# pveversion -v
proxmox-ve: 6.2-1 (running kernel: 5.4.44-2-pve)
pve-manager: 6.2-10 (running version: 6.2-10/a20769ed)
pve-kernel-5.4: 6.2-4
pve-kernel-helper: 6.2-4
pve-kernel-5.3: 6.1-6
pve-kernel-5.0: 6.0-11
pve-kernel-5.4.44-2-pve: 5.4.44-2
pve-kernel-5.4.44-1-pve: 5.4.44-1
pve-kernel-5.4.41-1-pve: 5.4.41-1
pve-kernel-4.15: 5.4-6
pve-kernel-5.3.18-3-pve: 5.3.18-3
pve-kernel-5.3.13-1-pve: 5.3.13-1
pve-kernel-5.3.10-1-pve: 5.3.10-1
pve-kernel-5.0.21-5-pve: 5.0.21-10
pve-kernel-5.0.21-3-pve: 5.0.21-7
pve-kernel-5.0.21-2-pve: 5.0.21-7
pve-kernel-4.15.18-18-pve: 4.15.18-44
pve-kernel-4.13.13-2-pve: 4.13.13-33
ceph: 14.2.10-pve1
ceph-fuse: 14.2.10-pve1
corosync: 3.0.4-pve1
criu: 3.11-3
glusterfs-client: 5.5-3
ifupdown: residual config
ifupdown2: 3.0.0-1+pve2
ksm-control-daemon: 1.3-1
libjs-extjs: 6.0.1-10
libknet1: 1.16-pve1
libproxmox-acme-perl: 1.0.4
libpve-access-control: 6.1-2
libpve-apiclient-perl: 3.0-3
libpve-common-perl: 6.1-5
libpve-guest-common-perl: 3.1-2
libpve-http-server-perl: 3.0-6
libpve-storage-perl: 6.2-5
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 4.0.2-1
lxcfs: 4.0.3-pve3
novnc-pve: 1.1.0-1
openvswitch-switch: 2.12.0-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.2-9
pve-cluster: 6.1-8
pve-container: 3.1-12
pve-docs: 6.2-5
pve-edk2-firmware: 2.20200531-1
pve-firewall: 4.1-2
pve-firmware: 3.1-1
pve-ha-manager: 3.0-9
pve-i18n: 2.1-3
pve-qemu-kvm: 5.0.0-11
pve-xtermjs: 4.3.0-1
qemu-server: 6.2-11
smartmontools: 7.1-pve2
spiceterm: 3.1-1
vncterm: 1.6-1
zfsutils-linux: 0.8.4-pve1
 
Last edited:
I've tried adding `eprintln!("new connection");` to line 91 of `src/bin/proxmox-backup-proxy.rs` to get a log of when new connections are accepted. This indicated that the backup server stops accepting new ones after a while.

C-like:
                    async move {
                        sock.set_nodelay(true).unwrap();
                        sock.set_send_buffer_size(1024*1024).unwrap();
                        sock.set_recv_buffer_size(1024*1024).unwrap();
                        eprintln!("new connection");
                        Ok(tokio_openssl::accept(&acceptor, sock)
                            .await
                            .ok() // handshake errors aren't be fatal, so return None to filter
                        )
                    }

Code:
...
Sep 01 00:41:22 zombie proxmox-backup-proxy[23432]: new connection
Sep 01 00:41:22 zombie proxmox-backup-proxy[23432]: new connection
<repeated>
Sep 01 00:42:01 zombie proxmox-backup-proxy[23432]: new connection
Sep 01 00:42:02 zombie proxmox-backup-proxy[23432]: new connection
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Upload statistics for 'root.pxar.didx'
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: UUID: 4e8e248e634c4b608b04edaf590172cc
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Checksum: 272d12345e5577d5d5edc8e9a94eef8d4c38ba5c7cd8efffbfa0edf57e585e88
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Size: 35488617899
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Chunk count: 7610
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Upload size: 34942828927 (98%)
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Duplicates: 163+56 (2%)
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Compression: 38%
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: successfully closed dynamic index 1
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Upload statistics for 'catalog.pcat1.didx'
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: UUID: ea6ddfeb75154206b22836ac0e7985ee
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Checksum: 9c476e306c004770f6de77d126caad214816c791a8ac2bf126666ceca7f4292c
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Size: 2247656
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Chunk count: 6
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Upload size: 2247656 (100%)
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: Compression: 38%
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: successfully closed dynamic index 2
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: add blob "/internal2/ct/118/2020-08-31T22:29:42Z/index.json.blob" (409 bytes, comp: 409)
Sep 01 01:23:19 zombie proxmox-backup-proxy[23432]: successfully finished backup
Sep 01 01:23:20 zombie proxmox-backup-proxy[23432]: backup finished successfully
Sep 01 01:23:20 zombie proxmox-backup-proxy[23432]: TASK OK
Sep 01 01:23:20 zombie proxmox-backup-proxy[23432]: Detected stopped UPID UPID:zombie:00005B88:031D484B:00000000:5F4D79D7:backup:internal2_ct_118:ws-maxmaton-nl@pbs:
Sep 01 01:23:20 zombie proxmox-backup-proxy[23432]: unregister worker
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/107/2020-08-31T01:15:52Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/107/2020-08-31T22:29:43Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/140/2020-08-31T01:23:45Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/124/2020-08-31T01:23:31Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/111/2020-08-31T01:23:01Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/115/2020-08-31T01:23:27Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/106/2020-08-31T19:40:59Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/133/2020-08-31T01:23:39Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/131/2020-08-31T01:23:34Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/104/2020-08-31T19:42:02Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/132/2020-08-31T01:23:37Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:27:16 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/135/2020-08-31T01:23:42Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/107/2020-08-31T01:15:52Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/107/2020-08-31T22:29:43Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/vm/140/2020-08-31T01:23:45Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/124/2020-08-31T01:23:31Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/111/2020-08-31T01:23:01Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/115/2020-08-31T01:23:27Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/106/2020-08-31T19:40:59Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/133/2020-08-31T01:23:39Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/131/2020-08-31T01:23:34Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:34 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/104/2020-08-31T19:42:02Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:35 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/132/2020-08-31T01:23:37Z/index.json.blob"' - No such file or directory (os erro
Sep 01 01:29:35 zombie proxmox-backup-proxy[23432]: error during snapshot file listing: 'unable to load blob '"/internal2/ct/135/2020-08-31T01:23:42Z/index.json.blob"' - No such file or directory (os erro
Sep 01 04:29:18 zombie proxmox-backup-proxy[23432]: GET /api2/json/nodes/localhost/tasks: 401 Unauthorized: [client [...]:55571] authentication failed - missing ticket
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Upload statistics for 'drive-scsi0.img.fidx'
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: UUID: 8c1deb32001148ddbf6d3034675a8e2b
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Checksum: 12530f0d8fa9a1d48468ae5f2633575d6eb5046c9771d94728f2cd3612114f53
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Size: 206158430208
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Chunk count: 49152
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Upload size: 193684570112 (93%)
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Duplicates: 2974+984 (8%)
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Compression: 76%
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: successfully closed fixed index 1
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: add blob "/internal2/vm/107/2020-08-31T22:29:43Z/index.json.blob" (364 bytes, comp: 364)
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: successfully finished backup
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: backup finished successfully
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: TASK OK
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: Detected stopped UPID UPID:zombie:00005B88:031D484B:00000001:5F4D79D8:backup:internal2_vm_107:ws-maxmaton-nl@pbs:
Sep 01 09:08:24 zombie proxmox-backup-proxy[23432]: unregister worker

At this point the webinterface no longer accepts connections and times out when trying to connect. Normally when everything is working fine the new connection messages intersperse with the backup jobs.

I don't have any experience with rust so I'm not sure what I can do to pinpoint this issue further. Does anyone have any idea?
 
could you open a bug entry over at bugzilla.proxmox.com with all the relevant logs and system information? thanks!
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!