Unable to open dynamic index - index too small (0)

[jan.pekar]

Hello,
I'm trying to backup my filesystem using pbs. Because my link is slow I separated files to smaller blocks but after 8 hours of successfully finished upload and repeating my backup over the same dir I noticed, that upload starts again.

Output of client

Starting backup: host/vserver01/2022-10-07T08:33:17Z Client name: vserver01 Starting backup protocol: Fri Oct 7 08:33:18 2022 Using encryption key from '/encryption-key.json'.. Encryption key fingerprint: xxxxxxxxxxxxxxxxxxxxxxxxxx Downloading previous manifest (Wed Oct 5 22:05:00 2022) Upload directory '/homecloud/' to 'backupuser@pbs@janpekar01.pbs.it.imatic.cz:8007:datastore01' as homecloud.pxar.didx Error downloading .didx from previous manifest: Unable to open dynamic index "/opt/datastore01/host/vserver01/2022-10-05T22:05:00Z/homecloud.pxar.didx" - No such file or directory (os error 2) warning: file size increased while reading: "data/nextcloud.log", file will be truncated! homecloud.pxar: had to backup 85.071 GiB of 90.321 GiB (compressed 82.527 GiB) in 30540.17s homecloud.pxar: average backup speed: 2.852 MiB/s homecloud.pxar: backup was done incrementally, reused 5.25 GiB (5.8%) Uploaded backup catalog (1.693 MiB) Duration: 30541.25s End Time: Fri Oct 7 17:02:19 2022

Second try

Starting backup protocol: Sat Oct 8 06:41:21 2022 Using encryption key from '/encryption-key.json'.. Encryption key fingerprint: xxxxxxxxxxxxxxxxxxxxxxxxxx Downloading previous manifest (Fri Oct 7 08:33:17 2022) Upload directory '/homecloud' to 'backupuser@pbs@janpekar01.pbs.it.imatic.cz:8007:datastore01' as homecloud.pxar.didx Error downloading .didx from previous manifest: Unable to open dynamic index "/opt/datastore01/host/vserver01/2022-10-07T08:33:17Z/homecloud.pxar.didx" - index too small (0)

Server side when first backup is finished

Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Upload statistics for 'homecloud.pxar.didx' Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: UUID: 636b7be594a148ea80a0bdb03ece83e5 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Checksum: 0110f2847dc232b90082e56678401378a381f4c1a3f824473b0bf07392b9d4fb Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Size: 96981751849 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Chunk count: 25347 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Upload size: 91344202583 (94%) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Duplicates: 1524+23805 (99%) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Compression: 97% Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully closed dynamic index 2 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: upload_chunk done: 117191 bytes, 16af40c4566899aadf524961e5112c71c2e7e50f9144751e9838ccc28acb25a8 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: PUT /dynamic_index Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: dynamic_append 4 chunks Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully added chunk 4a424acc6ac85e47c61d8e699404698b7e0ab86e1e245147c4b5e4c9bcfb4197 to dynamic index 1 (offset 0, size 694065) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully added chunk 95bc26184330b58421205294b44d90c0c4c630f577efcb89a29c298360b4fe5e to dynamic index 1 (offset 694065, size 828215) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully added chunk 9e0cc958bff521289fc00e1169f5829e6a7a7390e00f6a2d9acdc3eb03efc367 to dynamic index 1 (offset 1522280, size 135725) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully added chunk 16af40c4566899aadf524961e5112c71c2e7e50f9144751e9838ccc28acb25a8 to dynamic index 1 (offset 1658005, size 117191) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_close Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Upload statistics for 'catalog.pcat1.didx' Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: UUID: 2cc43ef9a310418d92d87865cb992e86 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Checksum: 73f9780f72268b9b89c45257d5cb0edc6e91a0eb118e3b196b5de02357f2e463 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Size: 1775196 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Chunk count: 4 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Upload size: 1775196 (100%) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Duplicates: 0+2 (50%) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: Compression: 35% Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully closed dynamic index 1 Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: POST /blob Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: add blob "/opt/datastore01/host/vserver01/2022-10-07T08:33:17Z/index.json.blob" (438 bytes, comp: 438) Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: POST /finish Oct 7 19:02:19 janpekar01 proxmox-backup-proxy[610]: successfully finished backup Oct 7 19:02:21 janpekar01 proxmox-backup-proxy[610]: backup finished successfully Oct 7 19:02:21 janpekar01 proxmox-backup-proxy[610]: TASK OK Oct 7 19:03:52 janpekar01 proxmox-backup-proxy[610]: write rrd data back to disk Oct 7 19:03:53 janpekar01 proxmox-backup-proxy[610]: starting rrd data sync Oct 7 19:03:53 janpekar01 proxmox-backup-proxy[610]: rrd journal successfully committed (18 files in 0.173 seconds)

