vzdump status mails: invalid character encountered while parsing JSON....

[fips]

Hey,

since 2 days the vzdump backup notification mails does't contain the normal information (which VM, time spend, size, etc.).
It just showing: "invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411."

Well backup is made, no changes to cluster or VM/CTs made in the last week.

 

[Stoiko Ivanov]

could you please post:
* `pveversion -v`
* the backup task log of the tasks in question

Thanks!

 

[fips]

sure:

Spoiler: pveversion

proxmox-ve: 6.0-2 (running kernel: 5.0.21-1-pve)

pve-manager: 6.0-7 (running version: 6.0-7/28984024)

pve-kernel-5.0: 6.0-7

pve-kernel-helper: 6.0-7

pve-kernel-5.0.21-1-pve: 5.0.21-2

pve-kernel-5.0.18-1-pve: 5.0.18-3

pve-kernel-4.15.18-20-pve: 4.15.18-46

pve-kernel-4.13.13-2-pve: 4.13.13-33

ceph: 14.2.2-pve1

ceph-fuse: 14.2.2-pve1

corosync: 3.0.2-pve2

criu: 3.11-3

glusterfs-client: 5.5-3

ksm-control-daemon: 1.3-1

libjs-extjs: 6.0.1-10

libknet1: 1.11-pve1

libpve-access-control: 6.0-2

libpve-apiclient-perl: 3.0-2

libpve-common-perl: 6.0-4

libpve-guest-common-perl: 3.0-1

libpve-http-server-perl: 3.0-2

libpve-storage-perl: 6.0-8

libqb0: 1.0.5-1

lvm2: 2.03.02-pve3

lxc-pve: 3.1.0-64

lxcfs: 3.0.3-pve60

novnc-pve: 1.0.0-60

proxmox-mini-journalreader: 1.1-1

proxmox-widget-toolkit: 2.0-7

pve-cluster: 6.0-7

pve-container: 3.0-7

pve-docs: 6.0-4

pve-edk2-firmware: 2.20190614-1

pve-firewall: 4.0-7

pve-firmware: 3.0-2

pve-ha-manager: 3.0-2

pve-i18n: 2.0-3

pve-qemu-kvm: 4.0.0-5

pve-xtermjs: 3.13.2-1

qemu-server: 6.0-7

smartmontools: 7.0-pve2

spiceterm: 3.1-1

vncterm: 1.6-1

zfsutils-linux: 0.8.1-pve2

Spoiler: backuptask

