PBS 1.1.10-1 to 1.1.12-1 broken?

[Ansy]

PVE 6.4-13 with PBS co-installed, working well for many days...

As usual, I've apt-get update (from Web-interface), three packages proxmox-backup-* pending... well, I've pressed button to apt-get dist-upgrade, no strange messages.

But PBS Web-interface on 8007 port doesn't responding, PBS storage isn't active in PVE Web-interface.

May be log below will help to investigate the reason? The problem is critical... No new backups, no access to old backups.

Jul 13 12:49:39 pve31 systemd[1]: Started Daily apt download activities.
Jul 13 12:49:39 pve31 systemd[1]: Reloading.
Jul 13 12:49:39 pve31 systemd[1]: /lib/systemd/system/rpc-statd.service:13: PIDFile= references path below legacy directory /var/run/, updating /var/run/rpc.statd.pid â /run/rpc.statd.pid; please update the unit file accordingly.
Jul 13 12:49:40 pve31 systemd[1]: proxmox-backup-daily-update.timer: Succeeded.
Jul 13 12:49:40 pve31 systemd[1]: Stopped Daily Proxmox Backup Server update and maintenance activities.
Jul 13 12:49:40 pve31 systemd[1]: Stopping Daily Proxmox Backup Server update and maintenance activities.
Jul 13 12:49:40 pve31 systemd[1]: Started Daily Proxmox Backup Server update and maintenance activities.
Jul 13 12:49:41 pve31 systemd[1]: Reloading.
Jul 13 12:49:41 pve31 systemd[1]: /lib/systemd/system/rpc-statd.service:13: PIDFile= references path below legacy directory /var/run/, updating /var/run/rpc.statd.pid â /run/rpc.statd.pid; please update the unit file accordingly.
Jul 13 12:49:41 pve31 systemd[1]: Reloading Proxmox Backup API Server.
Jul 13 12:49:41 pve31 systemd[1]: Reloaded Proxmox Backup API Server.
Jul 13 12:49:41 pve31 systemd[1]: Reloading Proxmox Backup API Proxy Server.
Jul 13 12:49:41 pve31 systemd[1]: Reloaded Proxmox Backup API Proxy Server.
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: got reload request (SIGHUP)
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: daemon reload...
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: got reload request (SIGHUP)
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: daemon reload...
Jul 13 12:49:42 pve31 systemd[1]: proxmox-backup-proxy.service: Supervising process 6881 which is not our child. We'll most likely not notice when it exits.
Jul 13 12:49:43 pve31 proxmox-backup-proxy[6881]: Error: Permission denied (os error 13)
Jul 13 12:49:43 pve31 pveupgrade[4779]: update new package list: /var/lib/pve-manager/pkgupdates
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: daemon shut down...
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: server shutting down, waiting for active workers to complete
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: done - exit server
Jul 13 12:49:44 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:49:50 pve31 pvedaemon[14029]: <root@pam> end task UPID:pve31:00001294:0613C242:60ED4562:vncshell::root@pam: OK
Jul 13 12:49:55 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:00 pve31 systemd[1]: Starting Proxmox VE replication runner...
Jul 13 12:50:01 pve31 pveproxy[1985]: worker exit
Jul 13 12:50:01 pve31 pveproxy[2286]: worker 1985 finished
Jul 13 12:50:01 pve31 pveproxy[2286]: starting 1 worker(s)
Jul 13 12:50:01 pve31 pveproxy[2286]: worker 7316 started
Jul 13 12:50:01 pve31 systemd[1]: pvesr.service: Succeeded.
Jul 13 12:50:01 pve31 systemd[1]: Started Proxmox VE replication runner.
Jul 13 12:50:04 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:14 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:25 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:35 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:45 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:50:55 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:00 pve31 systemd[1]: Starting Proxmox VE replication runner...
Jul 13 12:51:01 pve31 systemd[1]: pvesr.service: Succeeded.
Jul 13 12:51:01 pve31 systemd[1]: Started Proxmox VE replication runner.
Jul 13 12:51:05 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:11 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:51:14 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:24 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:35 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:45 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back
Jul 13 12:51:50 pve31 pvedaemon[14029]: <root@pam> successful auth for user 'root@pam'
Jul 13 12:51:55 pve31 pvestatd[2216]: pbs: error fetching datastores - 500 Server closed connection without sending any data back

 

[fiona]

Hi,
please share the output of pveversion -v and proxmox-backup-manager versions --verbose. Is there some additional information in the journal: journalctl -b0 -u proxmox-backup-proxy.service and journalctl -b0 -u proxmox-backup.service?

 

[Ansy]

Well, I've managed the issue manually by systemctl restart proxmox-backup-proxy.service.

But if I'd miswatched PBS not working, it would be the real problem after some time.

pveversion -v

