PBS backups failing and bringing down the PBS UI

I

inxsible

Active Member
Feb 6, 2020
139
8
38
My PBS is a LXC container and I had all of this working prior to a shutdown that I did. After rebooting my proxmox server, the backups have not worked. Yesterday I upgraded Proxmox frm 7.4.3 to 8 and also PBS from 2.4 to 3.0 but I still have all my backups failing as below.

Code: 
INFO: starting new backup job: vzdump 113 --notes-template '{{guestname}}' --remove 0 --mode snapshot --storage pbs2 --node proxmox
INFO: Starting Backup of VM 113 (lxc)
INFO: Backup started at 2023-07-13 15:25:57
INFO: status = running
INFO: CT Name: homer
INFO: including mount point rootfs ('/') in backup
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: create storage snapshot 'vzdump'
INFO: creating Proxmox Backup Server archive 'ct/113/2023-07-13T20:25:57Z'
INFO: run: lxc-usernsexec -m u:0:100000:65536 -m g:0:100000:65536 -- /usr/bin/proxmox-backup-client backup --crypt-mode=none pct.conf:/var/tmp/vzdumptmp2755452_113/etc/vzdump/pct.conf root.pxar:/mnt/vzsnap0 --include-dev /mnt/vzsnap0/./ --skip-lost-and-found --exclude=/tmp/?* --exclude=/var/tmp/?* --exclude=/var/run/?*.pid --backup-type ct --backup-id 113 --backup-time 1689279957 --repository root@pam@192.168.1.33:pbsDatastore
INFO: Starting backup: ct/113/2023-07-13T20:25:57Z
INFO: Client name: proxmox
INFO: Starting backup protocol: Thu Jul 13 15:25:58 2023
INFO: Downloading previous manifest (Sun Jun 25 05:23:56 2023)
INFO: Upload config file '/var/tmp/vzdumptmp2755452_113/etc/vzdump/pct.conf' to 'root@pam@192.168.1.33:8007:pbsDatastore' as pct.conf.blob
INFO: Upload directory '/mnt/vzsnap0' to 'root@pam@192.168.1.33:8007:pbsDatastore' as root.pxar.didx

These include the Backup Jobs in Proxmox as well as manual backups. Once I start the backup, the PBS UI also is incassesible until I stop the backup and then restart the proxmox-backup-proxy service.

What would be the issue here?
 
Last few lines from the PBS container:
Code: 
Jul 13 19:17:03 pbs zed[10454]: Failed to initialize libzfs
Jul 13 19:17:03 pbs systemd[1]: zfs-zed.service: Main process exited, code=exited, status=1/FAILURE
Jul 13 19:17:03 pbs systemd[1]: zfs-zed.service: Failed with result 'exit-code'.
Jul 13 19:17:03 pbs systemd[1]: zfs-zed.service: Scheduled restart job, restart counter is at 8333.
Jul 13 19:17:03 pbs systemd[1]: Stopped zfs-zed.service - ZFS Event Daemon (zed).
Jul 13 19:17:03 pbs systemd[1]: Started zfs-zed.service - ZFS Event Daemon (zed).
Jul 13 19:17:03 pbs zed[10460]: ZFS Event Daemon 2.1.12-pve1 (PID 10460)

Just this over and over...

Which service logs should I pull from the pve journal?

Here's how the storage is defined in PVE:
1689294216953.png
 
Last edited:
any inputs ?

I have disabled all the backups currently as PBS UI goes down whenever a backup starts and hangs...
 
can you post more logs from pve and pbs? (the above logs are not really enough to say anything)
also since the pbs is a container, i'd probably disable/stop the zfs related services inside the pbs to prevent log spamming (but that seems unrelated)

also is it possible that the storages are simply overwhelmed when the backup starts ?
 
hi @dcsapak ,

I started a backup from my desktop :
Code: 
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: starting new backup on datastore 'pbsDatastore': "host/prodesk/2023->
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: protocol upgrade done
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: GET /previous_backup_time
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: GET /previous
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: download 'index.json.blob' from previous backup.
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: POST /dynamic_index
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: GET /previous
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: register chunks in 'root.pxar.didx' from previous backup.
Jul 17 10:01:00 pbs proxmox-backup-proxy[45822]: download 'root.pxar.didx' from previous backup.

The logPBS UI immediately went down the second I started the backup.

Upon restarting proxmox-backup-proxy, I got the UI back and in the UI I see:
1689606434889.png

So it seems the connection happens during the backup but then the backup never finishes. As you can see, there's one backup that's "stuck" since the last 4 days as well along with the one I started today.
 