INFO: starting new backup job: vzdump 108 601 602 608 107 116 607 301 120 --mode snapshot --mailnotification always --storage OffsiteBackup --quiet 1 --compress lzo --mailto admin@example.org
INFO: skip external VMs: 108, 601, 602, 608, 116, 301, 120
INFO: Starting Backup of VM 107 (qemu)
INFO: Backup started at 2019-09-25 22:55:02
INFO: status = running
INFO: invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.
INFO: update VM 107: -lock backup
INFO: VM Name: mx.example.org
INFO: include disk 'virtio0' 'hst_vm:vm-107-disk-1' 32G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/OffsiteBackup/dump/vzdump-qemu-107-2019_09_25-22_55_02.vma.lzo'
INFO: started backup task '2c0a8ee9-56c8-4795-84cf-44dd96352225'
INFO: status: 1% (543555584/34359738368), sparse 1% (377430016), duration 3, read/write 181/55 MB/s
INFO: status: 2% (748814336/34359738368), sparse 1% (396521472), duration 6, read/write 68/62 MB/s
INFO: status: 3% (1033895936/34359738368), sparse 1% (421847040), duration 11, read/write 57/51 MB/s
INFO: status: 4% (1388314624/34359738368), sparse 1% (474591232), duration 16, read/write 70/60 MB/s
INFO: status: 5% (1775108096/34359738368), sparse 1% (517402624), duration 21, read/write 77/68 MB/s
INFO: status: 6% (2071986176/34359738368), sparse 1% (525246464), duration 26, read/write 59/57 MB/s
INFO: status: 7% (2428502016/34359738368), sparse 1% (546422784), duration 45, read/write 18/17 MB/s
INFO: status: 17% (5943328768/34359738368), sparse 11% (4040163328), duration 48, read/write 1171/7 MB/s
INFO: status: 26% (9135194112/34359738368), sparse 20% (7178989568), duration 51, read/write 1063/17 MB/s
INFO: status: 27% (9388687360/34359738368), sparse 20% (7179014144), duration 54, read/write 84/84 MB/s
INFO: status: 28% (9705619456/34359738368), sparse 20% (7179018240), duration 59, read/write 63/63 MB/s
INFO: status: 29% (9966452736/34359738368), sparse 20% (7182864384), duration 63, read/write 65/64 MB/s
INFO: status: 30% (10346561536/34359738368), sparse 20% (7182880768), duration 68, read/write 76/76 MB/s
INFO: status: 31% (10669654016/34359738368), sparse 20% (7182884864), duration 72, read/write 80/80 MB/s
INFO: status: 32% (11018436608/34359738368), sparse 20% (7182888960), duration 77, read/write 69/69 MB/s
INFO: status: 33% (11342446592/34359738368), sparse 21% (7226568704), duration 81, read/write 81/70 MB/s
INFO: status: 34% (11702108160/34359738368), sparse 21% (7226613760), duration 85, read/write 89/89 MB/s
INFO: status: 35% (12038045696/34359738368), sparse 21% (7226626048), duration 99, read/write 23/23 MB/s
INFO: status: 36% (12418154496/34359738368), sparse 21% (7226712064), duration 106, read/write 54/54 MB/s
INFO: status: 37% (12775849984/34359738368), sparse 21% (7226712064), duration 112, read/write 59/59 MB/s
INFO: status: 38% (13077839872/34359738368), sparse 21% (7226712064), duration 116, read/write 75/75 MB/s
INFO: status: 39% (13448249344/34359738368), sparse 21% (7282425856), duration 120, read/write 92/78 MB/s
INFO: status: 40% (13769900032/34359738368), sparse 21% (7282475008), duration 124, read/write 80/80 MB/s
INFO: status: 41% (14128644096/34359738368), sparse 21% (7282847744), duration 129, read/write 71/71 MB/s
INFO: status: 42% (14512291840/34359738368), sparse 21% (7282868224), duration 139, read/write 38/38 MB/s
INFO: status: 43% (14805237760/34359738368), sparse 21% (7282868224), duration 144, read/write 58/58 MB/s
INFO: status: 44% (15154020352/34359738368), sparse 21% (7282868224), duration 153, read/write 38/38 MB/s
INFO: status: 45% (15539896320/34359738368), sparse 21% (7370153984), duration 157, read/write 96/74 MB/s
INFO: status: 46% (15808724992/34359738368), sparse 21% (7370235904), duration 160, read/write 89/89 MB/s
INFO: status: 47% (16188833792/34359738368), sparse 21% (7370252288), duration 165, read/write 76/76 MB/s
INFO: status: 48% (16500523008/34359738368), sparse 21% (7401721856), duration 171, read/write 51/46 MB/s
INFO: status: 49% (16865296384/34359738368), sparse 21% (7426973696), duration 178, read/write 52/48 MB/s
INFO: status: 50% (17241735168/34359738368), sparse 21% (7431213056), duration 184, read/write 62/62 MB/s
INFO: status: 51% (17641242624/34359738368), sparse 21% (7558692864), duration 189, read/write 79/54 MB/s
INFO: status: 52% (17880317952/34359738368), sparse 21% (7558721536), duration 193, read/write 59/59 MB/s
INFO: status: 53% (18236833792/34359738368), sparse 22% (7559815168), duration 198, read/write 71/71 MB/s
INFO: status: 54% (18583519232/34359738368), sparse 22% (7560065024), duration 204, read/write 57/57 MB/s
INFO: status: 55% (18899009536/34359738368), sparse 22% (7560081408), duration 210, read/write 52/52 MB/s
INFO: status: 57% (19658702848/34359738368), sparse 23% (8132960256), duration 214, read/write 189/46 MB/s
INFO: status: 63% (21940404224/34359738368), sparse 30% (10312761344), duration 217, read/write 760/33 MB/s
INFO: status: 70% (24071110656/34359738368), sparse 35% (12307521536), duration 220, read/write 710/45 MB/s
INFO: status: 78% (26826768384/34359738368), sparse 43% (14993543168), duration 223, read/write 918/23 MB/s
INFO: status: 88% (30274486272/34359738368), sparse 53% (18417438720), duration 226, read/write 1149/7 MB/s
INFO: status: 95% (32950452224/34359738368), sparse 61% (21012860928), duration 229, read/write 891/26 MB/s
INFO: status: 96% (33189527552/34359738368), sparse 61% (21037490176), duration 232, read/write 79/71 MB/s
INFO: status: 97% (33415364608/34359738368), sparse 61% (21043175424), duration 235, read/write 75/73 MB/s
INFO: status: 98% (33746059264/34359738368), sparse 61% (21045821440), duration 240, read/write 66/65 MB/s
INFO: status: 99% (34061942784/34359738368), sparse 61% (21049217024), duration 245, read/write 63/62 MB/s
INFO: status: 100% (34359738368/34359738368), sparse 61% (21204627456), duration 247, read/write 148/71 MB/s
INFO: transferred 34359 MB in 247 seconds (139 MB/s)
INFO: archive file size: 7.24GB
INFO: invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.
INFO: Finished Backup of VM 107 (00:04:11)
INFO: Backup finished at 2019-09-25 22:59:13
INFO: Starting Backup of VM 607 (qemu)
INFO: Backup started at 2019-09-25 22:59:13
INFO: status = running
INFO: invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.
INFO: update VM 607: -lock backup
INFO: VM Name: exsys2
INFO: include disk 'scsi0' 'hst_vm:vm-607-disk-1' 50G
INFO: include disk 'scsi1' 'hst_vm:vm-607-disk-2' 100G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating archive '/mnt/pve/OffsiteBackup/dump/vzdump-qemu-607-2019_09_25-22_59_13.vma.lzo'
INFO: started backup task '06ad2378-3466-4e02-9720-ff21b91bae29'
INFO: status: 0% (794427392/161061273600), sparse 0% (564248576), duration 3, read/write 264/76 MB/s
INFO: status: 1% (1649672192/161061273600), sparse 0% (637329408), duration 13, read/write 85/78 MB/s
INFO: status: 2% (3223322624/161061273600), sparse 0% (761409536), duration 46, read/write 47/43 MB/s
------cutted------
INFO: status: 98% (158817320960/161061273600), sparse 47% (75922116608), duration 1365, read/write 2167/0 MB/s
INFO: status: 100% (161061273600/161061273600), sparse 48% (78166056960), duration 1366, read/write 2243/0 MB/s
INFO: transferred 161061 MB in 1366 seconds (117 MB/s)
INFO: archive file size: 27.36GB
INFO: invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.
INFO: Finished Backup of VM 607 (00:22:48)
INFO: Backup finished at 2019-09-25 23:22:01
INFO: Backup job finished successfully
TASK OK

 

