[SOLVED] Restore from LTO " parameter verification errors store"

[ElvisCZ]

Hello, because I not to find an answer, I would ask for information on whether the length of the parameter name of the file / storage / namespace is limited when saving / restoring data from tape (LTO 7).

My problem is that the backup to tape runs OK. But when restoring I get repeatedly error “ "parameter verification errors store: unable to parse array element: value may only be 65 characters long"”.

The tape drive is newly installed, the tapes are new and newly initialized. I perform recovery to different namespaces, under different permissions, incl. root. The error is still the same.

Spoiler: PBS version

proxmox-backup: 2.4-1 (running kernel: 5.15.107-2-pve)
proxmox-backup-server: 2.4.2-1 (running version: 2.4.2)
pve-kernel-5.15: 7.4-3
pve-kernel-6.2.11-2-pve: 6.2.11-2
pve-kernel-5.15.107-2-pve: 5.15.107-2
pve-kernel-5.15.107-1-pve: 5.15.107-1
pve-kernel-5.15.39-4-pve: 5.15.39-4
pve-kernel-5.15.35-1-pve: 5.15.35-3
ifupdown2: 3.1.0-1+pmx4
libjs-extjs: 7.0.0-1
proxmox-backup-docs: 2.4.2-1
proxmox-backup-client: 2.4.2-1
proxmox-mail-forward: not correctly installed
proxmox-mini-journalreader: 1.2-1
proxmox-offline-mirror-helper: not correctly installed
proxmox-widget-toolkit: 3.7.0
pve-xtermjs: 4.16.0-1
smartmontools: 7.2-pve3
zfsutils-linux: 2.1.11-pve1

Spoiler: Backup Log

