qmp command 'query-proxmox-support' failed - got timeout

Hi @Chris, here is the result of my experiment.

This is the log from PVE's side.
I hit "Stop" about 30 seconds after I received the timeout message, otherwise I would have waited for several minutes for the job to really abort.
That's why you see the last message "ERROR: Interrupted by signal".
Code: 
INFO: starting new backup job: vzdump 105 --node host0 --mode snapshot --storage BaR_PBS_Bluenas --fleecing '1,storage=vmzfs' --mailto log@<AMENDED> --prune-backups 'keep-daily=1,keep-last=2,keep-monthly=1,keep-weekly=1,keep-yearly=1' --notes-template '{{guestname}}' --all 0 --mailnotification failure --bwlimit 20480
INFO: Starting Backup of VM 105 (qemu)
INFO: Backup started at 2024-10-28 10:50:29
INFO: status = stopped
INFO: backup mode: stop
INFO: bandwidth limit: 20480 KiB/s
INFO: ionice priority: 7
INFO: VM Name: FreeBSD-dev
INFO: include disk 'sata0' 'vmzfs:vm-105-disk-0' 32G
INFO: creating Proxmox Backup Server archive 'vm/105/2024-10-28T09:50:29Z'
INFO: starting kvm to execute backup task
INFO: drive-sata0: attaching fleecing image vmzfs:vm-105-fleece-0 to QEMU
ERROR: VM 105 qmp command 'backup' failed - got timeout
INFO: aborting backup job
ERROR: interrupted by signal

This is the log from PBS' side.
Here, too, I hit "Stop" after receiving the timeout message on the PVE side.
Code: 
2024-10-28T10:50:33+01:00: starting new backup on datastore 'BlueNAS_PBS' from ::ffff:127.0.0.1: "vm/105/2024-10-28T09:50:29Z"
2024-10-28T10:50:33+01:00: GET /previous: 400 Bad Request: no valid previous backup
2024-10-28T10:53:48+01:00: received abort request ...
2024-10-28T10:53:48+01:00: backup failed: task aborted
2024-10-28T10:53:48+01:00: removing failed backup
2024-10-28T10:53:48+01:00: TASK ERROR: task aborted

Here is the result of the command you requested (before hitting "Stop" and after receiving the timeout message):
Code: 
root@host0:~# grep 'State' /proc/$(cat /var/run/qemu-server/105.pid)/task/*/status
/proc/834996/task/834996/status:State:    S (sleeping)
/proc/834996/task/834997/status:State:    S (sleeping)
/proc/834996/task/835263/status:State:    S (sleeping)
/proc/834996/task/835264/status:State:    S (sleeping)
/proc/834996/task/835265/status:State:    S (sleeping)
/proc/834996/task/835266/status:State:    S (sleeping)
/proc/834996/task/835267/status:State:    S (sleeping)
/proc/834996/task/835270/status:State:    S (sleeping)
/proc/834996/task/835312/status:State:    S (sleeping)
/proc/834996/task/835313/status:State:    S (sleeping)
/proc/834996/task/835314/status:State:    S (sleeping)
/proc/834996/task/835315/status:State:    S (sleeping)

And, last, this is the result of the same command several minutes after hitting "Stop":
Code: 
/proc/834996/task/834996/status:State:    S (sleeping)
/proc/834996/task/834997/status:State:    S (sleeping)
/proc/834996/task/835263/status:State:    S (sleeping)
/proc/834996/task/835264/status:State:    S (sleeping)
/proc/834996/task/835265/status:State:    S (sleeping)
/proc/834996/task/835266/status:State:    S (sleeping)
/proc/834996/task/835267/status:State:    S (sleeping)
/proc/834996/task/835270/status:State:    S (sleeping)

Hope this helps.
Cris
 
Regarding garbage collection: I have started a GC job about 15 minutes ago.
It is doing apparently nothing and it stil runs.
Given the fact that there are no backups on this PBS server, I'd expect it to finish immediately.
Looking at the job Status, I see that PID is 2434. A quick grep in the process list shows that PID 2434 is proxmox-backup-proxy.
If I grep in the process list for the Unique Task ID, I find nothing.
After about 20 minutes I hit "Stop". Nothing happened.
After about another 10 minutes, I restarted the proxmox-backup-proxy service to get rid of the stale job.
 
Last edited:
Please try to create a new datastore, backed by a local path and check if the backup and garbage collection works without issues there. This would allow to exclude the NFS as source of issues.
 