[Stoiko Ivanov]

hmm - something seems odd in a config-file - could you paste the output of:
* `grep -ri 'kv\/cep' /etc/pve`
* `pvesm status`
* `qm config 607`
* `qm list`

Thanks!

 

[fips]

sure:

Spoiler: grep -ri 'kv\/cep' /etc/pve

/etc/pve/.version:"kv/ceph-version": 50445,

/etc/pve/.version:"kv/ceph-mds": 50445,

/etc/pve/.version:"kv/ceph-mon": 50445,

/etc/pve/.version:"kv/ceph-mgr": 50445}

/etc/pve/.version:"kv/ceph-version": 50447,

/etc/pve/.version:"kv/ceph-mgr": 50447,

/etc/pve/.version:"kv/ceph-mon": 50447,

/etc/pve/.version:"kv/ceph-mds": 50447}

/etc/pve/.version:"kv/ceph-version": 50447,

/etc/pve/.version:"kv/ceph-mgr": 50447,

/etc/pve/.version:"kv/ceph-mon": 50447,

/etc/pve/.version:"kv/ceph-mds": 50447}

/etc/pve/.version:"kv/ceph-version": 50446,

/etc/pve/.version:"kv/ceph-mds": 50446,

/etc/pve/.version:"kv/ceph-mon": 50446,