Last edited:
From PVE : the last 150 lines of the logs are:
Code: 
Jul 17 09:58:30 proxmox cgroup-network[3551336]: child pid 3551337 exited with code 1.
Jul 17 09:58:30 proxmox cgroup-network[3551360]: Cannot open pid_from_cgroup() file '/sys/fs/cgroup/lxc/111/tasks'.
Jul 17 09:58:30 proxmox cgroup-network[3551360]: Cannot open pid_from_cgroup() file '/sys/fs/cgroup/lxc/111/ns/tasks'.
Jul 17 09:58:30 proxmox cgroup-network[3551360]: Cannot open pid_from_cgroup() file '/sys/fs/cgroup/lxc/111/ns/dev-mqueue.mount/tasks'.
Jul 17 09:58:30 proxmox cgroup-network[3551360]: Cannot open pid_from_cgroup() file '/sys/fs/cgroup/lxc/111/ns/user.slice/tasks'.
Jul 17 09:58:30 proxmox cgroup-network[3551360]: running: exec /usr/libexec/netdata/plugins.d/cgroup-network-helper.sh --cgroup '/sys/fs/cgroup/lxc/111'
Jul 17 09:58:30 proxmox cgroup-network[3551360]: child pid 3551361 exited with code 1.
Jul 17 09:59:45 proxmox smartd[2339]: Device: /dev/sdh [SAT], SMART Usage Attribute: 190 Airflow_Temperature_Cel changed from 60 to 59
Jul 17 09:59:45 proxmox smartd[2339]: Device: /dev/sdh [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 40 to 41
Jul 17 10:01:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:01:09 proxmox pvestatd[3756]: status update time (7.327 seconds)
Jul 17 10:01:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:01:19 proxmox pvestatd[3756]: status update time (7.348 seconds)
Jul 17 10:01:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
........
Jul 17 10:03:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:03:19 proxmox pvestatd[3756]: status update time (7.336 seconds)
Jul 17 10:03:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:03:30 proxmox pvestatd[3756]: status update time (7.342 seconds)
Jul 17 10:03:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:03:39 proxmox pvestatd[3756]: status update time (7.346 seconds)
Jul 17 10:03:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:03:49 proxmox pvestatd[3756]: status update time (7.345 seconds)
Jul 17 10:04:00 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:00 proxmox pvestatd[3756]: status update time (7.331 seconds)
Jul 17 10:04:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:09 proxmox pvestatd[3756]: status update time (7.326 seconds)
Jul 17 10:04:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:19 proxmox pvestatd[3756]: status update time (7.341 seconds)
Jul 17 10:04:28 proxmox postfix/qmgr[3160]: 8EFAC1407F: from=<root@proxmox.lan.mydomain.com>, size=45114, nrcpt=1 (queue active)
Jul 17 10:04:28 proxmox postfix/qmgr[3160]: 596911407B: from=<root@proxmox.lan.mydomain.com>, size=44948, nrcpt=1 (queue active)
Jul 17 10:04:28 proxmox postfix/qmgr[3160]: 760EE1168B: from=<root@proxmox.lan.mydomain.com>, size=15287, nrcpt=1 (queue active)
Jul 17 10:04:28 proxmox postfix/qmgr[3160]: EBD4013689: from=<root@proxmox.lan.mydomain.com>, size=15239, nrcpt=1 (queue active)
Jul 17 10:04:28 proxmox postfix/qmgr[3160]: 3488F16BE2: from=<root@proxmox.lan.mydomain.com>, size=45114, nrcpt=1 (queue active)
Jul 17 10:04:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:30 proxmox pvestatd[3756]: status update time (7.343 seconds)
Jul 17 10:04:38 proxmox postfix/smtp[3561418]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1a]:25: Network is unreachable
Jul 17 10:04:38 proxmox postfix/smtp[3561415]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1a]:25: Network is unreachable
Jul 17 10:04:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:39 proxmox pvestatd[3756]: status update time (7.344 seconds)
Jul 17 10:04:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:49 proxmox pvestatd[3756]: status update time (7.318 seconds)
Jul 17 10:05:00 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:00 proxmox pvestatd[3756]: status update time (7.339 seconds)
Jul 17 10:05:08 proxmox postfix/smtp[3561417]: connect to gmail-smtp-in.l.google.com[142.250.159.27]:25: Connection timed out
Jul 17 10:05:08 proxmox postfix/smtp[3561417]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1a]:25: Network is unreachable
Jul 17 10:05:08 proxmox postfix/smtp[3561417]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:400c:c08::1b]:25: Network is unreachable
Jul 17 10:05:08 proxmox postfix/smtp[3561416]: connect to gmail-smtp-in.l.google.com[142.250.159.26]:25: Connection timed out
Jul 17 10:05:08 proxmox postfix/smtp[3561419]: connect to gmail-smtp-in.l.google.com[142.250.159.27]:25: Connection timed out
Jul 17 10:05:08 proxmox postfix/smtp[3561418]: connect to gmail-smtp-in.l.google.com[142.250.159.26]:25: Connection timed out
Jul 17 10:05:08 proxmox postfix/smtp[3561415]: connect to gmail-smtp-in.l.google.com[142.250.159.27]:25: Connection timed out
Jul 17 10:05:08 proxmox postfix/smtp[3561419]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1a]:25: Network is unreachable
Jul 17 10:05:08 proxmox postfix/smtp[3561418]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:4023:400::1a]:25: Network is unreachable
Jul 17 10:05:08 proxmox postfix/smtp[3561416]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1a]:25: Network is unreachable
Jul 17 10:05:08 proxmox postfix/smtp[3561415]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:400c:c08::1b]:25: Network is unreachable
Jul 17 10:05:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:09 proxmox pvestatd[3756]: status update time (7.321 seconds)
Jul 17 10:05:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:19 proxmox pvestatd[3756]: status update time (7.337 seconds)
Jul 17 10:05:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:30 proxmox pvestatd[3756]: status update time (7.346 seconds)
Jul 17 10:05:38 proxmox postfix/smtp[3561417]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:05:38 proxmox postfix/smtp[3561418]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:05:38 proxmox postfix/smtp[3561419]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:05:38 proxmox postfix/smtp[3561419]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:4023:400::1a]:25: Network is unreachable
Jul 17 10:05:38 proxmox postfix/smtp[3561418]: connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4002:c03::1a]:25: Network is unreachable
Jul 17 10:05:38 proxmox postfix/smtp[3561416]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:05:38 proxmox postfix/smtp[3561416]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:400c:c08::1b]:25: Network is unreachable
Jul 17 10:05:38 proxmox postfix/smtp[3561415]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:05:38 proxmox postfix/smtp[3561415]: connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4002:c03::1a]:25: Network is unreachable
Jul 17 10:05:38 proxmox postfix/smtp[3561418]: EBD4013689: to=<myemail@gmail.com>, relay=none, delay=321270, delays=321199/0.03/70/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4002:c03::1a]:>
Jul 17 10:05:38 proxmox postfix/smtp[3561415]: 8EFAC1407F: to=<myemail@gmail.com>, relay=none, delay=273527, delays=273457/0.01/70/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4002:c03::1a]:>
Jul 17 10:05:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:39 proxmox pvestatd[3756]: status update time (7.350 seconds)
Jul 17 10:06:08 proxmox postfix/smtp[3561417]: connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Connection timed out
Jul 17 10:06:08 proxmox postfix/smtp[3561419]: connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Connection timed out
Jul 17 10:06:08 proxmox postfix/smtp[3561416]: connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Connection timed out
Jul 17 10:06:08 proxmox postfix/smtp[3561417]: 760EE1168B: to=<myemail@gmail.com>, relay=none, delay=350730, delays=350630/0.02/100/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Con>
Jul 17 10:06:08 proxmox postfix/smtp[3561419]: 3488F16BE2: to=<myemail@gmail.com>, relay=none, delay=14359, delays=14259/0.03/100/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Conne>
Jul 17 10:06:08 proxmox postfix/smtp[3561416]: 596911407B: to=<myemail@gmail.com>, relay=none, delay=273847, delays=273747/0.01/100/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Con>
Jul 17 10:09:28 proxmox postfix/qmgr[3160]: 1040916BDF: from=<root@proxmox.lan.mydomain.com>, size=44854, nrcpt=1 (queue active)
Jul 17 10:09:28 proxmox postfix/qmgr[3160]: 2408416C7B: from=<root@proxmox.lan.mydomain.com>, size=41407, nrcpt=1 (queue active)
Jul 17 10:09:28 proxmox postfix/qmgr[3160]: 2A69C15BE3: from=<root@proxmox.lan.mydomain.com>, size=15535, nrcpt=1 (queue active)
Jul 17 10:09:28 proxmox postfix/qmgr[3160]: 7CE1C14FDC: from=<root@proxmox.lan.mydomain.com>, size=15489, nrcpt=1 (queue active)
Jul 17 10:09:28 proxmox postfix/error[3569634]: 1040916BDF: to=<myemail@gmail.com>, relay=none, delay=14690, delays=14690/0.01/0/0.03, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to alt2.gmail-smtp-in.l.go>
Jul 17 10:09:28 proxmox postfix/error[3569635]: 2408416C7B: to=<myemail@gmail.com>, relay=none, delay=10431, delays=10431/0.01/0/0.02, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to alt2.gmail-smtp-in.l.go>
Jul 17 10:09:28 proxmox postfix/error[3569637]: 2A69C15BE3: to=<myemail@gmail.com>, relay=none, delay=121800, delays=121800/0.02/0/0.03, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to alt2.gmail-smtp-in.l.>
Jul 17 10:09:28 proxmox postfix/error[3569639]: 7CE1C14FDC: to=<myemail@gmail.com>, relay=none, delay=208100, delays=208100/0.02/0/0.02, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to alt2.gmail-smtp-in.l.>
Jul 17 10:14:28 proxmox postfix/qmgr[3160]: 1DFFD160A6: from=<root@proxmox.lan.mydomain.com>, size=45104, nrcpt=1 (queue active)
Jul 17 10:14:28 proxmox postfix/qmgr[3160]: CE59B160A0: from=<root@proxmox.lan.mydomain.com>, size=44950, nrcpt=1 (queue active)
Jul 17 10:14:28 proxmox postfix/qmgr[3160]: 509333C200: from=<root@proxmox.lan.mydomain.com>, size=24491, nrcpt=1 (queue active)
Jul 17 10:14:33 proxmox postfix/smtp[3578028]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1b]:25: Network is unreachable
Jul 17 10:14:33 proxmox postfix/smtp[3578025]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1b]:25: Network is unreachable
Jul 17 10:15:03 proxmox postfix/smtp[3578025]: connect to gmail-smtp-in.l.google.com[142.251.4.26]:25: Connection timed out
Jul 17 10:15:03 proxmox postfix/smtp[3578028]: connect to gmail-smtp-in.l.google.com[142.251.4.26]:25: Connection timed out
Jul 17 10:15:03 proxmox postfix/smtp[3578025]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:4023:400::1a]:25: Network is unreachable
Jul 17 10:15:03 proxmox postfix/smtp[3578027]: connect to gmail-smtp-in.l.google.com[142.251.4.26]:25: Connection timed out
Jul 17 10:15:03 proxmox postfix/smtp[3578027]: connect to gmail-smtp-in.l.google.com[2607:f8b0:4001:c58::1b]:25: Network is unreachable
Jul 17 10:15:33 proxmox postfix/smtp[3578025]: connect to alt1.gmail-smtp-in.l.google.com[108.177.12.27]:25: Connection timed out
Jul 17 10:15:33 proxmox postfix/smtp[3578025]: connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4004:c07::1a]:25: Network is unreachable
Jul 17 10:15:33 proxmox postfix/smtp[3578028]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:15:33 proxmox postfix/smtp[3578028]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:4023:400::1a]:25: Network is unreachable
Jul 17 10:15:33 proxmox postfix/smtp[3578028]: connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4004:c07::1a]:25: Network is unreachable
Jul 17 10:15:33 proxmox postfix/smtp[3578027]: connect to alt1.gmail-smtp-in.l.google.com[172.253.126.26]:25: Connection timed out
Jul 17 10:15:33 proxmox postfix/smtp[3578027]: connect to alt1.gmail-smtp-in.l.google.com[2607:f8b0:4023:400::1a]:25: Network is unreachable
Jul 17 10:15:33 proxmox postfix/smtp[3578025]: 1DFFD160A6: to=<myemail@gmail.com>, relay=none, delay=101246, delays=101181/0.01/65/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4004:c07::1a]:>
Jul 17 10:15:33 proxmox postfix/smtp[3578028]: 509333C200: to=<myemail@gmail.com>, relay=none, delay=425889, delays=425824/0.02/65/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[2607:f8b0:4004:c07::1a]:>
Jul 17 10:16:03 proxmox postfix/smtp[3578027]: connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Connection timed out
Jul 17 10:16:03 proxmox postfix/smtp[3578027]: CE59B160A0: to=<myemail@gmail.com>, relay=none, delay=101644, delays=101548/0.01/95/0, dsn=4.4.1, status=deferred (connect to alt2.gmail-smtp-in.l.google.com[173.194.219.26]:25: Conn>
Jul 17 10:17:01 proxmox CRON[3582244]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jul 17 10:17:01 proxmox CRON[3582245]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jul 17 10:17:01 proxmox CRON[3582244]: pam_unix(cron:session): session closed for user root
Jul 17 10:17:53 proxmox pvedaemon[2199136]: <root@pam> successful auth for user 'admin@pve'
Jul 17 10:19:28 proxmox postfix/qmgr[3160]: B37E115F51: from=<root@proxmox.lan.mydomain.com>, size=44846, nrcpt=1 (queue active)
Jul 17 10:19:28 proxmox postfix/error[3586307]: B37E115F51: to=<myemail@gmail.com>, relay=none, delay=101870, delays=101870/0.01/0/0.04, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to alt2.gmail-smtp-in.l.>
lines 95-150/150 (END)
 
can it be that your network is overloaded?

the many 'connection timed out' messages would indicate that there is either an error in your network or it is simply overloaded
 
hi @dcsapak ,
Thanks for responding.

The gmail (Network is unreachable) errors seem to be related to this : https://forum.proxmox.com/threads/gmail-unreachable-connection-timed-out.112676/

I, too, don't have any issues with accessing the internet and even accessing the proxmox server or any other services running on it in general. So I don't think the backups failing are due to the network overload.

Any other ideas please?

PS: I'll probably want to tackle the gmail error too as it seems to be polluting my logs quite a bit, but I'll look into it after my backups start working.
 
Last edited:
I started another backup and sure enough the pbs UI became non-responsive.

Logs from pbs container:
Code: 
[pbs: ~]── - sudo journalctl -b -u proxmox-backup-proxy
Jul 18 14:38:49 pbs systemd[1]: Starting proxmox-backup-proxy.service - Proxmox Backup API Proxy Server...
Jul 18 14:38:49 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: service is ready
Jul 18 14:38:49 pbs systemd[1]: Started proxmox-backup-proxy.service - Proxmox Backup API Proxy Server.
Jul 18 14:38:49 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: applied rrd journal (322 entries in 0.077 seconds)
Jul 18 14:38:49 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 18 14:38:49 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 18 14:38:49 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.085 seconds)
Jul 18 15:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 18 15:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 18 15:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.147 seconds)
Jul 18 15:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 18 15:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 18 15:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.102 seconds)
Jul 18 16:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 18 16:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 18 16:08:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.100 seconds)
Jul 18 16:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 18 16:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 18 16:38:50 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.102 seconds)
Jul 18 16:58:13 pbs proxmox-backup-proxy[172]: error during snapshot file listing: 'unable to load blob '"/mnt/freenas/pbsDatastore/host/prodesk/2023-07-17T15:00:59Z/index.json.blob"' - No such file or directory (os error 2)'
Jul 18 16:58:22 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: removing backup snapshot "/mnt/freenas/pbsDatastore/host/prodesk/2023-07-17T15:00:59Z"
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: starting new backup on datastore 'pbsDatastore': "host/prodesk/2023-07-18T21:58:37Z"
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: protocol upgrade done
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: GET /previous_backup_time
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: GET /previous
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: download 'index.json.blob' from previous backup.
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: GET /previous
Jul 18 16:58:37 pbs proxmox-backup-proxy[172]: POST /dynamic_index
[pbs: ~]── -

