Backup failed with "start failed: org.freedesktop.systemd1.UnitExists: Unit 142.scope already exists"

Dunuin

Dunuin

Distinguished Member
Jun 30, 2020
14,356
4,212
243
Germany
Hi, tonight a single VM backup of my weekly PBS backup job failed with this:
Code: 
INFO: Starting Backup of VM 142 (qemu)
INFO: Backup started at 2023-01-29 05:54:23
INFO: status = running
INFO: backup mode: stop
INFO: ionice priority: 7
INFO: VM Name: HomeAssistant
INFO: include disk 'scsi0' 'ZFS_8K:vm-142-disk-0' 32G
INFO: include disk 'efidisk0' 'ZFS_8K:vm-142-disk-1' 1M
INFO: stopping virtual guest
INFO: creating Proxmox Backup Server archive 'vm/142/2023-01-29T04:54:23Z'
INFO: starting kvm to execute backup task
INFO: restarting vm
INFO: kvm: warning: host doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
INFO: kvm: warning: host doesn't support requested feature: CPUID.07H:EDX.ssbd [bit 31]
INFO: kvm: warning: host doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
INFO: kvm: warning: host doesn't support requested feature: CPUID.07H:EDX.ssbd [bit 31]
INFO: guest is online again after 31 seconds
ERROR: Backup of VM 142 failed - start failed: org.freedesktop.systemd1.UnitExists: Unit 142.scope already exists.
INFO: Failed at 2023-01-29 05:54:54

What could have caused this "start failed: org.freedesktop.systemd1.UnitExists: Unit 142.scope already exists" error?
Can I do something to prevent it in the future?

It's my HomeAssistant VM with these options:
Code: 
root@j3710:~# qm config 142
agent: 1
bios: ovmf
boot: order=scsi0
cores: 2
cpu: host,flags=+pcid;+spec-ctrl;+ssbd;+aes
cpuunits: 25
description: 19.11.2022 19%3A33%3A%0ASwitched from "Virtio SCSI single" to "Virtio SCSI" and disabled "IO thread" for "scsi0"
efidisk0: ZFS_8K:vm-142-disk-1,efitype=4m,size=1M
ide2: none,media=cdrom
memory: 2048
meta: creation-qemu=7.0.0,ctime=1668623363
name: HomeAssistant
net0: virtio=XX:XX:XX:XX:XX:XX,bridge=vmbr42,firewall=1
net1: virtio=XX:XX:XX:XX:XX:XX,bridge=vmbr50,firewall=1
numa: 0
onboot: 1
ostype: l26
scsi0: ZFS_8K:vm-142-disk-0,discard=on,size=32G,ssd=1
scsihw: virtio-scsi-pci
smbios1: uuid=d0ec430f-d736-43a5-bf24-2893f2ac43fc
sockets: 1
startup: order=10
tags: j3710
vmgenid: 7993b382-1ad0-46fd-8e0c-36e221e97592
 
Last edited:
Yes. There is one starting at 5:30 and three starting at 6:30. The failed backup was part of the job that started at 5:30 and finished at 5:56:

1675077554086.png
1675077623420.png
 
Hi,

Dunuin said:
What could have caused this "start failed: org.freedesktop.systemd1.UnitExists: Unit 142.scope already exists" error?
Click to expand...
It is possible that the unit was not properly cleaned after the previous backup job run! What version of the PBS running?

Did you see anything in the syslog?

I would check also of the status of the Unit `systemctl status 142.scope` in order to see if it's failed or "active".
 
