can not start sync: could not open statefile for daily-remote-sync

[RobFantini]

full error - at pbs web page after clicking configuration > Sync Jobs:

    could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters

/etc/proxmox-backup/sync.cfg :

sync: daily-remote-sync
        remote pbs
        remote-store daily
        remove-vanished true
        schedule hourly
        store daily-remote-sync

systemd shows error

systemctl status proxmox-backup-proxy.service

● proxmox-backup-proxy.service - Proxmox Backup API Proxy Server
   Loaded: loaded (/lib/systemd/system/proxmox-backup-proxy.service; enabled; vendor preset: enabled)
   Active: active (running) since Sat 2020-09-05 16:24:42 EDT; 13min ago
Main PID: 6559 (proxmox-backup-)
    Tasks: 42 (limit: 6143)
   Memory: 26.4M
   CGroup: /system.slice/proxmox-backup-proxy.service
           └─6559 /usr/lib/x86_64-linux-gnu/proxmox-backup/proxmox-backup-proxy

Sep 05 16:33:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:34:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:35:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:36:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:37:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:37:50 s022 proxmox-backup-proxy[6559]: GET /api2/json/admin/sync: 400 Bad Request: [client [::ffff:172.30.24.11]:54046] could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:37:55 s022 proxmox-backup-proxy[6559]: GET /api2/json/admin/sync: 400 Bad Request: [client [::ffff:172.30.24.11]:54046] could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:38:00 s022 proxmox-backup-proxy[6559]: could not get last run time of syncjob daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:38:00 s022 proxmox-backup-proxy[6559]: GET /api2/json/admin/sync: 400 Bad Request: [client [::ffff:172.30.24.11]:54046] could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters
Sep 05 16:38:05 s022 proxmox-backup-proxy[6559]: GET /api2/json/admin/sync: 400 Bad Request: [client [::ffff:172.30.24.11]:54046] could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '07:24Z" done': input contains invalid characters

this did not fix

systemctl restart proxmox-backup*

I do not know how to get version from cli. this is from /var/log/apt/history.log

Start-Date: 2020-09-03  12:42:41
Commandline: apt -y dist-upgrade
Upgrade: libpve-storage-perl:amd64 (6.2-5, 6.2-6), pve-qemu-kvm:amd64 (5.0.0-11, 5.0.0-13), pve-ha-manager:amd64 (3.0-9
, 3.1-1), pve-container:amd64 (3.1-12, 3.1-13), proxmox-backup-server:amd64 (0.8.13-1, 0.8.14-1), proxmox-backup-client
:amd64 (0.8.13-1, 0.8.14-1), alpine:amd64 (2.20+dfsg1-7, 2.21+dfsg1-1.1), vncterm:amd64 (1.6-1, 1.6-2), pve-manager:amd
64 (6.2-10, 6.2-11), proxmox-backup-docs:amd64 (0.8.13-1, 0.8.14-1), libpve-common-perl:amd64 (6.1-5, 6.2-1), lxc-pve:a
md64 (4.0.2-1, 4.0.3-1), qemu-server:amd64 (6.2-11, 6.2-14), libproxmox-backup-qemu0:amd64 (0.6.2-1, 0.6.4-1)
End-Date: 2020-09-03  12:43:07

also tried rebooting the host. did not fix.

the issue could have been caused by this during an active sync
in a crontab we do this to try to handle multi day stuck sync:

systemctl restart proxmox-backup-proxy.service

In addition I did shutdown the host to replace a part. sync could have been in progress.

PS: the pbs backup system and local network remote sync are having no issues at all. the host with issue is on WAN network.

 

[dcsapak]

hi, can you post the relevant statefile and the task log?

the statefile should be under '/var/lib/proxmox-backup/jobstates/syncjob-daily-remote-sync.json'
in there you should find a upid which leads to the tasklog
'find /var/log/proxmox-backup/tasks/ -iname "theupidfromthestatefile"'

 

[RobFantini]

hi, can you post the relevant statefile and the task log?

{"started":{"upid":"UPID:s022:00001A75:00000669:00000000:5F53A7F0:syncjob:daily-remote-sync:backup@pam:"}}

 

[dcsapak]

please also the task log from /var/log/proxmox-backup/tasks/