The "unable to load blob" error is because I tried a backup yesterday which got stuck and I had to restart proxmox-backup-proxy ... so when refreshing the UI, it obviously couldn't find the "unfinished" backup.

But as you can see from the logs, the backup gets started and it seem to connect to the PBS instance too, but then gets stuck and never finishes.
 
Here's the PVE logs from the last 2 days:
Code: 
journalctl -b -u pvestatd --since "2 days ago"
Code: 
Jul 16 18:29:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:29:19 proxmox pvestatd[3756]: status update time (7.334 seconds)
Jul 16 18:29:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:29:30 proxmox pvestatd[3756]: status update time (7.331 seconds)
Jul 16 18:29:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:29:39 proxmox pvestatd[3756]: status update time (7.326 seconds)
Jul 16 18:29:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:29:49 proxmox pvestatd[3756]: status update time (7.331 seconds)
Jul 16 18:29:59 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:00 proxmox pvestatd[3756]: status update time (7.336 seconds)
Jul 16 18:30:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:09 proxmox pvestatd[3756]: status update time (7.344 seconds)
Jul 16 18:30:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:19 proxmox pvestatd[3756]: status update time (7.336 seconds)
Jul 16 18:30:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:30 proxmox pvestatd[3756]: status update time (7.314 seconds)
Jul 16 18:30:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:39 proxmox pvestatd[3756]: status update time (7.339 seconds)
Jul 16 18:30:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:30:49 proxmox pvestatd[3756]: status update time (7.334 seconds)
Jul 16 18:31:00 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:31:00 proxmox pvestatd[3756]: status update time (7.312 seconds)
Jul 16 18:31:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:31:09 proxmox pvestatd[3756]: status update time (7.329 seconds)
Jul 16 18:31:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)
Jul 16 18:31:19 proxmox pvestatd[3756]: status update time (7.340 seconds)
Jul 16 18:31:29 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 19.168.1.33:8007 (Connection timed out)

...............
...............

Jul 17 10:03:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:03:49 proxmox pvestatd[3756]: status update time (7.345 seconds)
Jul 17 10:04:00 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:00 proxmox pvestatd[3756]: status update time (7.331 seconds)
Jul 17 10:04:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:09 proxmox pvestatd[3756]: status update time (7.326 seconds)
Jul 17 10:04:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:19 proxmox pvestatd[3756]: status update time (7.341 seconds)
Jul 17 10:04:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:30 proxmox pvestatd[3756]: status update time (7.343 seconds)
Jul 17 10:04:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:39 proxmox pvestatd[3756]: status update time (7.344 seconds)
Jul 17 10:04:49 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:04:49 proxmox pvestatd[3756]: status update time (7.318 seconds)
Jul 17 10:05:00 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:00 proxmox pvestatd[3756]: status update time (7.339 seconds)
Jul 17 10:05:09 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:09 proxmox pvestatd[3756]: status update time (7.321 seconds)
Jul 17 10:05:19 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:19 proxmox pvestatd[3756]: status update time (7.337 seconds)
Jul 17 10:05:30 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:30 proxmox pvestatd[3756]: status update time (7.346 seconds)
Jul 17 10:05:39 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 17 10:05:39 proxmox pvestatd[3756]: status update time (7.350 seconds)
Jul 17 20:06:13 proxmox pvestatd[3756]: auth key pair too old, rotating..
Jul 17 22:34:38 proxmox pvestatd[3756]: status update time (5.456 seconds)
Jul 18 02:14:39 proxmox pvestatd[3756]: status update time (5.421 seconds)
Jul 18 02:24:39 proxmox pvestatd[3756]: status update time (5.423 seconds)
Jul 18 02:34:39 proxmox pvestatd[3756]: status update time (5.433 seconds)
Jul 18 03:04:38 proxmox pvestatd[3756]: status update time (5.434 seconds)
Jul 18 03:14:38 proxmox pvestatd[3756]: status update time (5.453 seconds)
Jul 18 03:34:38 proxmox pvestatd[3756]: status update time (5.452 seconds)
Jul 18 04:14:39 proxmox pvestatd[3756]: status update time (5.430 seconds)
Jul 18 04:24:39 proxmox pvestatd[3756]: status update time (5.438 seconds)
Jul 18 04:44:38 proxmox pvestatd[3756]: status update time (5.436 seconds)
Jul 18 04:54:38 proxmox pvestatd[3756]: status update time (5.458 seconds)
Jul 18 05:24:38 proxmox pvestatd[3756]: status update time (5.424 seconds)
Jul 18 05:34:38 proxmox pvestatd[3756]: status update time (5.434 seconds)
Jul 18 05:54:38 proxmox pvestatd[3756]: status update time (5.438 seconds)
Jul 18 06:04:38 proxmox pvestatd[3756]: status update time (5.514 seconds)