()
2023-06-01T09:33:22+02:00: Starting tape backup job 'externi-pole:media-pool-01:hq-lto-01:test1-archiv'
2023-06-01T09:33:22+02:00: update media online status
2023-06-01T09:33:22+02:00: media set uuid: 3f33a33b-9804-4362-8430-bd3da6ec5556
2023-06-01T09:33:22+02:00: found 8 groups
2023-06-01T09:33:22+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/100/2023-03-23T09:15:12Z"
2023-06-01T09:35:01+02:00: allocated new writable media 'CZS361L7'
2023-06-01T09:35:01+02:00: trying to load media 'CZS361L7' into drive 'hq-lto-01'
2023-06-01T09:35:38+02:00: found media label CZS361L7 (8d113d01-85f4-4395-9e88-25679b124519)
2023-06-01T09:35:38+02:00: writing new media set label
2023-06-01T09:35:53+02:00: moving to end of media
2023-06-01T09:35:56+02:00: arrived at end of media
2023-06-01T09:37:00+02:00: wrote 1536 chunks (4295.75 MB at 66.33 MB/s)
2023-06-01T09:38:04+02:00: wrote 1540 chunks (4295.75 MB at 67.22 MB/s)
2023-06-01T09:39:07+02:00: wrote 1477 chunks (4295.23 MB at 68.58 MB/s)
2023-06-01T09:40:08+02:00: wrote 1473 chunks (4298.90 MB at 70.32 MB/s)
2023-06-01T09:41:26+02:00: wrote 1491 chunks (4298.90 MB at 55.12 MB/s)
2023-06-01T09:42:39+02:00: wrote 1490 chunks (4295.75 MB at 59.36 MB/s)
2023-06-01T09:44:10+02:00: wrote 1534 chunks (4299.16 MB at 46.95 MB/s)
2023-06-01T09:45:39+02:00: wrote 1529 chunks (4296.02 MB at 48.33 MB/s)
2023-06-01T09:47:11+02:00: wrote 1802 chunks (4295.75 MB at 46.89 MB/s)
2023-06-01T09:48:17+02:00: wrote 1361 chunks (2826.44 MB at 42.61 MB/s)
2023-06-01T09:48:17+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/100/2023-03-23T09:15:12Z"
2023-06-01T09:48:17+02:00: percentage done: 12.50% (1/8 groups)
2023-06-01T09:48:17+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/101/2022-10-27T09:54:14Z"
2023-06-01T09:51:15+02:00: wrote 1908 chunks (4296.28 MB at 40.50 MB/s)
2023-06-01T09:52:50+02:00: wrote 1961 chunks (4296.28 MB at 44.96 MB/s)
2023-06-01T09:53:48+02:00: wrote 1335 chunks (2839.02 MB at 49.57 MB/s)
2023-06-01T09:53:48+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/101/2022-10-27T09:54:14Z"
2023-06-01T09:53:48+02:00: percentage done: 25.00% (2/8 groups)
2023-06-01T09:53:48+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/125/2023-01-18T12:55:27Z"
2023-06-01T09:57:36+02:00: wrote 3230 chunks (4298.64 MB at 38.28 MB/s)
2023-06-01T09:59:28+02:00: wrote 3198 chunks (4295.75 MB at 38.20 MB/s)
2023-06-01T10:00:18+02:00: wrote 1164 chunks (1811.68 MB at 36.35 MB/s)
2023-06-01T10:00:18+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/125/2023-01-18T12:55:27Z"
2023-06-01T10:00:18+02:00: percentage done: 37.50% (3/8 groups)
2023-06-01T10:00:18+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/134/2023-01-19T08:19:56Z"
2023-06-01T10:03:17+02:00: wrote 3366 chunks (4295.49 MB at 40.16 MB/s)
2023-06-01T10:04:24+02:00: wrote 2181 chunks (2759.33 MB at 41.15 MB/s)
2023-06-01T10:04:24+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/134/2023-01-19T08:19:56Z"
2023-06-01T10:04:24+02:00: percentage done: 50.00% (4/8 groups)
2023-06-01T10:04:24+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/142/2023-01-18T12:54:40Z"
2023-06-01T10:07:20+02:00: wrote 1853 chunks (4295.49 MB at 51.32 MB/s)
2023-06-01T10:08:41+02:00: wrote 1864 chunks (4295.49 MB at 52.74 MB/s)
2023-06-01T10:10:07+02:00: wrote 1986 chunks (4295.75 MB at 50.20 MB/s)
2023-06-01T10:10:38+02:00: wrote 679 chunks (1143.73 MB at 36.98 MB/s)
2023-06-01T10:10:38+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/142/2023-01-18T12:54:40Z"
2023-06-01T10:10:38+02:00: percentage done: 62.50% (5/8 groups)
2023-06-01T10:10:38+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/178/2023-01-19T08:23:35Z"
2023-06-01T10:15:47+02:00: wrote 3618 chunks (4295.23 MB at 37.53 MB/s)
2023-06-01T10:17:42+02:00: wrote 3625 chunks (4295.23 MB at 37.35 MB/s)
2023-06-01T10:19:39+02:00: wrote 3689 chunks (4296.54 MB at 36.84 MB/s)
2023-06-01T10:21:35+02:00: wrote 3589 chunks (4296.02 MB at 37.09 MB/s)
2023-06-01T10:22:22+02:00: wrote 1438 chunks (1658.59 MB at 35.40 MB/s)
2023-06-01T10:22:22+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/178/2023-01-19T08:23:35Z"
2023-06-01T10:22:22+02:00: percentage done: 75.00% (6/8 groups)
2023-06-01T10:22:22+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/444/2022-10-27T10:13:19Z"
2023-06-01T10:27:17+02:00: wrote 4653 chunks (4296.28 MB at 34.23 MB/s)
2023-06-01T10:29:26+02:00: wrote 4573 chunks (4296.28 MB at 33.39 MB/s)
2023-06-01T10:31:37+02:00: wrote 4491 chunks (4298.38 MB at 32.76 MB/s)
2023-06-01T10:31:59+02:00: wrote 808 chunks (674.23 MB at 31.11 MB/s)
2023-06-01T10:31:59+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/444/2022-10-27T10:13:19Z"
2023-06-01T10:31:59+02:00: percentage done: 87.50% (7/8 groups)
2023-06-01T10:31:59+02:00: backup snapshot "ns/X-archiv-ukoncenych-projektu/vm/445/2022-10-27T10:38:15Z"
2023-06-01T10:42:53+02:00: wrote 6345 chunks (4295.23 MB at 24.43 MB/s)
2023-06-01T10:45:58+02:00: wrote 6792 chunks (4295.75 MB at 23.31 MB/s)
2023-06-01T10:49:04+02:00: wrote 6317 chunks (4297.85 MB at 23.13 MB/s)
2023-06-01T10:52:28+02:00: wrote 6383 chunks (4295.75 MB at 21.02 MB/s)
2023-06-01T10:56:26+02:00: wrote 6300 chunks (4295.75 MB at 18.06 MB/s)
2023-06-01T10:59:47+02:00: wrote 4403 chunks (2921.33 MB at 15.05 MB/s)
2023-06-01T10:59:52+02:00: end backup externi-pole:"ns/X-archiv-ukoncenych-projektu/vm/445/2022-10-27T10:38:15Z"
2023-06-01T10:59:52+02:00: percentage done: 100.00% (8/8 groups)
2023-06-01T10:59:52+02:00: append media catalog
2023-06-01T10:59:52+02:00: TASK OK

Spoiler: PMT cartridge