i guess this will be fixed by this patch https://lists.proxmox.com/pipermail/pbs-devel/2020-September/000535.html
(we previously tried to parse only part of lines from the task log, which fails in your case)

 

[RobFantini]

when I posted my reply I had not done the find - and renamed the jobstatefile to fix backups. sync error went away and sync worked.

now the find command does not return anything . here is what I tried:

find /var/log/proxmox-backup/tasks/ -iname s022:0000199F:00000670

find /var/log/proxmox-backup/tasks/ -iname 0000199F

I'll move back the original syncjob-daily-remote-sync.json file to see iI can recreate the issue - after the sync finishes.

 

[dcsapak]

the correct find command would be

find /var/log/proxmox-backup/tasks -iname "UPID:s022:00001A75:00000669:00000000:5F53A7F0:syncjob:daily-remote-sync:backup@pam:"

 

[RobFantini]

the correct find command would be

find /var/log/proxmox-backup/tasks -iname "UPID:s022:00001A75:00000669:00000000:5F53A7F0:syncjob:daily-remote-sync:backup@pam:"

# find /var/log/proxmox-backup/tasks -iname "UPID:s022:00001A75:00000669:00000000:5F53A7F0:syncjob:daily-remote-sync:backup@pam:"
/var/log/proxmox-backup/tasks/69/UPID:s022:00001A75:00000669:00000000:5F53A7F0:syncjob:daily-remote-sync:backup@pam:

 

[RobFantini]

the remote system was all caught up on syncs. I had checked a couple hours ago and there were short hourly syncs. now there is the following:

could not open statefile for daily-remote-sync: error reading upid log status: cannot parse '"vm/102/2020-09-09T22:30:02Z" done': input contains invalid characters

end of day here will check back later.

 

[dcsapak]

yeah as i said im 99% sure that the fix i mentioned earlier will fix this (no package released yet though)

 

[RobFantini]

is there a reccommended way to get the syncs working by hand? for now I do this:

mv syncjob-daily-remote-sync.json syncjob-daily-remote-sync.json-bad

here is more info:

# cat /var/lib/proxmox-backup/jobstates/syncjob-daily-remote-sync.json
{"started":{"upid":"UPID:s022:0000199F:00000670:00000027:5F595E70:syncjob:daily-remote-sync:backup@pam:"}}root@s022:[/var/lib/proxmox-backup/jobstates]:#

find /var/log/proxmox-backup/tasks -iname "UPID:s022:0000199F:00000670:00000027:5F595E70:syncjob:daily-remote-sync:backup@pam:"
/var/log/proxmox-backup/tasks/70/UPID:s022:0000199F:00000670:00000027:5F595E70:syncjob:daily-remote-sync:backup@pam:

## last part of that file:
020-09-09T20:24:23-04:00: re-sync snapshot "vm/3120/2020-09-08T22:33:52Z" done
2020-09-09T20:24:23-04:00: sync snapshot "vm/3120/2020-09-09T22:34:06Z"
2020-09-09T20:24:23-04:00: sync archive qemu-server.conf.blob
2020-09-09T20:24:23-04:00: sync archive drive-scsi0.img.fidx
2020-09-09T20:30:45-04:00: got backup log file "client.log.blob"
2020-09-09T20:30:45-04:00: sync snapshot "vm/3120/2020-09-09T22:34:06Z" done
2020-09-09T20:30:45-04:00: re-sync snapshot "vm/446/2020-09-08T22:16:27Z"
2020-09-09T20:30:45-04:00: no data changes
2020-09-09T20:30:45-04:00: re-sync snapshot "vm/446/2020-09-08T22:16:27Z" done
2020-09-09T20:30:45-04:00: sync snapshot "vm/446/2020-09-09T22:16:30Z"
2020-09-09T20:30:45-04:00: sync archive qemu-server.conf.blob
2020-09-09T20:30:45-04:00: sync archive drive-ide0.img.fidx

 

[dcsapak]

there should be and update pushed to the repos already, so an update should fix it
maybe you have to delete and recreate the sync job

 

[RobFantini]

there should be and update pushed to the repos already, so an update should fix it
maybe you have to delete and recreate the sync job

OK thank you.