/etc/pve/.version:"kv/ceph-mgr": 50446}

/etc/pve/.version:"kv/ceph-version": 50446,

/etc/pve/.version:"kv/ceph-mgr": 50446,

/etc/pve/.version:"kv/ceph-mon": 50446,

/etc/pve/.version:"kv/ceph-mds": 50446}

/etc/pve/.version:"kv/ceph-version": 50447,

/etc/pve/.version:"kv/ceph-mgr": 50448,

/etc/pve/.version:"kv/ceph-mon": 50448,

/etc/pve/.version:"kv/ceph-mds": 50448}

Spoiler: pvesm status

invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411, <DATA> line 755.

Name Type Status Total Used Available %

Archiv nfs active 14737605376 9325388928 5412216448 63.28%

Backup nfs active 6468182656 1055966208 5412216448 16.33%

OffsiteBackup nfs active 6198391424 786174976 5412216448 12.68%

ceph_ct rbd active 3747940719 2183146223 1564794496 58.25%

ceph_vm rbd active 3747940719 2183146223 1564794496 58.25%

local dir active 30316484 4424508 24328944 14.59%

local-zfs zfspool disabled 0 0 0 N/A

Spoiler: qm config 607

invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.

balloon: 0

boot: cdn

bootdisk: scsi0

cores: 4

ide2: Backup:iso/server2019.ISO,media=cdrom,size=4779696K

memory: 10240

name: exsys2

net0: virtio=42:91:80:48:56:78,bridge=vmbr1,tag=20

numa: 0

onboot: 1

ostype: win10

scsi0: ceph_vm:vm-607-disk-1,discard=on,size=50G

scsi1: ceph_vm:vm-607-disk-2,discard=on,size=100G

scsihw: virtio-scsi-pci

smbios1: uuid=b3ff5d94-8249-4e8c-a3cf-9d01a5432f58

sockets: 1

Spoiler: qm list

invalid character encountered while parsing JSON string, at character offset 724 (before "\x{16}": 0,\n"kv/cep...") at /usr/share/perl5/PVE/Cluster.pm line 411.
VMID NAME STATUS MEM(MB) BOOTDISK(GB) PID
107 mx.example.org running 4096 32.00 4182
401 pbx5.example.org running 1024 5.00 11735
603 rdscontsys1 running 4096 32.00 5125
607 exsys2 running 10240 50.00 5430

Thanks!

 

[Stoiko Ivanov]

could you upload '/etc/pve/.versions' as file? (please edit sensitive information if needed, but please keep the file as pristine as possible)

Thanks!

 

[fips]

can I send it via mail or PN? than I would not need to edit sensitive info.

 

[Stoiko Ivanov]

e-mail would work fine: s.ivanov _at_ proxmox.com

Thanks!

 

[Stoiko Ivanov]

Thanks for the file - there are some strange entries in the kvstore of ceph5 and ceph8.

please check the journal for messages from 'pmxcfs' (a.k.a. pve-cluster)
please try to:
* restart pmxcfs on both nodes (ceph5 and ceph8): `systemctl restart pve-cluster`
* you can check the file with 'cat -A /etc/pve/.versions' - the problematic key is displayed as "a^V":
* alternatively install `jq` and check with `cat /etc/pve/.versions |jq`

If this does not help you'd need to restart pmxcfs on all nodes at the same time (or stop it everywhere and start it after it's stopped on all nodes)

Hope this helps!

 

[fips]

strange... I checked .version on ceph8: there was not such key attribut list of ceph8.
So I went back to the problematic ceph7. There I could find that "a^V" ( or somthing like that).
On ceph7 I restarted: pve-cluster, pveproxy pvedaemon and pvestatd and checked again that file.
The problematic key in ceph5 and ceph8 disappeared...

Well I am also one of these guys who have problems with offline nodes within the gui since 6.0.
Maybe this is somehow related?

 

[Stoiko Ivanov]

Well I am also one of these guys who have problems with offline nodes within the gui since 6.0.
Maybe this is somehow related?

this could be related - I would do a thorough check of the hardware (e.g. let memtest86 run for a while)

else - check the logs for messages from pve-cluster, pvestatd, pmxcfs

I hope this helps!