Hi @Chris , the (predictable?) result is that using a local datastore makes the entire process work without issues.

Now I'm trying to identify what are the differences between the server that has difficulty working with NFS and the one that works without issues.

I think this may be due to two different NFS implementations, as one NAS (the working one) is a QNAP, while the other one is a Zyxel.

Here are the logs of the successful backup using the local datastore:
Code: 
PVE side:
INFO: starting new backup job: vzdump 105 --all 0 --mailnotification failure --bwlimit 25600 --storage BaR_PBS_Local --fleecing '1,storage=vmzfs' --mailto log@<AMENDED> --node host0 --mode snapshot --prune-backups 'keep-daily=1,keep-last=2,keep-monthly=1,keep-weekly=1,keep-yearly=1' --notes-template '{{guestname}}'
INFO: Starting Backup of VM 105 (qemu)
INFO: Backup started at 2024-10-30 13:30:54
INFO: status = stopped
INFO: backup mode: stop
INFO: bandwidth limit: 25600 KiB/s
INFO: ionice priority: 7
INFO: VM Name: FreeBSD-dev
INFO: include disk 'sata0' 'vmzfs:vm-105-disk-0' 32G
INFO: creating Proxmox Backup Server archive 'vm/105/2024-10-30T12:30:54Z'
INFO: starting kvm to execute backup task
INFO: drive-sata0: attaching fleecing image vmzfs:vm-105-fleece-0 to QEMU
INFO: started backup task '2d90dd7a-1e5c-4d2c-afa4-ffffa302e364'
INFO: sata0: dirty-bitmap status: created new
INFO:   0% (76.0 MiB of 32.0 GiB) in 3s, read: 25.3 MiB/s, write: 4.0 MiB/s
INFO:   1% (328.0 MiB of 32.0 GiB) in 13s, read: 25.2 MiB/s, write: 0 B/s
INFO:   2% (676.0 MiB of 32.0 GiB) in 27s, read: 24.9 MiB/s, write: 0 B/s
INFO:   3% (1004.0 MiB of 32.0 GiB) in 40s, read: 25.2 MiB/s, write: 0 B/s
INFO:   4% (1.3 GiB of 32.0 GiB) in 53s, read: 24.9 MiB/s, write: 0 B/s
INFO:   5% (1.6 GiB of 32.0 GiB) in 1m 7s, read: 23.1 MiB/s, write: 0 B/s
INFO:   6% (1.9 GiB of 32.0 GiB) in 1m 20s, read: 24.9 MiB/s, write: 0 B/s
INFO:   7% (2.2 GiB of 32.0 GiB) in 1m 33s, read: 24.9 MiB/s, write: 19.4 MiB/s
INFO:   8% (2.6 GiB of 32.0 GiB) in 1m 46s, read: 25.2 MiB/s, write: 20.6 MiB/s
INFO:   9% (2.9 GiB of 32.0 GiB) in 1m 59s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  10% (3.2 GiB of 32.0 GiB) in 2m 13s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  11% (3.5 GiB of 32.0 GiB) in 2m 26s, read: 25.2 MiB/s, write: 25.2 MiB/s
INFO:  12% (3.9 GiB of 32.0 GiB) in 2m 39s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  13% (4.2 GiB of 32.0 GiB) in 2m 52s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  14% (4.5 GiB of 32.0 GiB) in 3m 5s, read: 25.2 MiB/s, write: 21.2 MiB/s
INFO:  15% (4.8 GiB of 32.0 GiB) in 3m 18s, read: 24.9 MiB/s, write: 24.3 MiB/s
INFO:  16% (5.1 GiB of 32.0 GiB) in 3m 31s, read: 24.9 MiB/s, write: 20.3 MiB/s
INFO:  17% (5.4 GiB of 32.0 GiB) in 3m 44s, read: 25.2 MiB/s, write: 24.9 MiB/s
INFO:  18% (5.8 GiB of 32.0 GiB) in 3m 57s, read: 24.9 MiB/s, write: 20.6 MiB/s
INFO:  19% (6.1 GiB of 32.0 GiB) in 4m 10s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  20% (6.4 GiB of 32.0 GiB) in 4m 24s, read: 23.4 MiB/s, write: 23.1 MiB/s
INFO:  21% (6.7 GiB of 32.0 GiB) in 4m 38s, read: 24.9 MiB/s, write: 17.4 MiB/s
INFO:  22% (7.1 GiB of 32.0 GiB) in 4m 51s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  23% (7.4 GiB of 32.0 GiB) in 5m 4s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  24% (7.7 GiB of 32.0 GiB) in 5m 17s, read: 25.2 MiB/s, write: 15.7 MiB/s
INFO:  25% (8.0 GiB of 32.0 GiB) in 5m 30s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  26% (8.3 GiB of 32.0 GiB) in 5m 43s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  27% (8.6 GiB of 32.0 GiB) in 5m 56s, read: 25.2 MiB/s, write: 20.6 MiB/s
INFO:  28% (9.0 GiB of 32.0 GiB) in 6m 9s, read: 24.9 MiB/s, write: 18.5 MiB/s
INFO:  29% (9.3 GiB of 32.0 GiB) in 6m 22s, read: 24.9 MiB/s, write: 21.8 MiB/s
INFO:  30% (9.6 GiB of 32.0 GiB) in 6m 36s, read: 25.1 MiB/s, write: 16.3 MiB/s
INFO:  31% (9.9 GiB of 32.0 GiB) in 6m 49s, read: 24.9 MiB/s, write: 20.3 MiB/s
INFO:  32% (10.3 GiB of 32.0 GiB) in 7m 2s, read: 24.9 MiB/s, write: 20.0 MiB/s
INFO:  33% (10.6 GiB of 32.0 GiB) in 7m 15s, read: 25.2 MiB/s, write: 15.7 MiB/s
INFO:  34% (10.9 GiB of 32.0 GiB) in 7m 28s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  35% (11.2 GiB of 32.0 GiB) in 7m 41s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  36% (11.5 GiB of 32.0 GiB) in 7m 55s, read: 23.1 MiB/s, write: 14.3 MiB/s
INFO:  37% (11.8 GiB of 32.0 GiB) in 8m 8s, read: 25.2 MiB/s, write: 25.2 MiB/s
INFO:  38% (12.2 GiB of 32.0 GiB) in 8m 21s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  39% (12.5 GiB of 32.0 GiB) in 8m 34s, read: 24.9 MiB/s, write: 21.5 MiB/s
INFO:  40% (12.8 GiB of 32.0 GiB) in 8m 48s, read: 25.1 MiB/s, write: 23.4 MiB/s
INFO:  41% (13.1 GiB of 32.0 GiB) in 9m 1s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  42% (13.5 GiB of 32.0 GiB) in 9m 14s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  43% (13.8 GiB of 32.0 GiB) in 9m 27s, read: 24.9 MiB/s, write: 21.2 MiB/s
INFO:  44% (14.1 GiB of 32.0 GiB) in 9m 40s, read: 25.2 MiB/s, write: 15.7 MiB/s
INFO:  45% (14.4 GiB of 32.0 GiB) in 9m 53s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  46% (14.7 GiB of 32.0 GiB) in 10m 6s, read: 24.9 MiB/s, write: 20.3 MiB/s
INFO:  47% (15.0 GiB of 32.0 GiB) in 10m 19s, read: 25.2 MiB/s, write: 15.7 MiB/s
INFO:  48% (15.4 GiB of 32.0 GiB) in 10m 32s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  49% (15.7 GiB of 32.0 GiB) in 10m 46s, read: 24.9 MiB/s, write: 23.4 MiB/s
INFO:  50% (16.0 GiB of 32.0 GiB) in 10m 58s, read: 25.3 MiB/s, write: 20.7 MiB/s
INFO:  51% (16.3 GiB of 32.0 GiB) in 11m 12s, read: 24.9 MiB/s, write: 24.6 MiB/s
INFO:  52% (16.7 GiB of 32.0 GiB) in 11m 25s, read: 24.9 MiB/s, write: 20.3 MiB/s
INFO:  53% (17.0 GiB of 32.0 GiB) in 11m 39s, read: 23.4 MiB/s, write: 16.6 MiB/s
INFO:  54% (17.3 GiB of 32.0 GiB) in 11m 52s, read: 24.9 MiB/s, write: 22.8 MiB/s
INFO:  55% (17.6 GiB of 32.0 GiB) in 12m 5s, read: 24.9 MiB/s, write: 13.5 MiB/s
INFO:  56% (17.9 GiB of 32.0 GiB) in 12m 18s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  57% (18.2 GiB of 32.0 GiB) in 12m 31s, read: 25.2 MiB/s, write: 20.6 MiB/s
INFO:  58% (18.6 GiB of 32.0 GiB) in 12m 44s, read: 24.9 MiB/s, write: 8.9 MiB/s
INFO:  59% (18.9 GiB of 32.0 GiB) in 12m 57s, read: 25.2 MiB/s, write: 15.4 MiB/s
INFO:  60% (19.2 GiB of 32.0 GiB) in 13m 11s, read: 24.9 MiB/s, write: 16.0 MiB/s
INFO:  61% (19.5 GiB of 32.0 GiB) in 13m 24s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  62% (19.9 GiB of 32.0 GiB) in 13m 37s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  63% (20.2 GiB of 32.0 GiB) in 13m 50s, read: 24.9 MiB/s, write: 15.7 MiB/s
INFO:  64% (20.5 GiB of 32.0 GiB) in 14m 3s, read: 25.2 MiB/s, write: 16.6 MiB/s
INFO:  65% (20.8 GiB of 32.0 GiB) in 14m 16s, read: 24.9 MiB/s, write: 24.0 MiB/s
INFO:  66% (21.1 GiB of 32.0 GiB) in 14m 29s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  67% (21.4 GiB of 32.0 GiB) in 14m 42s, read: 25.2 MiB/s, write: 20.3 MiB/s
INFO:  68% (21.8 GiB of 32.0 GiB) in 14m 55s, read: 24.9 MiB/s, write: 20.3 MiB/s
INFO:  69% (22.1 GiB of 32.0 GiB) in 15m 10s, read: 23.5 MiB/s, write: 15.2 MiB/s
INFO:  70% (22.4 GiB of 32.0 GiB) in 15m 23s, read: 24.9 MiB/s, write: 21.8 MiB/s
INFO:  71% (22.7 GiB of 32.0 GiB) in 15m 36s, read: 24.9 MiB/s, write: 18.5 MiB/s
INFO:  72% (23.1 GiB of 32.0 GiB) in 15m 49s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  73% (23.4 GiB of 32.0 GiB) in 16m 2s, read: 25.2 MiB/s, write: 25.2 MiB/s
INFO:  74% (23.7 GiB of 32.0 GiB) in 16m 15s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  75% (24.0 GiB of 32.0 GiB) in 16m 28s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  76% (24.3 GiB of 32.0 GiB) in 16m 41s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  77% (24.6 GiB of 32.0 GiB) in 16m 54s, read: 25.2 MiB/s, write: 15.7 MiB/s
INFO:  78% (25.0 GiB of 32.0 GiB) in 17m 7s, read: 24.9 MiB/s, write: 18.8 MiB/s
INFO:  79% (25.3 GiB of 32.0 GiB) in 17m 21s, read: 25.1 MiB/s, write: 22.0 MiB/s
INFO:  80% (25.6 GiB of 32.0 GiB) in 17m 34s, read: 24.9 MiB/s, write: 15.4 MiB/s
INFO:  81% (25.9 GiB of 32.0 GiB) in 17m 47s, read: 24.9 MiB/s, write: 10.8 MiB/s
INFO:  82% (26.3 GiB of 32.0 GiB) in 18m, read: 24.9 MiB/s, write: 19.7 MiB/s
INFO:  83% (26.6 GiB of 32.0 GiB) in 18m 13s, read: 25.2 MiB/s, write: 5.8 MiB/s
INFO:  84% (26.9 GiB of 32.0 GiB) in 18m 26s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  85% (27.2 GiB of 32.0 GiB) in 18m 40s, read: 23.1 MiB/s, write: 23.1 MiB/s
INFO:  86% (27.5 GiB of 32.0 GiB) in 18m 53s, read: 24.9 MiB/s, write: 9.2 MiB/s
INFO:  87% (27.8 GiB of 32.0 GiB) in 19m 6s, read: 25.2 MiB/s, write: 18.5 MiB/s
INFO:  88% (28.2 GiB of 32.0 GiB) in 19m 19s, read: 24.9 MiB/s, write: 12.3 MiB/s
INFO:  89% (28.5 GiB of 32.0 GiB) in 19m 32s, read: 25.2 MiB/s, write: 7.7 MiB/s
INFO:  90% (28.8 GiB of 32.0 GiB) in 19m 46s, read: 24.9 MiB/s, write: 19.4 MiB/s
INFO:  91% (29.1 GiB of 32.0 GiB) in 19m 59s, read: 24.9 MiB/s, write: 10.5 MiB/s
INFO:  92% (29.5 GiB of 32.0 GiB) in 20m 12s, read: 25.2 MiB/s, write: 9.5 MiB/s
INFO:  93% (29.8 GiB of 32.0 GiB) in 20m 25s, read: 24.9 MiB/s, write: 21.2 MiB/s
INFO:  94% (30.1 GiB of 32.0 GiB) in 20m 38s, read: 24.9 MiB/s, write: 9.2 MiB/s
INFO:  95% (30.4 GiB of 32.0 GiB) in 20m 51s, read: 24.9 MiB/s, write: 23.1 MiB/s
INFO:  96% (30.7 GiB of 32.0 GiB) in 21m 4s, read: 24.9 MiB/s, write: 17.2 MiB/s
INFO:  97% (31.0 GiB of 32.0 GiB) in 21m 17s, read: 25.2 MiB/s, write: 5.8 MiB/s
INFO:  98% (31.4 GiB of 32.0 GiB) in 21m 31s, read: 24.9 MiB/s, write: 24.9 MiB/s
INFO:  99% (31.7 GiB of 32.0 GiB) in 21m 44s, read: 25.2 MiB/s, write: 0 B/s
INFO: 100% (32.0 GiB of 32.0 GiB) in 21m 57s, read: 23.4 MiB/s, write: 315.1 KiB/s
INFO: Waiting for server to finish backup validation...
INFO: backup is sparse: 9.58 GiB (29%) total zero data
INFO: backup was done incrementally, reused 9.58 GiB (29%)
INFO: transferred 32.00 GiB in 1320 seconds (24.8 MiB/s)
INFO: stopping kvm after backup task
INFO: adding notes to backup
INFO: prune older backups with retention: keep-daily=1, keep-last=2, keep-monthly=1, keep-weekly=1, keep-yearly=1
INFO: running 'proxmox-backup-client prune' for 'vm/105'
INFO: pruned 0 backup(s)
INFO: Finished Backup of VM 105 (00:22:07)
INFO: Backup finished at 2024-10-30 13:53:01
INFO: Backup job finished successfully
TASK OK