pmt cartridge-memory
using device /dev/tape/by-id/scsi-C0180D60BD-sg
0|Remaining Capacity In Partition|5589652
1|Maximum Capacity In Partition|5722045
2|Tapealert Flags|(empty)
3|Load Count|15
4|MAM Space Remaining|3024
5|Assigning Organization|LTO-CVE
6|Formatted Density Code|5c
7|Initialization Count|5
9|Volume Change Reference|00000013
522|Device Vendor/Serial Number at Last Load|HP      CZ2317014K                                                                                                                                               
523|Device Vendor/Serial Number at Load-1|HP      CZ2317014K                                                                                                                                                 
524|Device Vendor/Serial Number at Load-2|HP      CZ2317014K                                                                                                                                                 
525|Device Vendor/Serial Number at Load-3|HP      CZ2317014K                                                                                                                                                 
544|Total MBytes Written in Medium Life|134394
545|Total MBytes Read In Medium Life|614
546|Total MBytes Written in Current Load|0
547|Total MBytes Read in Current/Last Load|466
548|Logical Position of First Encrypted Block|ffffffffffffffff
549|Logical Position of First Unencrypted Block After the First Encrypted Block|                                                                                                                              ffffffffffffffff
1024|Medium Manufacturer|HPE
1025|Medium Serial Number|V221128039
1026|Medium Length|960
1027|Medium Width|127
1028|Assigning Organization|LTO-CVE
1029|Medium Density Code|5c
1030|Medium Manufacture Date|20221128
1031|MAM Capacity|16352
1032|Medium Type|00
1033|Medium Type Information|0000
2054|Barcode|CZS361L7
4096|Unique Cartridge Identify (UCI)|6c5c71332a32323037323831534f4e5920202020001                                                                                                                              0a43a00400000
4097|Alternate Unique Cartridge Identify (Alt-UCI)|33715c6c4a4c37573031343756323                                                                                                                              2313132383033390040

data recovery wizard error:



Storage is Directory (not ZFS) .
Same problem is on Kernel 6.2 and 5.15.
thank you in advance, Petr

 

[dcsapak]

can you also post the first page of the recovery window? what is the source datastores you want to restore from?

 

[ElvisCZ]

yes:

 

[dcsapak]

can you post your versions of the pbs (with 'proxmox-backup-manager versions --verbose')

also could you open the developer console and check what the parameters are for the api call that gets made?
this should be in the network tab a 'POST' request that failed

 

[ElvisCZ]

proxmox-backup-manager version --verbose
proxmox-backup                2.4-1        running kernel: 5.15.107-2-pve
proxmox-backup-server         2.4.2-1      running version: 2.4.2
pve-kernel-5.15               7.4-3
pve-kernel-6.2.11-2-pve       6.2.11-2
pve-kernel-5.15.107-2-pve     5.15.107-2
pve-kernel-5.15.107-1-pve     5.15.107-1
pve-kernel-5.15.39-4-pve      5.15.39-4
pve-kernel-5.15.35-1-pve      5.15.35-3
ifupdown2                     3.1.0-1+pmx4
libjs-extjs                   7.0.0-1
proxmox-backup-docs           2.4.2-1
proxmox-backup-client         2.4.2-1
proxmox-mail-forward          unknown
proxmox-mini-journalreader    1.2-1
proxmox-offline-mirror-helper unknown
proxmox-widget-toolkit        3.7.0
pve-xtermjs                   4.16.0-2
smartmontools                 7.2-pve3
zfsutils-linux                2.1.11-pve1

The error is the same whether I go to PBS directly at https://servername:8007 or through the proxy https://nicename.ltd, so there is no error in this either.

 

[dcsapak]

thats the correct request, but i'd require the content of the 'parameter' (or 'payload') tab on the right

 

[ElvisCZ]

Oh, ok, better?

media-set=3f33a33b-9804-4362-8430-bd3da6ec5556&snapshots=externi-pole%3Ans%2FX-archiv-ukoncenych-projektu%2Fvm%2F100%2F2023-03-23T09%3A15%3A12Z&notify-user=root%40pam&owner=root%40pam&drive=hq-lto-01&namespaces=store%3Dexterni-pole%2Ctarget%3DXXX-LTO&store=externi-pole%3Ans%2FX-archiv-ukoncenych-projektu%2Fvm%2F100%2F2023-03-23T09%3A15%3A12Z%3Dexterni-pole

{"errors":{"store":"unable to parse array element: value may only be 65 characters long"},"message":"parameter verification errors","success":false}

 

[dcsapak]

ok it seems the gui sends the wrong request, the snapshot should not be included in the 'store' parameter

i could reproduce the error here, and sent a fix to the list:
https://lists.proxmox.com/pipermail/pbs-devel/2023-June/006146.html

 

[ElvisCZ]

Thanks for the fix. works great!
Petr