proxmox-ve: 6.4-1 (running kernel: 5.4.124-1-pve)
pve-manager: 6.4-13 (running version: 6.4-13/9f411e79)
pve-kernel-5.4: 6.4-4
pve-kernel-helper: 6.4-4
pve-kernel-5.3: 6.1-6
pve-kernel-5.4.124-1-pve: 5.4.124-1
pve-kernel-5.4.119-1-pve: 5.4.119-1
pve-kernel-5.4.106-1-pve: 5.4.106-1
pve-kernel-5.3.18-3-pve: 5.3.18-3
ceph-fuse: 12.2.11+dfsg1-2.1+b1
corosync: 3.1.2-pve1
criu: 3.11-3
glusterfs-client: 5.5-3
ifupdown: residual config
ifupdown2: 3.0.0-1+pve4~bpo10
ksm-control-daemon: 1.3-1
libjs-extjs: 6.0.1-10
libknet1: 1.20-pve1
libproxmox-acme-perl: 1.1.0
libproxmox-backup-qemu0: 1.1.0-1
libpve-access-control: 6.4-3
libpve-apiclient-perl: 3.1-3
libpve-common-perl: 6.4-3
libpve-guest-common-perl: 3.1-5
libpve-http-server-perl: 3.2-3
libpve-storage-perl: 6.4-1
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 4.0.6-2
lxcfs: 4.0.6-pve1
novnc-pve: 1.1.0-1
proxmox-backup-client: 1.1.12-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.6-1
pve-cluster: 6.4-1
pve-container: 3.3-6
pve-docs: 6.4-2
pve-edk2-firmware: 2.20200531-1
pve-firewall: 4.1-4
pve-firmware: 3.2-4
pve-ha-manager: 3.1-1
pve-i18n: 2.3-1
pve-qemu-kvm: 5.2.0-6
pve-xtermjs: 4.7.0-3
qemu-server: 6.4-2
smartmontools: 7.2-pve2
spiceterm: 3.1-1
vncterm: 1.6-2
zfsutils-linux: 2.0.4-pve1

proxmox-backup-manager versions --verbose

proxmox-backup             1.0-4              running kernel: 5.4.124-1-pve
proxmox-backup-server      1.1.12-1           running version: 1.1.12     
pve-kernel-5.4             6.4-4                                           
pve-kernel-helper          6.4-4                                           
pve-kernel-5.3             6.1-6                                           
pve-kernel-5.4.124-1-pve   5.4.124-1                                       
pve-kernel-5.4.119-1-pve   5.4.119-1                                       
pve-kernel-5.4.106-1-pve   5.4.106-1                                       
pve-kernel-5.3.18-3-pve    5.3.18-3                                       
ifupdown2                  3.0.0-1+pve4~bpo10                             
libjs-extjs                6.0.1-10                                       
proxmox-backup-docs        1.1.12-1                                       
proxmox-backup-client      1.1.12-1                                       
proxmox-mini-journalreader 1.1-1                                           
proxmox-widget-toolkit     2.6-1                                           
pve-xtermjs                4.7.0-3                                         
smartmontools              7.2-pve2                                       
zfsutils-linux             2.0.4-pve1

journalctl -b0 -u proxmox-backup-proxy.service

Jul 13 12:41:23 pve31 proxmox-backup-proxy[2012]: GET /api2/json/admin/datastore: 401 Unauthorized: [client [::ffff:10.150.10.250]:46040] authentication failed - invali
Jul 13 12:41:23 pve31 proxmox-backup-proxy[2012]: GET /api2/json/nodes/localhost/tasks?running=1&limit=100: 401 Unauthorized: [client [::ffff:10.150.10.250]:46042] auth
Jul 13 12:41:23 pve31 proxmox-backup-proxy[2012]: GET /api2/json/nodes/localhost/tasks?limit=0&since=1623483960: 401 Unauthorized: [client [::ffff:10.150.10.250]:46050]
Jul 13 12:41:23 pve31 proxmox-backup-proxy[2012]: GET /api2/json/status/datastore-usage: 401 Unauthorized: [client [::ffff:10.150.10.250]:46048] authentication failed -
Jul 13 12:41:24 pve31 proxmox-backup-proxy[2012]: GET /api2/json/admin/datastore: 401 Unauthorized: [client [::ffff:10.150.10.250]:46052] authentication failed - invali
Jul 13 12:49:41 pve31 systemd[1]: Reloading Proxmox Backup API Proxy Server.
Jul 13 12:49:41 pve31 systemd[1]: Reloaded Proxmox Backup API Proxy Server.
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: got reload request (SIGHUP)
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-proxy[2012]: daemon reload...
Jul 13 12:49:42 pve31 systemd[1]: proxmox-backup-proxy.service: Supervising process 6881 which is not our child. We'll most likely not notice when it exits.
Jul 13 12:49:43 pve31 proxmox-backup-proxy[6881]: Error: Permission denied (os error 13)
Jul 13 12:51:11 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:52:42 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:54:12 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:55:42 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:57:12 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 12:58:43 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:00:13 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:01:43 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:03:13 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:04:44 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:06:14 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:07:44 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:09:14 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:10:45 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:12:15 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:13:45 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:15:15 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:16:45 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:18:15 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:19:45 pve31 systemd[1]: proxmox-backup-proxy.service: Reload operation timed out. Killing reload process.
Jul 13 13:20:37 pve31 systemd[1]: proxmox-backup-proxy.service: Main process exited, code=killed, status=15/TERM
Jul 13 13:20:37 pve31 systemd[1]: proxmox-backup-proxy.service: Succeeded.
Jul 13 13:20:37 pve31 systemd[1]: Stopped Proxmox Backup API Proxy Server.
Jul 13 13:20:37 pve31 systemd[1]: Starting Proxmox Backup API Proxy Server...
Jul 13 13:20:37 pve31 systemd[1]: Started Proxmox Backup API Proxy Server.

journalctl -b0 -u proxmox-backup.service

Jul 13 12:49:41 pve31 systemd[1]: Reloading Proxmox Backup API Server.
Jul 13 12:49:41 pve31 systemd[1]: Reloaded Proxmox Backup API Server.
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: got reload request (SIGHUP)
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: SET SHUTDOWN MODE
Jul 13 12:49:41 pve31 proxmox-backup-api[1765]: daemon reload...
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: daemon shut down...
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: server shutting down, waiting for active workers to complete
Jul 13 12:49:43 pve31 proxmox-backup-api[1765]: done - exit server