PBS side:
2024-10-30T13:30:57+01:00: starting new backup on datastore 'Test_Local' from ::ffff:127.0.0.1: "vm/105/2024-10-30T12:30:54Z"
2024-10-30T13:30:57+01:00: GET /previous: 400 Bad Request: no valid previous backup
2024-10-30T13:30:57+01:00: created new fixed index 1 ("vm/105/2024-10-30T12:30:54Z/drive-sata0.img.fidx")
2024-10-30T13:30:57+01:00: add blob "/vmzfs/test_pbs/vm/105/2024-10-30T12:30:54Z/qemu-server.conf.blob" (573 bytes, comp: 573)
2024-10-30T13:52:54+01:00: Upload statistics for 'drive-sata0.img.fidx'
2024-10-30T13:52:54+01:00: UUID: 33bc9c3683b947c9aa668b8feb0ef165
2024-10-30T13:52:54+01:00: Checksum: 13a81ba2a3dc92528b169ace8b9b0019270f593d6ea13973669a54f3cf77f563
2024-10-30T13:52:54+01:00: Size: 34359738368
2024-10-30T13:52:54+01:00: Chunk count: 8192
2024-10-30T13:52:54+01:00: Upload size: 24079499264 (70%)
2024-10-30T13:52:54+01:00: Duplicates: 2451+0 (29%)
2024-10-30T13:52:54+01:00: Compression: 49%
2024-10-30T13:52:54+01:00: successfully closed fixed index 1
2024-10-30T13:52:54+01:00: add blob "/vmzfs/test_pbs/vm/105/2024-10-30T12:30:54Z/index.json.blob" (328 bytes, comp: 328)
2024-10-30T13:52:57+01:00: successfully finished backup
2024-10-30T13:52:57+01:00: backup finished successfully
2024-10-30T13:52:57+01:00: TASK OK
 
Just as a follow-up, for anybody interested: I changed the NAS with a new QNAP, which has a more recent NFS implementation.
After this change, PBS started working correctly on the NFS share.
So the problem was an old/incorrect NFS implementation on the old Zyxel NAS.
 
You must log in or register to reply here.
Top Bottom