...........
...........

Jul 18 18:26:42 proxmox pvestatd[3756]: status update time (7.322 seconds)
Jul 18 18:26:53 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:26:53 proxmox pvestatd[3756]: status update time (7.319 seconds)
Jul 18 18:27:02 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:02 proxmox pvestatd[3756]: status update time (7.316 seconds)
Jul 18 18:27:12 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:12 proxmox pvestatd[3756]: status update time (7.333 seconds)
Jul 18 18:27:23 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:23 proxmox pvestatd[3756]: status update time (7.337 seconds)
Jul 18 18:27:32 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:32 proxmox pvestatd[3756]: status update time (7.446 seconds)
Jul 18 18:27:42 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:43 proxmox pvestatd[3756]: status update time (7.315 seconds)
Jul 18 18:27:52 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:27:52 proxmox pvestatd[3756]: status update time (7.333 seconds)
Jul 18 18:28:02 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:02 proxmox pvestatd[3756]: status update time (7.342 seconds)
Jul 18 18:28:12 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:13 proxmox pvestatd[3756]: status update time (7.342 seconds)
Jul 18 18:28:22 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:22 proxmox pvestatd[3756]: status update time (7.330 seconds)
Jul 18 18:28:32 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:32 proxmox pvestatd[3756]: status update time (7.336 seconds)
Jul 18 18:28:42 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:43 proxmox pvestatd[3756]: status update time (7.335 seconds)
Jul 18 18:28:52 proxmox pvestatd[3756]: pbs: error fetching datastores - 500 Can't connect to 192.168.1.33:8007
Jul 18 18:28:52 proxmox pvestatd[3756]: status update time (7.333 seconds)

Seems like PVE cannot connect to the datastores. Not sure what the difference is between the Can't connect vs Can't connect (Connection timed out). Is there something I can do to fix this?
 
Last edited:
i'd try to connect via ssh/pct console to the pbs and then check with htop/top/ps during a backup what might be going on
 
I have a garbage collection running for the past 16 hours but it doesn't seem to be doing anything: 1689803424024.png

Most of my other garbage collections have completed within 30 mins.
1689803494721.png

Once this garbage collection finishes, I can test out a backup and see if it indicates anything.
 
can you check with htop/ps/top/etc to see what the server is doing? espeically the proxmox-backup-proxy processes
 
dcsapak said:
can you check with htop/ps/top/etc to see what the server is doing? espeically the proxmox-backup-proxy processes
Click to expand...
Thanks for sticking with me on this...

The GC ran for 24 hours and then I tried to stop it but even that didn't do anything except an extra line in the task log indicating that it received a stop request. So I rebooted the PBS container but upon reboot another GC started immediately and has been running for the past 8 hours even though I requested a stop.
1689860564221.png

Here's the top output. The load seems high but is the same as that on the PVE server since PBS is just a LXC container.

Code: 
top - 08:38:41 up  8:22,  1 user,  load average: 5.50, 4.95, 4.67
Tasks:  23 total,   1 running,  22 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.3 us,  1.0 sy,  0.3 ni, 98.0 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
MiB Mem :    512.0 total,    434.8 free,     37.1 used,     40.1 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.    474.9 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
      1 root      20   0  102064   9984   7168 S   0.0   1.9   0:00.22 systemd
     50 root      20   0   56996  24664  23640 S   0.0   4.7   0:00.16 systemd-journal
     81 root      20   0    3600   1536   1408 S   0.0   0.3   0:00.04 cron
     82 message+  20   0    9128   3584   3072 S   0.0   0.7   0:00.01 dbus-daemon
     84 root      20   0  152140   3456   2816 S   0.0   0.7   0:00.01 rsyslogd
     85 root      20   0   16984   6528   5504 S   0.0   1.2   0:00.04 systemd-logind
    120 root      20   0    5868   2560   1792 S   0.0   0.5   0:00.00 dhclient
    161 root      20   0  177328  15908  12452 S   0.0   3.0   1:18.01 proxmox-backup-
    168 root      20   0    2516   1152   1152 S   0.0   0.2   0:00.00 agetty
    169 root      20   0    2516   1024   1024 S   0.0   0.2   0:00.00 agetty
    170 root      20   0    2516   1152   1152 S   0.0   0.2   0:00.00 agetty
    173 backup    20   0  595412  24020  16256 S   0.0   4.6   1:01.99 proxmox-backup-
    174 root      20   0   15404   7168   5888 S   0.0   1.4   0:00.01 sshd
    323 root      20   0   42656   2068   1536 S   0.0   0.4   0:00.06 master
    326 postfix   20   0   43088   4352   3712 S   0.0   0.8   0:00.01 qmgr
   1273 pbsuser   20   0   18896   8576   7040 S   0.0   1.6   0:00.01 systemd
   1274 pbsuser   20   0  103124   4516   1536 S   0.0   0.9   0:00.00 (sd-pam)
   1291 pbsuser   20   0    7660   1484    768 S   0.0   0.3   0:00.00 ssh-agent
   1302 postfix   20   0   43040   4352   3712 S   0.0   0.8   0:00.00 pickup
   1303 root      20   0   17784   8448   6912 S   0.0   1.6   0:00.01 sshd
   1309 pbsuser   20   0   17944   5444   3584 S   0.0   1.0   0:00.00 sshd


At this point I haven't really found out why it stopped working.I had shutdown the PVE and the NAS on June 25th and then rebooted on July 6 as I was out of town.
1689860734180.png

Since the reboot the backups have stopped working. Initially I had not noticed it and I also updated PVE from 7.3 to 8 and also PBS from 2.4 to 3, but that hasn't changed anything.
 
Just went ahead and started a backup even though the GC task hadn't stopped yet inspite of giving it the abort request 9 hours ago.
Code: 
sudo journalctl -b -u proxmox-backup-proxy

Jul 20 00:15:56 pbs systemd[1]: Starting proxmox-backup-proxy.service - Proxmox Backup API Proxy Server...
Jul 20 00:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: service is ready
Jul 20 00:15:57 pbs systemd[1]: Started proxmox-backup-proxy.service - Proxmox Backup API Proxy Server.
Jul 20 00:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: applied rrd journal (262 entries in 0.070 seconds)
Jul 20 00:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 00:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 00:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.107 seconds)
Jul 20 00:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 00:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 00:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.124 seconds)
Jul 20 01:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 01:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 01:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.123 seconds)
Jul 20 01:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 01:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 01:45:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.113 seconds)
Jul 20 02:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 02:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 02:15:57 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.107 seconds)
Jul 20 02:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 02:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 02:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.115 seconds)
Jul 20 03:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 03:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 03:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.124 seconds)
Jul 20 03:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 03:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 03:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.101 seconds)
Jul 20 04:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 04:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 04:15:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.097 seconds)
Jul 20 04:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 04:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 04:45:58 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.099 seconds)
Jul 20 05:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 05:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 05:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.092 seconds)
Jul 20 05:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 05:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 05:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.097 seconds)
Jul 20 06:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 06:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 06:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.114 seconds)
Jul 20 06:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 06:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 06:45:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.082 seconds)
Jul 20 07:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 07:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 07:15:59 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.089 seconds)
Jul 20 07:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 07:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 07:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.079 seconds)
Jul 20 08:16:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 08:16:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 08:16:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.102 seconds)
Jul 20 08:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 08:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 08:46:00 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.094 seconds)
Jul 20 09:16:01 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: write rrd data back to disk
Jul 20 09:16:01 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: starting rrd data sync
Jul 20 09:16:01 pbs proxmox-backup-[173]: pbs proxmox-backup-proxy[173]: rrd journal successfully committed (20 files in 0.083 seconds)
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: starting new backup on datastore 'pbsDatastore': "host/prodesk/2023-07-20T14:42:48Z"
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: protocol upgrade done
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: GET /previous_backup_time
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: GET /previous
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: download 'index.json.blob' from previous backup.
Jul 20 09:42:48 pbs proxmox-backup-proxy[173]: POST /dynamic_index

