Hi,
today I got massive problems with my vms.
First Win11 starts to show no reaction. Than I want to restart, this takes a loong time and doesn´t work, so I switched it off.
Than I want to restore a Backup from my NAS (NFS-System). It starts very slow (20 secs per percent and at 10% it needs 100 secs.)
At this time, my opnsense-vm isn´t reachable and internet goes down.
On console it shows something like
(da0:vtscsi0:0:0:0): CAM status: Command timeout
(da0:vtscsi0:0:0:0): Retrying command, 3 more tries
(da0:vtscsi0:0:0:0): SYNCHRONIZE CACHE(1). CDB: 35 00 00 ...
Syslog:
When I stop restore and restart OPNSense, it seems, that all works fine...
Greets
Byte
today I got massive problems with my vms.
First Win11 starts to show no reaction. Than I want to restart, this takes a loong time and doesn´t work, so I switched it off.
Than I want to restore a Backup from my NAS (NFS-System). It starts very slow (20 secs per percent and at 10% it needs 100 secs.)
At this time, my opnsense-vm isn´t reachable and internet goes down.
On console it shows something like
(da0:vtscsi0:0:0:0): CAM status: Command timeout
(da0:vtscsi0:0:0:0): Retrying command, 3 more tries
(da0:vtscsi0:0:0:0): SYNCHRONIZE CACHE(1). CDB: 35 00 00 ...
Syslog:
Code:
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Processes still around after final SIGKILL. Entering failed mode.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Failed with result 'watchdog'.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Unit process 161553 (systemd-udevd) remains running after unit stopped.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Consumed 11.744s CPU time.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 2.
Feb 28 16:13:02 proxmox systemd[1]: Stopped Rule-based Manager for Device Events and Files.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Consumed 11.744s CPU time.
Feb 28 16:13:02 proxmox systemd[1]: systemd-udevd.service: Found left-over process 161553 (systemd-udevd) in control group while starting unit. Ignoring.
Feb 28 16:13:02 proxmox systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Feb 28 16:13:02 proxmox systemd[1]: Starting Rule-based Manager for Device Events and Files...
Feb 28 16:13:02 proxmox systemd[1]: Started Rule-based Manager for Device Events and Files.
Feb 28 16:13:02 proxmox systemd-udevd[271340]: Using default interface naming scheme 'v247'.
Feb 28 16:13:02 proxmox systemd-udevd[271340]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 28 16:13:02 proxmox systemd-udevd[271342]: Using default interface naming scheme 'v247'.
Feb 28 16:13:02 proxmox systemd-udevd[271342]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 28 16:13:02 proxmox systemd-udevd[271343]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 28 16:13:02 proxmox systemd-udevd[271337]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 28 16:13:02 proxmox systemd-udevd[271337]: Using default interface naming scheme 'v247'.
Feb 28 16:13:02 proxmox systemd-udevd[271336]: Using default interface naming scheme 'v247'.
Feb 28 16:13:02 proxmox systemd-udevd[271337]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 28 16:13:04 proxmox kernel: usb 1-8.3: reset full-speed USB device number 7 using xhci_hcd
Feb 28 16:13:05 proxmox kernel: usb 1-8.2: reset full-speed USB device number 9 using xhci_hcd
Feb 28 16:13:46 proxmox zed[32523]: Missed 24 events
Feb 28 16:13:46 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:13:46 proxmox zed[32523]: Missed 96 events
Feb 28 16:13:46 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:13:46 proxmox zed[32523]: Missed 49 events
Feb 28 16:13:46 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:13:46 proxmox zed[273356]: eid=261 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=8192 offset=872588496896 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1240076
Feb 28 16:13:46 proxmox zed[273361]: eid=262 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=8192 offset=872588488704 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1240075
Feb 28 16:13:46 proxmox zed[273416]: eid=277 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=45056 offset=506975404032 priority=3 err=0 flags=0x184880 bookmark=453:1:1:1210
Feb 28 16:13:46 proxmox zed[273417]: eid=274 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=126976 offset=872588296192 priority=3 err=0 flags=0x40080c80 delay=3874583ms
Feb 28 16:14:03 proxmox systemd-udevd[271333]: zd400: Worker [271338] processing SEQNUM=5588 is taking a long time
Feb 28 16:14:47 proxmox zed[32523]: Missed 18 events
Feb 28 16:14:47 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:14:47 proxmox zed[32523]: Missed 108 events
Feb 28 16:14:47 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:14:47 proxmox zed[276426]: eid=279 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805998592 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278429
Feb 28 16:14:47 proxmox zed[276478]: eid=284 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805978112 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278424
Feb 28 16:14:47 proxmox zed[276487]: eid=285 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805974016 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278423
Feb 28 16:14:47 proxmox zed[276480]: eid=295 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=8192 offset=872805912576 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278413
Feb 28 16:14:47 proxmox zed[276479]: eid=294 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805920768 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278414
Feb 28 16:14:47 proxmox zed[276486]: eid=296 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=8192 offset=872805904384 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278412
Feb 28 16:14:47 proxmox zed[276490]: eid=290 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805937152 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278418
Feb 28 16:14:47 proxmox zed[276492]: eid=292 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=872805928960 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278416
Feb 28 16:14:47 proxmox zed[276498]: eid=297 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224_part1 size=8192 offset=872805896192 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1278411
Feb 28 16:15:15 proxmox audit[277569]: AVC apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox kernel: audit: type=1400 audit(1646061315.918:42): apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox kernel: audit: type=1400 audit(1646061315.918:43): apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox kernel: audit: type=1400 audit(1646061315.918:44): apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox kernel: audit: type=1400 audit(1646061315.922:45): apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox kernel: audit: type=1400 audit(1646061315.922:46): apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox audit[277569]: AVC apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox audit[277569]: AVC apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox audit[277569]: AVC apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:15 proxmox audit[277569]: AVC apparmor="DENIED" operation="open" namespace="root//lxc-107_<-var-lib-lxc>" profile="/usr/sbin/unbound" name="/proc/sys/kernel/random/boot_id" pid=277569 comm="unbound" requested_mask="r" denied_mask="r" fsuid=100000 ouid=100000
Feb 28 16:15:49 proxmox zed[32523]: Missed 16 events
Feb 28 16:15:49 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:15:49 proxmox zed[32523]: Missed 128 events
Feb 28 16:15:49 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:15:49 proxmox zed[32523]: Missed 28 events
Feb 28 16:15:49 proxmox zed[32523]: Bumping queue length to 2147483647
Feb 28 16:15:49 proxmox zed[278890]: eid=300 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=4096 offset=873043943424 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1339439
Feb 28 16:15:49 proxmox zed[278908]: eid=306 class=deadman pool='SSD_BigStore' vdev=ata-SanDisk_SSD_PLUS_1000GB_21224-part1 size=8192 offset=873043910656 priority=3 err=0 flags=0x184880 bookmark=453:1:0:1339433
[..]
Feb 28 16:16:03 proxmox systemd-udevd[271333]: zd400: Worker [271338] processing SEQNUM=5588 killed
When I stop restore and restart OPNSense, it seems, that all works fine...
Greets
Byte
Last edited: