[SOLVED] PBS Backup to NFS Fails, but says TASK OK (successfully)

[sheggy012]

Hello everyone. I was glad to hear about Proxmoxs' own backup solution (PBS). Unfortunately there are still a few difficulties to implement it. Following scenario. PBS runs in an VM on same Host. Mounted is a NFS mount as datastore. The backup of small containers (1gb) works fine here as an example:

Spoiler

2020-11-02T13:21:09+01:00: starting new backup on datastore 'Backups': "ct/115/2020-11-02T12:21:08Z"
2020-11-02T13:21:09+01:00: download 'index.json.blob' from previous backup.
2020-11-02T13:21:09+01:00: add blob "/mnt/NFS/Backup/ct/115/2020-11-02T12:21:08Z/pct.conf.blob" (247 bytes, comp: 247)
2020-11-02T13:21:09+01:00: register chunks in 'root.pxar.didx' from previous backup.
2020-11-02T13:21:09+01:00: download 'root.pxar.didx' from previous backup.
2020-11-02T13:21:09+01:00: created new dynamic index 1 ("ct/115/2020-11-02T12:21:08Z/catalog.pcat1.didx")
2020-11-02T13:21:09+01:00: created new dynamic index 2 ("ct/115/2020-11-02T12:21:08Z/root.pxar.didx")
2020-11-02T13:21:14+01:00: Upload statistics for 'root.pxar.didx'
2020-11-02T13:21:14+01:00: UUID: aefee7688d9a483ab074ff97e32e8cf3
2020-11-02T13:21:14+01:00: Checksum: ffbeede98c5c54bac6ef6c78c75a5a9157a653cf4cea1504f88ab8b5ca1e664a
2020-11-02T13:21:14+01:00: Size: 1130714377
2020-11-02T13:21:14+01:00: Chunk count: 268
2020-11-02T13:21:14+01:00: Upload size: 31836231 (2%)
2020-11-02T13:21:14+01:00: Duplicates: 261+0 (97%)
2020-11-02T13:21:14+01:00: Compression: 25%
2020-11-02T13:21:14+01:00: successfully closed dynamic index 2
2020-11-02T13:21:14+01:00: Upload statistics for 'catalog.pcat1.didx'
2020-11-02T13:21:14+01:00: UUID: 69bd535497af443ab01463d9305add96
2020-11-02T13:21:14+01:00: Checksum: b8ce3bb40b940a9ad49c190f9dd28306512f4c8ec7481fface0b6ed2a8a0e3d6
2020-11-02T13:21:14+01:00: Size: 455119
2020-11-02T13:21:14+01:00: Chunk count: 2
2020-11-02T13:21:14+01:00: Upload size: 455119 (100%)
2020-11-02T13:21:14+01:00: Compression: 43%
2020-11-02T13:21:14+01:00: successfully closed dynamic index 1
2020-11-02T13:21:14+01:00: add blob "/mnt/NFS/Backup/ct/115/2020-11-02T12:21:08Z/index.json.blob" (372 bytes, comp: 372)
2020-11-02T13:21:14+01:00: successfully finished backup
2020-11-02T13:21:14+01:00: backup finished successfully
2020-11-02T13:21:14+01:00: TASK OK

But if I now inflate the container a bit to 8gb. (8GB data generated from urandom)
the log still says Task OK:

Spoiler