That's where it is stuck. The PBS UI instantly becomes unavailable until I restart proxmox-backup-proxy
 
Last edited:
can you post a portion of the unfiltered journal (so that we can see everything that is going on in the pbs?), also can you post the output of 'ps ax | grep proxmox' ?
 
Hi @dcsapak

Code: 
[pbs: ~]── - ps ax | grep proxmox
    160 ?        Ssl    0:02 /usr/lib/x86_64-linux-gnu/proxmox-backup/proxmox-backup-api
    172 ?        Ssl    0:03 /usr/lib/x86_64-linux-gnu/proxmox-backup/proxmox-backup-proxy
    399 pts/3    R+     0:00 grep --color=auto proxmox
[pbs: ~]── -

Logs after booting up the PBS container.
Code: 
Jul 31 12:53:50 pbs systemd-journald[50]: Journal started
Jul 31 12:53:50 pbs systemd-journald[50]: Runtime Journal (/run/log/journal/ead4cafc737b4bf6837b2c86c54294e3) is 8.0M, max 640.9M, 632.9M free.
Jul 31 12:53:50 pbs systemd-modules-load[51]: Failed to find module 'zfs'
Jul 31 12:53:50 pbs mount[42]: mount: /sys/kernel/debug: permission denied.
Jul 31 12:53:50 pbs mount[42]:        dmesg(1) may have more information after failed mount system call.
Jul 31 12:53:50 pbs mount[54]: mount: /sys/kernel/config: permission denied.
Jul 31 12:53:50 pbs mount[54]:        dmesg(1) may have more information after failed mount system call.
Jul 31 12:53:50 pbs systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage...
Jul 31 12:53:50 pbs systemd[1]: Finished lvm2-monitor.service - Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables.
Jul 31 12:53:50 pbs systemd-journald[50]: Time spent on flushing to /var/log/journal/ead4cafc737b4bf6837b2c86c54294e3 is 1.767ms for 10 entries.
Jul 31 12:53:50 pbs systemd-journald[50]: System Journal (/var/log/journal/ead4cafc737b4bf6837b2c86c54294e3) is 406.0M, max 409.6M, 3.5M free.
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-sysusers.service - Create System Users.
Jul 31 12:53:50 pbs systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev...
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev.
Jul 31 12:53:50 pbs systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems.
Jul 31 12:53:50 pbs systemd[1]: systemd-udevd.service - Rule-based Manager for Device Events and Files was skipped because of an unmet condition check (ConditionPathIsReadWrite=/sys).
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage.
Jul 31 12:54:00 pbs zfs[57]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:00 pbs zfs[57]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:00 pbs systemd[1]: zfs-mount.service: Main process exited, code=exited, status=1/FAILURE
Jul 31 12:54:00 pbs systemd[1]: zfs-mount.service: Failed with result 'exit-code'.
Jul 31 12:54:00 pbs systemd[1]: Failed to start zfs-mount.service - Mount ZFS filesystems.
Jul 31 12:54:00 pbs systemd[1]: Reached target local-fs.target - Local File Systems.
Jul 31 12:54:00 pbs systemd[1]: Starting networking.service - Network initialization...
Jul 31 12:54:00 pbs systemd[1]: Starting proxmox-backup-banner.service - Proxmox Backup Server Login Banner...
Jul 31 12:54:00 pbs systemd[1]: systemd-binfmt.service - Set Up Additional Binary Formats was skipped because of an unmet condition check (ConditionPathIsReadWrite=/proc/sys).
Jul 31 12:54:00 pbs systemd[1]: systemd-machine-id-commit.service - Commit a transient machine-id on disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id).
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-tmpfiles-setup.service - Create Volatile Files and Directories...
Jul 31 12:54:00 pbs systemd[1]: Finished proxmox-backup-banner.service - Proxmox Backup Server Login Banner.
Jul 31 12:54:00 pbs zvol_wait[63]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:00 pbs zvol_wait[63]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:00 pbs zvol_wait[58]: No zvols found, nothing to do.
Jul 31 12:54:00 pbs systemd[1]: Finished zfs-volume-wait.service - Wait for ZFS Volume (zvol) links in /dev.
Jul 31 12:54:00 pbs systemd[1]: Reached target zfs-volumes.target - ZFS volumes are ready.
Jul 31 12:54:00 pbs systemd[1]: Finished systemd-tmpfiles-setup.service - Create Volatile Files and Directories.
Jul 31 12:54:00 pbs systemd[1]: systemd-timesyncd.service - Network Time Synchronization was skipped because of an unmet condition check (ConditionVirtualization=!container).
Jul 31 12:54:00 pbs systemd[1]: Reached target time-set.target - System Time Set.
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP...
Jul 31 12:54:00 pbs networking[68]: networking: Configuring network interfaces
Jul 31 12:54:00 pbs systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP.
Jul 31 12:54:00 pbs systemd[1]: Reached target sysinit.target - System Initialization.
Jul 31 12:54:00 pbs systemd[1]: Started apt-daily.timer - Daily apt download activities.
Jul 31 12:54:00 pbs systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities.
Jul 31 12:54:00 pbs systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer.
Jul 31 12:54:00 pbs systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems.
Jul 31 12:54:00 pbs systemd[1]: Started logrotate.timer - Daily rotation of log files.
Jul 31 12:54:00 pbs systemd[1]: Started man-db.timer - Daily man-db regeneration.
Jul 31 12:54:00 pbs systemd[1]: Started proxmox-backup-daily-update.timer - Daily Proxmox Backup Server update and maintenance activities.
Jul 31 12:54:00 pbs systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories.
Jul 31 12:54:00 pbs systemd[1]: Reached target timers.target - Timer Units.
Jul 31 12:54:00 pbs systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket.
Jul 31 12:54:00 pbs systemd[1]: Reached target sockets.target - Socket Units.
Jul 31 12:54:00 pbs systemd[1]: systemd-pcrphase-sysinit.service - TPM2 PCR Barrier (Initialization) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f).
Jul 31 12:54:00 pbs systemd[1]: Reached target basic.target - Basic System.
Jul 31 12:54:00 pbs systemd[1]: Started cron.service - Regular background program processing daemon.
Jul 31 12:54:00 pbs systemd[1]: Starting dbus.service - D-Bus System Message Bus...
Jul 31 12:54:00 pbs cron[79]: (CRON) INFO (pidfile fd = 3)
Jul 31 12:54:00 pbs cron[79]: (CRON) INFO (Running @reboot jobs)
Jul 31 12:54:00 pbs systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots...
Jul 31 12:54:00 pbs systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon).
Jul 31 12:54:00 pbs systemd[1]: Starting rsyslog.service - System Logging Service...
Jul 31 12:54:00 pbs systemd[1]: smartmontools.service - Self Monitoring and Reporting Technology (SMART) Daemon was skipped because of an unmet condition check (ConditionVirtualization=no).
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-logind.service - User Login Management...
Jul 31 12:54:00 pbs systemd[1]: systemd-pcrphase.service - TPM2 PCR Barrier (User) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f).
Jul 31 12:54:00 pbs systemd[1]: Starting zfs-share.service - ZFS file system shares...
Jul 31 12:54:00 pbs systemd[1]: Started dbus.service - D-Bus System Message Bus.
Jul 31 12:54:00 pbs systemd[1]: Started rsyslog.service - System Logging Service.
Jul 31 12:54:00 pbs rsyslogd[88]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2302.0]
Jul 31 12:54:00 pbs rsyslogd[88]: imklog: cannot open kernel log (/proc/kmsg): Permission denied.
Jul 31 12:54:00 pbs rsyslogd[88]: activation of module imklog failed [v8.2302.0 try https://www.rsyslog.com/e/2145 ]
Jul 31 12:54:00 pbs rsyslogd[88]: [origin software="rsyslogd" swVersion="8.2302.0" x-pid="88" x-info="https://www.rsyslog.com"] start
Jul 31 12:54:00 pbs systemd-logind[89]: New seat seat0.
Jul 31 12:54:00 pbs systemd[1]: Started systemd-logind.service - User Login Management.
Jul 31 12:54:00 pbs systemd[1]: e2scrub_reap.service: Deactivated successfully.
Jul 31 12:54:00 pbs systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots.
Jul 31 12:54:00 pbs info[103]: eth0: enabling syslog for dhcp configuration
Jul 31 12:54:00 pbs info[103]: executing ip -o addr show eth0
Jul 31 12:54:01 pbs info[103]: executing /sbin/dhclient -pf /run/dhclient.eth0.pid -lf /var/lib/dhcp/dhclient.eth0.leases eth0
Jul 31 12:54:01 pbs dhclient[119]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4
Jul 31 12:54:01 pbs dhclient[119]: DHCPOFFER of 192.168.1.33 from 192.168.1.1
Jul 31 12:54:01 pbs dhclient[119]: DHCPREQUEST for 192.168.1.33 on eth0 to 255.255.255.255 port 67
Jul 31 12:54:01 pbs dhclient[119]: DHCPACK of 192.168.1.33 from 192.168.1.1
Jul 31 12:54:01 pbs dhclient[119]: bound to 192.168.1.33 -- renewal in 3077 seconds.
Jul 31 12:54:01 pbs info[103]: executing ip -o addr show eth0
Jul 31 12:54:01 pbs info[103]: eth0: dhclient: new address detected: 192.168.1.33/24
Jul 31 12:54:02 pbs systemd[1]: Finished networking.service - Network initialization.
Jul 31 12:54:02 pbs systemd[1]: Reached target network.target - Network.
Jul 31 12:54:02 pbs systemd[1]: Reached target network-online.target - Network is Online.
Jul 31 12:54:02 pbs systemd[1]: Starting postfix@-.service - Postfix Mail Transport Agent (instance -)...
Jul 31 12:54:02 pbs systemd[1]: Starting proxmox-backup.service - Proxmox Backup API Server...
Jul 31 12:54:02 pbs systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
Jul 31 12:54:02 pbs systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions...
Jul 31 12:54:02 pbs systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions.
Jul 31 12:54:02 pbs systemd[1]: Started console-getty.service - Console Getty.
Jul 31 12:54:02 pbs systemd[1]: Started container-getty@1.service - Container Getty on /dev/tty1.
Jul 31 12:54:02 pbs systemd[1]: Started container-getty@2.service - Container Getty on /dev/tty2.
Jul 31 12:54:02 pbs systemd[1]: Reached target getty.target - Login Prompts.
Jul 31 12:54:02 pbs proxmox-backup-[160]: pbs proxmox-backup-api[160]: service is ready
Jul 31 12:54:02 pbs systemd[1]: Started proxmox-backup.service - Proxmox Backup API Server.
Jul 31 12:54:02 pbs systemd[1]: Starting proxmox-backup-proxy.service - Proxmox Backup API Proxy Server...
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: service is ready
Jul 31 12:54:02 pbs systemd[1]: Started proxmox-backup-proxy.service - Proxmox Backup API Proxy Server.
Jul 31 12:54:02 pbs sshd[173]: Server listening on 0.0.0.0 port 22.
Jul 31 12:54:02 pbs sshd[173]: Server listening on :: port 22.
Jul 31 12:54:02 pbs systemd[1]: Started ssh.service - OpenBSD Secure Shell server.
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: applied rrd journal (1542 entries in 0.033 seconds)
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 31 12:54:02 pbs postfix[231]: Postfix is using backwards-compatible default settings
Jul 31 12:54:02 pbs postfix[231]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jul 31 12:54:02 pbs postfix[231]: To disable backwards compatibility use "postconf compatibility_level=3.6" and "postfix reload"
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.129 seconds)
Jul 31 12:54:02 pbs postfix/postfix-script[322]: starting the Postfix mail system
Jul 31 12:54:02 pbs postfix/master[324]: daemon started -- version 3.7.6, configuration /etc/postfix
Jul 31 12:54:02 pbs systemd[1]: Started postfix@-.service - Postfix Mail Transport Agent (instance -).
Jul 31 12:54:02 pbs systemd[1]: Starting postfix.service - Postfix Mail Transport Agent...
Jul 31 12:54:02 pbs systemd[1]: Finished postfix.service - Postfix Mail Transport Agent.
Jul 31 12:54:10 pbs zfs[90]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:10 pbs zfs[90]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:10 pbs systemd[1]: zfs-share.service: Main process exited, code=exited, status=1/FAILURE
Jul 31 12:54:10 pbs systemd[1]: zfs-share.service: Failed with result 'exit-code'.
Jul 31 12:54:10 pbs systemd[1]: Failed to start zfs-share.service - ZFS file system shares.
Jul 31 12:54:10 pbs systemd[1]: Reached target zfs.target - ZFS startup target.
Jul 31 12:54:10 pbs systemd[1]: Reached target multi-user.target - Multi-User System.
Jul 31 12:54:10 pbs systemd[1]: Reached target graphical.target - Graphical Interface.
Jul 31 12:54:10 pbs systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP...
Jul 31 12:54:10 pbs systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully.
Jul 31 12:54:10 pbs systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP.
Jul 31 12:54:10 pbs systemd[1]: Startup finished in 20.471s.
Jul 31 12:54:24 pbs sshd[329]: Accepted publickey for pbsuser from 192.168.1.51 port 40036 ssh2: ED25519 SHA256:XYqVYvEDaGTtH58w0iRM7UQ7U6XukS+hoNpQp4kBtek
Jul 31 12:54:24 pbs sshd[329]: pam_unix(sshd:session): session opened for user pbsuser(uid=1000) by (uid=0)
Jul 31 12:54:24 pbs systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
Jul 31 12:54:24 pbs systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...
Jul 31 12:54:24 pbs systemd-logind[89]: New session 3916 of user pbsuser.
Jul 31 12:54:24 pbs systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000.
Jul 31 12:54:24 pbs systemd[1]: Starting user@1000.service - User Manager for UID 1000...
Jul 31 12:54:24 pbs (systemd)[332]: pam_unix(systemd-user:session): session opened for user pbsuser(uid=1000) by (uid=0)
Jul 31 12:54:24 pbs systemd[332]: Queued start job for default target default.target.
Jul 31 12:54:24 pbs systemd[332]: Created slice app.slice - User Application Slice.
Jul 31 12:54:24 pbs sshd[329]: pam_env(sshd:session): deprecated reading of user environment enabled
Jul 31 12:54:24 pbs systemd[332]: Reached target paths.target - Paths.
Jul 31 12:54:24 pbs systemd[332]: Reached target timers.target - Timers.
Jul 31 12:54:24 pbs systemd[332]: Starting dbus.socket - D-Bus User Message Bus Socket...
Jul 31 12:54:24 pbs systemd[332]: Listening on dbus.socket - D-Bus User Message Bus Socket.
Jul 31 12:54:24 pbs systemd[332]: Reached target sockets.target - Sockets.
Jul 31 12:54:24 pbs systemd[332]: Reached target basic.target - Basic System.
Jul 31 12:54:24 pbs systemd[1]: Started user@1000.service - User Manager for UID 1000.
Jul 31 12:54:24 pbs systemd[1]: Started session-3916.scope - Session 3916 of User pbsuser.
Jul 31 12:54:24 pbs systemd[332]: Reached target default.target - Main User Target.
Jul 31 12:54:24 pbs systemd[332]: Startup finished in 39ms.
Jul 31 12:54:49 pbs sudo[372]:  pbsuser : TTY=pts/3 ; PWD=/home/pbsuser ; USER=root ; COMMAND=/usr/bin/journalctl -b
Jul 31 12:54:49 pbs sudo[372]: pam_limits(sudo:session): Could not set limit for 'core' to soft=0, hard=-1: Operation not permitted; uid=1000,euid=0
Jul 31 12:54:49 pbs sudo[372]: pam_unix(sudo:session): session opened for user root(uid=0) by pbsuser(uid=1000)
 