Moayad said:
It is possible that the unit was not properly cleaned after the previous backup job run! What version of the PBS running?
Click to expand...
The PBS server with the failed backup is on the latest 2.3 no-subscription version with no available packages for an upgrade. The Tuxis PBS of the other backup jobs is "2.3-1".
Moayad said:
Did you see anything in the syslog?
Click to expand...
Syslog shows this:
Code: 
Jan 29 05:54:23 j3710 pvescheduler[1782385]: INFO: Finished Backup of VM 141 (00:05:16)
Jan 29 05:54:23 j3710 pvescheduler[1782385]: INFO: Starting Backup of VM 142 (qemu)
Jan 29 05:54:26 j3710 qm[1916263]: shutdown VM 142: UPID:j3710:001D3D67:112551C9:63D5FC02:qmshutdown:142:root@pam:
Jan 29 05:54:26 j3710 qm[1916143]: <root@pam> starting task UPID:j3710:001D3D67:112551C9:63D5FC02:qmshutdown:142:root@pam:
Jan 29 05:54:31 j3710 filebeat[2789]: 2023-01-29T05:54:31.824+0100    ERROR    [logstash]    logstash/async.go:280    Failed to publish events caused by: EOF
Jan 29 05:54:31 j3710 filebeat[2789]: 2023-01-29T05:54:31.825+0100    ERROR    [logstash]    logstash/async.go:280    Failed to publish events caused by: client is not connected
Jan 29 05:54:33 j3710 filebeat[2789]: 2023-01-29T05:54:33.668+0100    ERROR    [publisher_pipeline_output]    pipeline/output.go:180    failed to publish events: client is not connected
Jan 29 05:54:44 j3710 kernel:  zd0: p1 p2 p3 p4 p5 p6 p7 p8
Jan 29 05:54:45 j3710 kernel: fwbr142i0: port 2(tap142i0) entered disabled state
Jan 29 05:54:45 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered disabled state
Jan 29 05:54:45 j3710 kernel: vmbr42: port 5(fwpr142p0) entered disabled state
Jan 29 05:54:45 j3710 kernel: device fwln142i0 left promiscuous mode
Jan 29 05:54:45 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered disabled state
Jan 29 05:54:45 j3710 kernel: device fwpr142p0 left promiscuous mode
Jan 29 05:54:45 j3710 kernel: vmbr42: port 5(fwpr142p0) entered disabled state
Jan 29 05:54:46 j3710 kernel: fwbr142i1: port 2(tap142i1) entered disabled state
Jan 29 05:54:46 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered disabled state
Jan 29 05:54:46 j3710 kernel: vmbr50: port 3(fwpr142p1) entered disabled state
Jan 29 05:54:46 j3710 kernel: device fwln142i1 left promiscuous mode
Jan 29 05:54:46 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered disabled state
Jan 29 05:54:46 j3710 kernel: device fwpr142p1 left promiscuous mode
Jan 29 05:54:46 j3710 kernel: vmbr50: port 3(fwpr142p1) entered disabled state
Jan 29 05:54:46 j3710 qmeventd[2001]: read: Connection reset by peer
Jan 29 05:54:46 j3710 qm[1916143]: <root@pam> end task UPID:j3710:001D3D67:112551C9:63D5FC02:qmshutdown:142:root@pam: OK
Jan 29 05:54:46 j3710 systemd[1]: 142.scope: Succeeded.
Jan 29 05:54:46 j3710 systemd[1]: Stopped 142.scope.
Jan 29 05:54:46 j3710 systemd[1]: 142.scope: Consumed 2d 3h 26min 27.232s CPU time.
Jan 29 05:54:48 j3710 qmeventd[1918082]: Starting cleanup for 142
Jan 29 05:54:48 j3710 qmeventd[1918082]: Finished cleanup for 142
Jan 29 05:54:49 j3710 qm[1918117]: start VM 142: UPID:j3710:001D44A5:11255AAB:63D5FC18:qmstart:142:root@pam:
Jan 29 05:54:49 j3710 qm[1918085]: <root@pam> starting task UPID:j3710:001D44A5:11255AAB:63D5FC18:qmstart:142:root@pam:
Jan 29 05:54:49 j3710 systemd[1]: Started 142.scope.
Jan 29 05:54:49 j3710 systemd-udevd[1917999]: Using default interface naming scheme 'v247'.
Jan 29 05:54:49 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:51 j3710 kernel: device tap142i0 entered promiscuous mode
Jan 29 05:54:51 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:51 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:51 j3710 systemd-udevd[1918001]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:51 j3710 systemd-udevd[1918001]: Using default interface naming scheme 'v247'.
Jan 29 05:54:51 j3710 kernel: vmbr42: port 5(fwpr142p0) entered blocking state
Jan 29 05:54:51 j3710 kernel: vmbr42: port 5(fwpr142p0) entered disabled state
Jan 29 05:54:51 j3710 kernel: device fwpr142p0 entered promiscuous mode
Jan 29 05:54:51 j3710 kernel: vmbr42: port 5(fwpr142p0) entered blocking state
Jan 29 05:54:51 j3710 kernel: vmbr42: port 5(fwpr142p0) entered forwarding state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered blocking state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered disabled state
Jan 29 05:54:51 j3710 kernel: device fwln142i0 entered promiscuous mode
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered blocking state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 1(fwln142i0) entered forwarding state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 2(tap142i0) entered blocking state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 2(tap142i0) entered disabled state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 2(tap142i0) entered blocking state
Jan 29 05:54:51 j3710 kernel: fwbr142i0: port 2(tap142i0) entered forwarding state
Jan 29 05:54:51 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:53 j3710 kernel: device tap142i1 entered promiscuous mode
Jan 29 05:54:53 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:53 j3710 systemd-udevd[1917999]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:53 j3710 systemd-udevd[1918337]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 29 05:54:53 j3710 systemd-udevd[1918337]: Using default interface naming scheme 'v247'.
Jan 29 05:54:53 j3710 kernel: vmbr50: port 3(fwpr142p1) entered blocking state
Jan 29 05:54:53 j3710 kernel: vmbr50: port 3(fwpr142p1) entered disabled state
Jan 29 05:54:53 j3710 kernel: device fwpr142p1 entered promiscuous mode
Jan 29 05:54:53 j3710 kernel: vmbr50: port 3(fwpr142p1) entered blocking state
Jan 29 05:54:53 j3710 kernel: vmbr50: port 3(fwpr142p1) entered forwarding state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered blocking state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered disabled state
Jan 29 05:54:54 j3710 kernel: device fwln142i1 entered promiscuous mode
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered blocking state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 1(fwln142i1) entered forwarding state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 2(tap142i1) entered blocking state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 2(tap142i1) entered disabled state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 2(tap142i1) entered blocking state
Jan 29 05:54:54 j3710 kernel: fwbr142i1: port 2(tap142i1) entered forwarding state
Jan 29 05:54:54 j3710 qm[1918085]: <root@pam> end task UPID:j3710:001D44A5:11255AAB:63D5FC18:qmstart:142:root@pam: OK
Jan 29 05:54:54 j3710 pvescheduler[1782385]: ERROR: Backup of VM 142 failed - start failed: org.freedesktop.systemd1.UnitExists: Unit 142.scope already exists.
Jan 29 05:54:54 j3710 pvescheduler[1782385]: INFO: Starting Backup of VM 143 (lxc)
Moayad said:
I would check also of the status of the Unit `systemctl status 142.scope` in order to see if it's failed or "active".
Click to expand...
Code: 
root@j3710:~# systemctl status 142.scope
● 142.scope
     Loaded: loaded (/run/systemd/transient/142.scope; transient)
  Transient: yes
     Active: active (running) since Sun 2023-01-29 14:16:45 CET; 24h ago
      Tasks: 8 (limit: 18957)
     Memory: 1.8G
        CPU: 7h 16min 46.677s
     CGroup: /qemu.slice/142.scope
             └─242709 /usr/bin/kvm -id 142 -name HomeAssistant,debug-threads=on -no-shutdown -chardev socket,id=qmp,path=/var/run/qemu-server/142.qmp,server=>


Jan 29 14:16:45 j3710 systemd[1]: Started 142.scope.
 
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