Hi, all my backups of size larger than (about) 1Gb fails. Here is a sample task log:
And here is the syslog (on the node) from the same timeframe:
And probably more helpful is the syslog from the PBS (notice the tokio-runtime-w segfault):
A few relevant facts:
Thanks!
Code:
INFO: starting new backup job: vzdump 124 --node vmh3 --mode snapshot --remove 0 --storage pbs-primary
INFO: Starting Backup of VM 124 (lxc)
INFO: Backup started at 2020-10-09 09:13:52
INFO: status = running
INFO: CT Name: bjornlokan
INFO: including mount point rootfs ('/') in backup
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
/dev/rbd4
INFO: creating Proxmox Backup Server archive 'ct/124/2020-10-09T07:13:52Z'
INFO: run: lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup --crypt-mode=none pct.conf:/var/tmp/vzdumptmp841076/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --backup-type ct --backup-id 124 --backup-time 1602227632 --repository root@pam@backup.nilsson.link:primary
INFO: Starting backup: ct/124/2020-10-09T07:13:52Z
INFO: Client name: vmh3
INFO: Starting backup protocol: Fri Oct 9 09:13:53 2020
INFO: Upload config file '/var/tmp/vzdumptmp841076/etc/vzdump/pct.conf' to 'root@pam@backup.nilsson.link:8007:primary' as pct.conf.blob
INFO: Upload directory '/mnt/vzsnap0' to 'root@pam@backup.nilsson.link:8007:primary' as root.pxar.didx
INFO: root.pxar: had to upload 65.51 MiB of 1.35 GiB in 78.92s, average speed 849.95 KiB/s).
INFO: root.pxar: backup was done incrementally, reused 1.29 GiB (95.3%)
INFO: Uploaded backup catalog (781.80 KiB)
INFO: catalog upload error - broken pipe
INFO: Error: broken pipe
INFO: remove vzdump snapshot
Removing snap: 100% complete...done.
ERROR: Backup of VM 124 failed - command 'lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup '--crypt-mode=none' pct.conf:/var/tmp/vzdumptmp841076/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --backup-type ct --backup-id 124 --backup-time 1602227632 --repository root@pam@backup.nilsson.link:primary' failed: exit code 255
INFO: Failed at 2020-10-09 09:15:13
INFO: Backup job finished with errors
TASK ERROR: job errors
And here is the syslog (on the node) from the same timeframe:
Code:
Oct 09 09:13:52 vmh3 pvedaemon[1528]: <root@pam> starting task UPID:vmh3:000CD574:0088123B:5F800DB0:vzdump:124:root@pam:
Oct 09 09:13:52 vmh3 pvedaemon[841076]: INFO: starting new backup job: vzdump 124 --node vmh3 --mode snapshot --remove 0 --storage pbs-primary
Oct 09 09:13:52 vmh3 pvedaemon[841076]: INFO: Starting Backup of VM 124 (lxc)
Oct 09 09:13:52 vmh3 kernel: rbd: rbd4: capacity 8589934592 features 0x3d
Oct 09 09:13:52 vmh3 kernel: EXT4-fs (rbd4): mounted filesystem without journal. Opts: noload
Oct 09 09:14:00 vmh3 systemd[1]: Starting Proxmox VE replication runner...
Oct 09 09:14:01 vmh3 systemd[1]: pvesr.service: Succeeded.
Oct 09 09:14:01 vmh3 systemd[1]: Started Proxmox VE replication runner.
Oct 09 09:15:00 vmh3 systemd[1]: Starting Proxmox VE replication runner...
Oct 09 09:15:01 vmh3 systemd[1]: pvesr.service: Succeeded.
Oct 09 09:15:01 vmh3 systemd[1]: Started Proxmox VE replication runner.
Oct 09 09:15:13 vmh3 pvedaemon[841076]: ERROR: Backup of VM 124 failed - command 'lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup '--crypt-mode=none' pct.conf:/var/tmp/vzdumptmp841076/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --backup-type ct --backup-id 124 --backup-time 1602227632 --repository root@pam@backup.nilsson.link:primary' failed: exit code 255
Oct 09 09:15:13 vmh3 pvedaemon[841076]: INFO: Backup job finished with errors
Oct 09 09:15:13 vmh3 pvedaemon[841076]: job errors
Oct 09 09:15:13 vmh3 pvedaemon[1528]: <root@pam> end task UPID:vmh3:000CD574:0088123B:5F800DB0:vzdump:124:root@pam: job errors
And probably more helpful is the syslog from the PBS (notice the tokio-runtime-w segfault):
Code:
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: register worker
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: FILE: "/var/log/proxmox-backup/tasks/EB/UPID:backup:00000268:000005EB:00000004:5F800DB1:backup:primary_ct_124:root@pam:"
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: starting new backup on datastore 'primary': "ct/124/2020-10-09T07:13:52Z"
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: download 'index.json.blob' from previous backup.
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: add blob "/mnt/datastore/primary/ct/124/2020-10-09T07:13:52Z/pct.conf.blob" (189 bytes, comp: 189)
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: created new dynamic index 1 ("ct/124/2020-10-09T07:13:52Z/catalog.pcat1.didx")
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: register chunks in 'root.pxar.didx' from previous backup.
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: download 'root.pxar.didx' from previous backup.
Oct 09 09:13:53 backup proxmox-backup-proxy[616]: created new dynamic index 2 ("ct/124/2020-10-09T07:13:52Z/root.pxar.didx")
Oct 09 09:13:54 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:00 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:01 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:05 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:11 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:11 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:14 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:20 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:21 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:24 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:30 backup proxmox-backup-proxy[616]: error during snapshot file listing: 'unable to load blob '"/mnt/datastore/primary/ct/124/2020-10-09T07:13:52Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 09 09:14:30 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:31 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:35 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:41 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:41 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:44 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:50 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:52 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:14:54 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:00 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:01 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:05 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:10 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:11 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Upload statistics for 'root.pxar.didx'
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: UUID: 2c2dc08b9db64509a8879f7191fb1243
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Checksum: 5e5c69866564e361e1aee994c106a43050c2c1e146a24b447cf8c00e08d55c24
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Size: 1450963972
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Chunk count: 424
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Upload size: 68688884 (4%)
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Duplicates: 412+0 (97%)
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Compression: 20%
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: successfully closed dynamic index 2
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Upload statistics for 'catalog.pcat1.didx'
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: UUID: dab73f205b264d01be947549c0e1d5a3
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Checksum: e4e5cb17d52c829c280456647b3cf98886e2cdcae8c7b4794a70904bf4f2523b
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Size: 800568
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Chunk count: 4
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Upload size: 800568 (100%)
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Duplicates: 0+2 (50%)
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: Compression: 41%
Oct 09 09:15:12 backup proxmox-backup-proxy[616]: successfully closed dynamic index 1
Oct 09 09:15:12 backup kernel: tokio-runtime-w[922]: segfault at 563de1e69000 ip 0000563de1ad56e0 sp 00007f7f5230aa60 error 4 in proxmox-backup-proxy[563de14cb000+6e8000]
Oct 09 09:15:12 backup kernel: Code: 00 00 00 01 00 00 48 8b 53 08 49 8d 40 ff 44 89 c6 83 e6 07 48 83 f8 07 72 71 48 89 f0 4c 29 c0 66 2e 0f 1f 84 00 00 00 00 00 <0f> b6 1a 48 31 fb 48 0f af d9 0f b6 7a 01 48 31 df 48 0f af f9 0f
Oct 09 09:15:12 backup systemd[1]: proxmox-backup-proxy.service: Main process exited, code=killed, status=11/SEGV
Oct 09 09:15:12 backup systemd[1]: proxmox-backup-proxy.service: Failed with result 'signal'.
Oct 09 09:15:12 backup systemd[1]: proxmox-backup-proxy.service: Service RestartSec=100ms expired, scheduling restart.
Oct 09 09:15:12 backup systemd[1]: proxmox-backup-proxy.service: Scheduled restart job, restart counter is at 1.
Oct 09 09:15:12 backup systemd[1]: Stopped Proxmox Backup API Proxy Server.
Oct 09 09:15:12 backup systemd[1]: Starting Proxmox Backup API Proxy Server...
Oct 09 09:15:12 backup systemd[1]: Started Proxmox Backup API Proxy Server.
Oct 09 09:15:14 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:14 backup proxmox-backup-proxy[931]: Detected stopped UPID UPID:backup:00000268:000005EB:00000004:5F800DB1:backup:primary_ct_124:root@pam:
Oct 09 09:15:20 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:21 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
Oct 09 09:15:24 backup proxmox-backup-api[590]: successful auth for user 'root@pam'
A few relevant facts:
- The entry for the failed backup in the Datastore Content list (on the bps) has a spinning wheel instead of the size.
- Verification of the backup fails with "manifest load error: unable to load blob '"/mnt/datastore/primary/ct/124/2020-10-09T07:13:52Z/index.json.blob"' - No such file or directory (os error 2)"
- The dashboard does not mention any failed backups.
- All my backups (with the exception of a few tiny containers) have failed during the last two days. This is true for all 3 of my nodes.
- It started happening right after I uppgraded all my nodes and my PBS to the latest versions:
- PBS: 0.9-0
- PVE: 6.2-12
- Deleting the bad backups have no effect.
Thanks!