Log after starting a backup: (I had to remove the first 12 lines of the log as the forum won't allow me to post more than 16384 characters in a post but they were the same as in the previous post)
Code: 
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-sysusers.service - Create System Users.
Jul 31 12:53:50 pbs systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev...
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev.
Jul 31 12:53:50 pbs systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems.
Jul 31 12:53:50 pbs systemd[1]: systemd-udevd.service - Rule-based Manager for Device Events and Files was skipped because of an unmet condition check (ConditionPathIsReadWrite=/sys).
Jul 31 12:53:50 pbs systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage.
Jul 31 12:54:00 pbs zfs[57]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:00 pbs zfs[57]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:00 pbs systemd[1]: zfs-mount.service: Main process exited, code=exited, status=1/FAILURE
Jul 31 12:54:00 pbs systemd[1]: zfs-mount.service: Failed with result 'exit-code'.
Jul 31 12:54:00 pbs systemd[1]: Failed to start zfs-mount.service - Mount ZFS filesystems.
Jul 31 12:54:00 pbs systemd[1]: Reached target local-fs.target - Local File Systems.
Jul 31 12:54:00 pbs systemd[1]: Starting networking.service - Network initialization...
Jul 31 12:54:00 pbs systemd[1]: Starting proxmox-backup-banner.service - Proxmox Backup Server Login Banner...
Jul 31 12:54:00 pbs systemd[1]: systemd-binfmt.service - Set Up Additional Binary Formats was skipped because of an unmet condition check (ConditionPathIsReadWrite=/proc/sys).
Jul 31 12:54:00 pbs systemd[1]: systemd-machine-id-commit.service - Commit a transient machine-id on disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id).
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-tmpfiles-setup.service - Create Volatile Files and Directories...
Jul 31 12:54:00 pbs systemd[1]: Finished proxmox-backup-banner.service - Proxmox Backup Server Login Banner.
Jul 31 12:54:00 pbs zvol_wait[63]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:00 pbs zvol_wait[63]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:00 pbs zvol_wait[58]: No zvols found, nothing to do.
Jul 31 12:54:00 pbs systemd[1]: Finished zfs-volume-wait.service - Wait for ZFS Volume (zvol) links in /dev.
Jul 31 12:54:00 pbs systemd[1]: Reached target zfs-volumes.target - ZFS volumes are ready.
Jul 31 12:54:00 pbs systemd[1]: Finished systemd-tmpfiles-setup.service - Create Volatile Files and Directories.
Jul 31 12:54:00 pbs systemd[1]: systemd-timesyncd.service - Network Time Synchronization was skipped because of an unmet condition check (ConditionVirtualization=!container).
Jul 31 12:54:00 pbs systemd[1]: Reached target time-set.target - System Time Set.
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP...
Jul 31 12:54:00 pbs networking[68]: networking: Configuring network interfaces
Jul 31 12:54:00 pbs systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP.
Jul 31 12:54:00 pbs systemd[1]: Reached target sysinit.target - System Initialization.
Jul 31 12:54:00 pbs systemd[1]: Started apt-daily.timer - Daily apt download activities.
Jul 31 12:54:00 pbs systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities.
Jul 31 12:54:00 pbs systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer.
Jul 31 12:54:00 pbs systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems.
Jul 31 12:54:00 pbs systemd[1]: Started logrotate.timer - Daily rotation of log files.
Jul 31 12:54:00 pbs systemd[1]: Started man-db.timer - Daily man-db regeneration.
Jul 31 12:54:00 pbs systemd[1]: Started proxmox-backup-daily-update.timer - Daily Proxmox Backup Server update and maintenance activities.
Jul 31 12:54:00 pbs systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories.
Jul 31 12:54:00 pbs systemd[1]: Reached target timers.target - Timer Units.
Jul 31 12:54:00 pbs systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket.
Jul 31 12:54:00 pbs systemd[1]: Reached target sockets.target - Socket Units.
Jul 31 12:54:00 pbs systemd[1]: systemd-pcrphase-sysinit.service - TPM2 PCR Barrier (Initialization) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f).
Jul 31 12:54:00 pbs systemd[1]: Reached target basic.target - Basic System.
Jul 31 12:54:00 pbs systemd[1]: Started cron.service - Regular background program processing daemon.
Jul 31 12:54:00 pbs systemd[1]: Starting dbus.service - D-Bus System Message Bus...
Jul 31 12:54:00 pbs cron[79]: (CRON) INFO (pidfile fd = 3)
Jul 31 12:54:00 pbs cron[79]: (CRON) INFO (Running @reboot jobs)
Jul 31 12:54:00 pbs systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots...
Jul 31 12:54:00 pbs systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon).
Jul 31 12:54:00 pbs systemd[1]: Starting rsyslog.service - System Logging Service...
Jul 31 12:54:00 pbs systemd[1]: smartmontools.service - Self Monitoring and Reporting Technology (SMART) Daemon was skipped because of an unmet condition check (ConditionVirtualization=no).
Jul 31 12:54:00 pbs systemd[1]: Starting systemd-logind.service - User Login Management...
Jul 31 12:54:00 pbs systemd[1]: systemd-pcrphase.service - TPM2 PCR Barrier (User) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f).
Jul 31 12:54:00 pbs systemd[1]: Starting zfs-share.service - ZFS file system shares...
Jul 31 12:54:00 pbs systemd[1]: Started dbus.service - D-Bus System Message Bus.
Jul 31 12:54:00 pbs systemd[1]: Started rsyslog.service - System Logging Service.
Jul 31 12:54:00 pbs rsyslogd[88]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2302.0]
Jul 31 12:54:00 pbs rsyslogd[88]: imklog: cannot open kernel log (/proc/kmsg): Permission denied.
Jul 31 12:54:00 pbs rsyslogd[88]: activation of module imklog failed [v8.2302.0 try https://www.rsyslog.com/e/2145 ]
Jul 31 12:54:00 pbs rsyslogd[88]: [origin software="rsyslogd" swVersion="8.2302.0" x-pid="88" x-info="https://www.rsyslog.com"] start
Jul 31 12:54:00 pbs systemd-logind[89]: New seat seat0.
Jul 31 12:54:00 pbs systemd[1]: Started systemd-logind.service - User Login Management.
Jul 31 12:54:00 pbs systemd[1]: e2scrub_reap.service: Deactivated successfully.
Jul 31 12:54:00 pbs systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots.
Jul 31 12:54:00 pbs info[103]: eth0: enabling syslog for dhcp configuration
Jul 31 12:54:00 pbs info[103]: executing ip -o addr show eth0
Jul 31 12:54:01 pbs info[103]: executing /sbin/dhclient -pf /run/dhclient.eth0.pid -lf /var/lib/dhcp/dhclient.eth0.leases eth0
Jul 31 12:54:01 pbs dhclient[119]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4
Jul 31 12:54:01 pbs dhclient[119]: DHCPOFFER of 192.168.1.33 from 192.168.1.1
Jul 31 12:54:01 pbs dhclient[119]: DHCPREQUEST for 192.168.1.33 on eth0 to 255.255.255.255 port 67
Jul 31 12:54:01 pbs dhclient[119]: DHCPACK of 192.168.1.33 from 192.168.1.1
Jul 31 12:54:01 pbs dhclient[119]: bound to 192.168.1.33 -- renewal in 3077 seconds.
Jul 31 12:54:01 pbs info[103]: executing ip -o addr show eth0
Jul 31 12:54:01 pbs info[103]: eth0: dhclient: new address detected: 192.168.1.33/24
Jul 31 12:54:02 pbs systemd[1]: Finished networking.service - Network initialization.
Jul 31 12:54:02 pbs systemd[1]: Reached target network.target - Network.
Jul 31 12:54:02 pbs systemd[1]: Reached target network-online.target - Network is Online.
Jul 31 12:54:02 pbs systemd[1]: Starting postfix@-.service - Postfix Mail Transport Agent (instance -)...
Jul 31 12:54:02 pbs systemd[1]: Starting proxmox-backup.service - Proxmox Backup API Server...
Jul 31 12:54:02 pbs systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
Jul 31 12:54:02 pbs systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions...
Jul 31 12:54:02 pbs systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions.
Jul 31 12:54:02 pbs systemd[1]: Started console-getty.service - Console Getty.
Jul 31 12:54:02 pbs systemd[1]: Started container-getty@1.service - Container Getty on /dev/tty1.
Jul 31 12:54:02 pbs systemd[1]: Started container-getty@2.service - Container Getty on /dev/tty2.
Jul 31 12:54:02 pbs systemd[1]: Reached target getty.target - Login Prompts.
Jul 31 12:54:02 pbs proxmox-backup-[160]: pbs proxmox-backup-api[160]: service is ready
Jul 31 12:54:02 pbs systemd[1]: Started proxmox-backup.service - Proxmox Backup API Server.
Jul 31 12:54:02 pbs systemd[1]: Starting proxmox-backup-proxy.service - Proxmox Backup API Proxy Server...
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: service is ready
Jul 31 12:54:02 pbs systemd[1]: Started proxmox-backup-proxy.service - Proxmox Backup API Proxy Server.
Jul 31 12:54:02 pbs sshd[173]: Server listening on 0.0.0.0 port 22.
Jul 31 12:54:02 pbs sshd[173]: Server listening on :: port 22.
Jul 31 12:54:02 pbs systemd[1]: Started ssh.service - OpenBSD Secure Shell server.
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: applied rrd journal (1542 entries in 0.033 seconds)
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: write rrd data back to disk
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: starting rrd data sync
Jul 31 12:54:02 pbs postfix[231]: Postfix is using backwards-compatible default settings
Jul 31 12:54:02 pbs postfix[231]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Jul 31 12:54:02 pbs postfix[231]: To disable backwards compatibility use "postconf compatibility_level=3.6" and "postfix reload"
Jul 31 12:54:02 pbs proxmox-backup-[172]: pbs proxmox-backup-proxy[172]: rrd journal successfully committed (20 files in 0.129 seconds)
Jul 31 12:54:02 pbs postfix/postfix-script[322]: starting the Postfix mail system
Jul 31 12:54:02 pbs postfix/master[324]: daemon started -- version 3.7.6, configuration /etc/postfix
Jul 31 12:54:02 pbs systemd[1]: Started postfix@-.service - Postfix Mail Transport Agent (instance -).
Jul 31 12:54:02 pbs systemd[1]: Starting postfix.service - Postfix Mail Transport Agent...
Jul 31 12:54:02 pbs systemd[1]: Finished postfix.service - Postfix Mail Transport Agent.
Jul 31 12:54:10 pbs zfs[90]: /dev/zfs and /proc/self/mounts are required.
Jul 31 12:54:10 pbs zfs[90]: Try running 'udevadm trigger' and 'mount -t proc proc /proc' as root.
Jul 31 12:54:10 pbs systemd[1]: zfs-share.service: Main process exited, code=exited, status=1/FAILURE
Jul 31 12:54:10 pbs systemd[1]: zfs-share.service: Failed with result 'exit-code'.
Jul 31 12:54:10 pbs systemd[1]: Failed to start zfs-share.service - ZFS file system shares.
Jul 31 12:54:10 pbs systemd[1]: Reached target zfs.target - ZFS startup target.
Jul 31 12:54:10 pbs systemd[1]: Reached target multi-user.target - Multi-User System.
Jul 31 12:54:10 pbs systemd[1]: Reached target graphical.target - Graphical Interface.
Jul 31 12:54:10 pbs systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP...
Jul 31 12:54:10 pbs systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully.
Jul 31 12:54:10 pbs systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP.
Jul 31 12:54:10 pbs systemd[1]: Startup finished in 20.471s.
Jul 31 12:54:24 pbs sshd[329]: Accepted publickey for pbsuser from 192.168.1.51 port 40036 ssh2: ED25519 SHA256:XYqVYvEDaGTtH58w0iRM7UQ7U6XukS+hoNpQp4kBtek
Jul 31 12:54:24 pbs sshd[329]: pam_unix(sshd:session): session opened for user pbsuser(uid=1000) by (uid=0)
Jul 31 12:54:24 pbs systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
Jul 31 12:54:24 pbs systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...
Jul 31 12:54:24 pbs systemd-logind[89]: New session 3916 of user pbsuser.
Jul 31 12:54:24 pbs systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000.
Jul 31 12:54:24 pbs systemd[1]: Starting user@1000.service - User Manager for UID 1000...
Jul 31 12:54:24 pbs (systemd)[332]: pam_unix(systemd-user:session): session opened for user pbsuser(uid=1000) by (uid=0)
Jul 31 12:54:24 pbs systemd[332]: Queued start job for default target default.target.
Jul 31 12:54:24 pbs systemd[332]: Created slice app.slice - User Application Slice.
Jul 31 12:54:24 pbs sshd[329]: pam_env(sshd:session): deprecated reading of user environment enabled
Jul 31 12:54:24 pbs systemd[332]: Reached target paths.target - Paths.
Jul 31 12:54:24 pbs systemd[332]: Reached target timers.target - Timers.
Jul 31 12:54:24 pbs systemd[332]: Starting dbus.socket - D-Bus User Message Bus Socket...
Jul 31 12:54:24 pbs systemd[332]: Listening on dbus.socket - D-Bus User Message Bus Socket.
Jul 31 12:54:24 pbs systemd[332]: Reached target sockets.target - Sockets.
Jul 31 12:54:24 pbs systemd[332]: Reached target basic.target - Basic System.
Jul 31 12:54:24 pbs systemd[1]: Started user@1000.service - User Manager for UID 1000.
Jul 31 12:54:24 pbs systemd[1]: Started session-3916.scope - Session 3916 of User pbsuser.
Jul 31 12:54:24 pbs systemd[332]: Reached target default.target - Main User Target.
Jul 31 12:54:24 pbs systemd[332]: Startup finished in 39ms.
Jul 31 12:54:49 pbs sudo[372]:  pbsuser : TTY=pts/3 ; PWD=/home/pbsuser ; USER=root ; COMMAND=/usr/bin/journalctl -b
Jul 31 12:54:49 pbs sudo[372]: pam_limits(sudo:session): Could not set limit for 'core' to soft=0, hard=-1: Operation not permitted; uid=1000,euid=0
Jul 31 12:54:49 pbs sudo[372]: pam_unix(sudo:session): session opened for user root(uid=0) by pbsuser(uid=1000)
Jul 31 12:54:49 pbs sudo[372]: pam_unix(sudo:session): session closed for user root
Jul 31 12:55:01 pbs CRON[379]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jul 31 12:55:01 pbs CRON[380]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 31 12:55:01 pbs CRON[379]: pam_unix(cron:session): session closed for user root
Jul 31 13:05:01 pbs CRON[391]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Jul 31 13:05:01 pbs CRON[392]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 31 13:05:01 pbs CRON[391]: pam_unix(cron:session): session closed for user root
Jul 31 13:09:27 pbs systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories...
Jul 31 13:09:27 pbs systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Jul 31 13:09:27 pbs systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories.
Jul 31 13:09:27 pbs systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully.
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: starting new backup on datastore 'pbsDatastore': "host/prodesk/2023-07-31T18:12:54Z"
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: protocol upgrade done
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: GET /previous_backup_time
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: GET /previous
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: download 'index.json.blob' from previous backup.
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: POST /dynamic_index
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: GET /previous
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: register chunks in 'root.pxar.didx' from previous backup.
Jul 31 13:12:54 pbs proxmox-backup-proxy[172]: download 'root.pxar.didx' from previous backup.
 
Last edited:
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom
Back