Server side when new backup is started

Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: starting new backup on datastore 'datastore01': "host/vserver01/2022-10-08T06:41:19Z" Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: protocol upgrade done Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: GET /previous_backup_time Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: GET /previous Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: download 'index.json.blob' from previous backup. Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_index Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: created new dynamic index 1 ("host/vserver01/2022-10-08T06:41:19Z/catalog.pcat1.didx") Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: GET /previous Oct 8 08:41:22 janpekar01 proxmox-backup-proxy[610]: GET /previous: 400 Bad Request: Unable to open dynamic index "/opt/datastore01/host/vserver01/2022-10-07T08:33:17Z/homecloud.pxar.didx" - index too small (0) Oct 8 08:41:23 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_index Oct 8 08:41:23 janpekar01 proxmox-backup-proxy[610]: created new dynamic index 2 ("host/vserver01/2022-10-08T06:41:19Z/homecloud.pxar.didx") Oct 8 08:41:23 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 8 08:41:25 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 8 08:41:25 janpekar01 proxmox-backup-proxy[610]: upload_chunk done: 2445575 bytes, 7e0dca036b9e3affef9882a57ba3a8d4a80875e893fd63594de90379000ff59c Oct 8 08:41:25 janpekar01 proxmox-backup-proxy[610]: upload_chunk done: 1525230 bytes, 072096f0982eb104c4d05363132236319ce6d5894bea7d222e375c8c502a53fa Oct 8 08:41:27 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 8 08:41:28 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 8 08:41:28 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk Oct 8 08:41:28 janpekar01 proxmox-backup-proxy[610]: POST /dynamic_chunk

Listing of previous backup

-rw-r--r-- 1 backup backup 0 Oct 7 10:33 catalog.pcat1.didx
-rw-r--r-- 1 backup backup 0 Oct 7 10:33 homecloud.pxar.didx
-rw-r--r-- 1 backup backup 512 Oct 7 19:02 index.json.blob

Datastore is mounted over NFS, but I cannot see any problems in kern.log or other logs..

Is there any way how I can debug it?

Thank you

 

[jan.pekar]

I retried backup now, after 8 hours the same result

 

[dcsapak]

it seems to be problem that the server cannot correctly write the index files (for whatever reason)
can write normally to files on in the datastore directory?

 

[jan.pekar]

I tried now to backup (incrementally) VM on the same datastore and backup succeeded and I was able to restore some files.

I also noticed, that "corrupted" backup looks fine over the PBS web interface even it is unusable, because catalog and .pxar. files are zero size on the datastore filesystem. Only index.json.blob has few bytes..



Also GC has problem mentioning backup above..
...
2022-10-10T00:00:01+02:00: marked 46% (23 of 49 index files)
2022-10-10T00:00:01+02:00: marked 48% (24 of 49 index files)
2022-10-10T00:00:01+02:00: marked 51% (25 of 49 index files)
2022-10-10T00:00:01+02:00: TASK ERROR: can't read index '/opt/datastore01/host/vserver01/2022-10-07T08:33:17Z/homecloud.pxar.didx' - index too small (0)