2020-11-02T13:27:59+01:00: starting new backup on datastore 'Backups': "ct/115/2020-11-02T12:27:58Z"
2020-11-02T13:27:59+01:00: download 'index.json.blob' from previous backup.
2020-11-02T13:27:59+01:00: add blob "/mnt/NFS/Backup/ct/115/2020-11-02T12:27:58Z/pct.conf.blob" (247 bytes, comp: 247)
2020-11-02T13:27:59+01:00: created new dynamic index 1 ("ct/115/2020-11-02T12:27:58Z/catalog.pcat1.didx")
2020-11-02T13:27:59+01:00: register chunks in 'root.pxar.didx' from previous backup.
2020-11-02T13:27:59+01:00: download 'root.pxar.didx' from previous backup.
2020-11-02T13:27:59+01:00: created new dynamic index 2 ("ct/115/2020-11-02T12:27:58Z/root.pxar.didx")
2020-11-02T13:31:27+01:00: Upload statistics for 'root.pxar.didx'
2020-11-02T13:31:27+01:00: UUID: 896d6ee52fc2463ca55ef1a5da5923f9
2020-11-02T13:31:27+01:00: Checksum: 082e588365c010b41224a49f6d83b90ac4e04f280131c3c5b3d189e3bfa2e343
2020-11-02T13:31:27+01:00: Size: 9464198629
2020-11-02T13:31:27+01:00: Chunk count: 2454
2020-11-02T13:31:27+01:00: Upload size: 8371845507 (88%)
2020-11-02T13:31:27+01:00: Duplicates: 262+0 (10%)
2020-11-02T13:31:27+01:00: Compression: 99%
2020-11-02T13:31:27+01:00: successfully closed dynamic index 2
2020-11-02T13:31:27+01:00: Upload statistics for 'catalog.pcat1.didx'
2020-11-02T13:31:27+01:00: UUID: a1ac4257558c4dcc90c74eb0daa6dc8a
2020-11-02T13:31:27+01:00: Checksum: e0fc43248e2eff999e4d0bc75cbf9075b5ba4deba190f59f6c8a6faa521b9513
2020-11-02T13:31:27+01:00: Size: 455140
2020-11-02T13:31:27+01:00: Chunk count: 2
2020-11-02T13:31:27+01:00: Upload size: 455140 (100%)
2020-11-02T13:31:27+01:00: Compression: 43%
2020-11-02T13:31:27+01:00: successfully closed dynamic index 1
2020-11-02T13:31:27+01:00: add blob "/mnt/NFS/Backup/ct/115/2020-11-02T12:27:58Z/index.json.blob" (372 bytes, comp: 372)
2020-11-02T13:31:27+01:00: successfully finished backup
2020-11-02T13:31:27+01:00: backup finished successfully
2020-11-02T13:31:27+01:00: TASK OK

However, this backup cannot be accessed:
bad request (400)
unable to read dynamic index '"/mnt/NFS/Backup/ct/115/2020-11-02T02:22:34Z/catalog.pcat1.didx"' - Unable to open dynamic index "/mnt/NFS/Backup/ct/115/2020-11-02T02:22:34Z/catalog.pcat1.didx" - failed to fill whole buffer

If I now look at the data on the filesystem it looks like this:
first backup:

root@NFS-Share:~$ sudo ls  -la /mnt/NFS/Backup/Backup/ct/115/2020-11-02T12\:21\:08Z/
total 40
drwxr-xr-x 2 backup backup   185 Nov  2 12:28 .
drwxr-xr-x 8 backup backup   202 Nov  2 12:31 ..
-rw-r--r-- 1 backup backup   372 Nov  2 12:21 .fuse_hidden003e572400001db6
-rw-r--r-- 1 backup backup  4176 Nov  2 12:21 catalog.pcat1.didx
-rw-r--r-- 1 backup backup   829 Nov  2 12:21 client.log.blob
-rw-r--r-- 1 backup backup   534 Nov  2 12:28 index.json.blob
-rw-r--r-- 1 backup backup   247 Nov  2 12:21 pct.conf.blob
-rw-r--r-- 1 backup backup 14816 Nov  2 12:21 root.pxar.didx

second backup.

root@NFS-Share:~$ sudo ls  -la /mnt/NFS/Backup/Backup/ct/115/2020-11-02T12:27:58Z/
total 16
drwxr-xr-x 2 backup backup 104 Nov  2 12:31 .
drwxr-xr-x 8 backup backup 202 Nov  2 12:31 ..
-rw-r--r-- 1 backup backup 372 Nov  2 12:31 .fuse_hidden003e90be00001db8
-rw-r--r-- 1 backup backup   0 Nov  2 12:27 catalog.pcat1.didx
-rw-r--r-- 1 backup backup 837 Nov  2 12:31 client.log.blob
-rw-r--r-- 1 backup backup 442 Nov  2 12:31 index.json.blob
-rw-r--r-- 1 backup backup 247 Nov  2 12:27 pct.conf.blob
-rw-r--r-- 1 backup backup   0 Nov  2 12:27 root.pxar.didx

It directly points out that something is wrong here. root.pxar.didx and catalog.pcat1.didx have a file size of 0.
Does anyone have an idea? I don't understand why PBS itself doesn't create or display more errors.
The NFS mount is mounted as follows:
192.168.1.50:/mnt/Snapraid/Backup /mnt/NFS/ nfs rw,local_lock=all 0 0

Best Regards Sergej

 

[wolfgang]

Hi,

I guess it is a caching problem. Please try to mount nfs with noac and sync

 

[sheggy012]

Hi,

I guess it is a caching problem. Please try to mount nfs with noac and sync

Okay, after adding noac and sync I had NFS Stale file handl's with every Backup. This made me think that something was wrong with my NFS. I have now switched completely to NFSv4, before the mounts ran over NFS3. Now there are no more problems, with and without noac and sync.
Thanks a lot for the help.