Arch Linux

Rupioe

Member

Registered: 2023-04-16

Posts: 2

[SOLVED] Slow boot and impossible shutdown when using second monitor

Hello, this is my first post here, I usually succeed debugging alone, but not this time;
Every time I boot with my monitor plugged to my laptop, I have to wait 15 secondes before login manager display appears.
I also have weird ACPI warnings, and after watchdogs alerts are displayed, the system still can't shutdown.
Because systemd-shutdown has already been reached, there is no output of it in journalctl.
My setup :
Laptop connected to a Monitor through usb-c hub.
My xrandr config is "hardcoded" for that setup which means I'll only get the right resolution and everything if the monitor is plugged like that.
I have tried downgrading kernek, did not work.
There is nothing much interesting in my last updated packages.
Last things i did before it happened is modprobing some bus related modules like i2c-dev.
And trying to install virtual box, which is not working currently but that's a story for another time.

Here is an extract of journalctl at boot :

Apr 16 23:50:44 Darchrai systemd[1]: Reached target Sound Card.
Apr 16 23:50:44 Darchrai root[809]: ACPI group/action undefined: jack/lineout / LINEOUT
Apr 16 23:50:44 Darchrai root[811]: ACPI group/action undefined: jack/videoout / VIDEOOUT
Apr 16 23:50:45 Darchrai ifplugd(enp0s13f0u1u2u1)[383]: Link beat detected.
Apr 16 23:50:45 Darchrai root[813]: ACPI group/action undefined: jack/lineout / LINEOUT
Apr 16 23:50:45 Darchrai root[815]: ACPI group/action undefined: jack/videoout / VIDEOOUT
Apr 16 23:50:46 Darchrai ifplugd(enp0s13f0u1u2u1)[383]: Executing '/etc/ifplugd/ifplugd.action enp0s13f0u1u2u1 up'.
Apr 16 23:50:46 Darchrai dhcpcd[372]: wlan0: Router Advertisement from fe80::9a42:65ff:fe2d:3800
Apr 16 23:50:46 Darchrai dhcpcd[372]: wlan0: adding address 2a01:cb08:8c43:a00:1774:ef37:a75b:297a/64
Apr 16 23:50:46 Darchrai dhcpcd[372]: wlan0: adding route to 2a01:cb08:8c43:a00::/64
Apr 16 23:50:46 Darchrai dhcpcd[372]: wlan0: adding default route via fe80::9a42:65ff:fe2d:3800
Apr 16 23:50:46 Darchrai dhcpcd[372]: wlan0: requesting DHCPv6 information
Apr 16 23:50:46 Darchrai kernel: ucsi_acpi USBC000:00: PPM init failed (-110)
Apr 16 23:50:46 Darchrai ifplugd(enp0s13f0u1u2u1)[383]: Program executed successfully.
Apr 16 23:50:46 Darchrai systemd[1]: systemd-rfkill.service: Deactivated successfully.
Apr 16 23:50:47 Darchrai dhcpcd[372]: wlan0: REPLY6 received from fe80::9a42:65ff:fe2d:3800
Apr 16 23:50:47 Darchrai dhcpcd[372]: wlan0: refresh in 86400 seconds
Apr 16 23:50:56 Darchrai dhcpcd[372]: enp0s13f0u1u2u1: no IPv6 Routers available
Apr 16 23:51:00 Darchrai root[859]: ACPI group/action undefined: 9DBB5994-A997- / 000000d0
Apr 16 23:51:10 Darchrai systemd-timesyncd[334]: Contacted time server [2a05:f480:2400:1b10::123]:123 (2.arch.pool.ntp.org).
Apr 16 23:51:10 Darchrai systemd-timesyncd[334]: Initial clock synchronization to Sun 2023-04-16 23:51:10.729255 CEST.
Apr 16 23:51:11 Darchrai systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Apr 16 23:51:18 Darchrai lightdm[867]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=971) by (uid=0)
Apr 16 23:51:18 Darchrai systemd[1]: Created slice User Slice of UID 971.
Apr 16 23:51:18 Darchrai systemd[1]: Starting User Runtime Directory /run/user/971...
Apr 16 23:51:18 Darchrai systemd-logind[462]: New session c1 of user lightdm.

The ACPI undefined prompt is from /etc/acpi.d/handler.sh, though I don't know what this code is corresponding to.
I've searched a bit about the problem, and windows fast boot or hibernation came up a lot, I did powercfg /h off in an admin cmd on my windows double boot.
(I don't know if its related but then the UEFI boot order changed and I had to put grub up through windows recovery restart)

Also the enp0 dhcpcd warning is nothing to care about, ive got a nas connected in direct ethernet to my laptop.

Journalctl extract at shutdown :

Apr 16 23:21:36 Darchrai systemd[1]: Stopped User Login Management.
Apr 16 23:21:36 Darchrai systemd[1]: ifplugd@enp0s13f0u1u2u1.service: Deactivated successfully.
Apr 16 23:21:36 Darchrai systemd[1]: Stopped Daemon which acts upon network cable insertion/removal.
Apr 16 23:21:36 Darchrai systemd[1]: lm_sensors.service: Deactivated successfully.
Apr 16 23:21:36 Darchrai systemd[1]: Stopped Initialize hardware monitoring sensors.
Apr 16 23:21:37 Darchrai systemd[1]: Removed slice Slice /system/ifplugd.
Apr 16 23:21:37 Darchrai acpid[437]: exiting
Apr 16 23:21:37 Darchrai systemd[1]: acpid.service: Deactivated successfully.
Apr 16 23:21:37 Darchrai systemd[1]: Stopped ACPI event daemon.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: State 'stop-sigterm' timed out. Killing.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Killing process 978 (systemd) with signal SIGKILL.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Killing process 1216 (wireplumber) with signal SIGKILL.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Killing process 1215 (pipewire) with signal SIGKILL.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Killing process 1222 (pipewire) with signal SIGKILL.
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Main process exited, code=killed, status=9/KILL
Apr 16 23:21:55 Darchrai systemd[1]: user@1000.service: Killing process 1216 (wireplumber) with signal SIGKILL.
Apr 16 23:22:05 Darchrai kernel: snd_hda_codec_realtek ehdaudio0D0: Unable to sync register 0x2b8000. -5
Apr 16 23:22:09 Darchrai kernel: snd_hda_codec_realtek ehdaudio0D0: Unable to sync register 0x2b8000. -5
Apr 16 23:22:09 Darchrai systemd[1]: user@1000.service: Failed with result 'timeout'.
Apr 16 23:22:09 Darchrai systemd[1]: Stopped User Manager for UID 1000.
Apr 16 23:22:09 Darchrai systemd[1]: Stopping Permit User Sessions...
Apr 16 23:22:09 Darchrai systemd[1]: Stopping User Runtime Directory /run/user/1000...

skipping some seemingly normal shutdown prompt...

Apr 16 23:22:11 Darchrai systemd[1]: Reached target Unmount All Filesystems.
Apr 16 23:22:11 Darchrai systemd[1]: Reached target Late Shutdown Services.
Apr 16 23:22:11 Darchrai systemd[1]: systemd-reboot.service: Deactivated successfully.
Apr 16 23:22:11 Darchrai systemd[1]: Finished System Reboot.
Apr 16 23:22:11 Darchrai systemd[1]: Reached target System Reboot.
Apr 16 23:22:11 Darchrai systemd[1]: Shutting down.
Apr 16 23:22:11 Darchrai systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog0
Apr 16 23:22:11 Darchrai systemd[1]: Watchdog running with a timeout of 10min.
Apr 16 23:22:11 Darchrai kernel: watchdog: watchdog0: watchdog did not stop!
Apr 16 23:22:11 Darchrai systemd-shutdown[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog0
Apr 16 23:22:11 Darchrai systemd-shutdown[1]: Watchdog running with a timeout of 10min.
Apr 16 23:22:11 Darchrai systemd-shutdown[1]: Syncing filesystems and block devices.
Apr 16 23:22:11 Darchrai systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Apr 16 23:22:11 Darchrai systemd-journald[214]: Received SIGTERM from PID 1 (systemd-shutdow).
Apr 16 23:22:11 Darchrai systemd-journald[214]: Journal stopped
-- Boot bffc00abea324862b51172a9145ca96e --

... then there is the boot log

Tell me if you want the whole log of a boot or shutdown, I just took the suspect parts, or gap parts.
There is a strange break at "Stopped ACPI event daemon." in shutdown.
Et voila, that is all I got for now, thanks for reading me.

Last edited by Rupioe (2023-04-16 23:13:43)

Rupioe

Member

Registered: 2023-04-16

Posts: 2

Re: [SOLVED] Slow boot and impossible shutdown when using second monitor

I have waited for the shutdown of the computer for 5 minutes after watchdog did not stop, and the laptop finally shutdown.
Now it seems to be working fine, I don't know why.
Here is the new boot log :

Apr 17 01:00:01 Darchrai root[779]: ACPI group/action undefined: jack/videoout / VIDEOOUT
Apr 17 01:00:02 Darchrai root[781]: ACPI group/action undefined: jack/lineout / LINEOUT
Apr 17 01:00:02 Darchrai root[783]: ACPI group/action undefined: jack/videoout / VIDEOOUT
Apr 17 01:00:02 Darchrai lightdm[786]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=971) by (uid=0)
Apr 17 01:00:02 Darchrai systemd[1]: Created slice User Slice of UID 971.
Apr 17 01:00:02 Darchrai systemd[1]: Starting User Runtime Directory /run/user/971...
Apr 17 01:00:02 Darchrai systemd-logind[480]: New session c1 of user lightdm.
Apr 17 01:00:02 Darchrai systemd[1]: Finished User Runtime Directory /run/user/971.
Apr 17 01:00:02 Darchrai systemd[1]: Starting User Manager for UID 971...
Apr 17 01:00:02 Darchrai dbus-daemon[442]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.13' (uid=0 pid=793 comm="(systemd)")
Apr 17 01:00:02 Darchrai dbus-daemon[442]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Apr 17 01:00:02 Darchrai (systemd)[793]: pam_systemd_home(systemd-user:account): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Apr 17 01:00:02 Darchrai (systemd)[793]: pam_warn(systemd-user:setcred): function=[pam_sm_setcred] flags=0x8002 service=[systemd-user] terminal=[] user=[lightdm] ruser=[<unknown>] rhost=[<unknown>]
Apr 17 01:00:02 Darchrai (systemd)[793]: pam_unix(systemd-user:session): session opened for user lightdm(uid=971) by (uid=0)
Apr 17 01:00:03 Darchrai systemd[793]: Queued start job for default target Main User Target.
Apr 17 01:00:03 Darchrai systemd[793]: Created slice User Application Slice.
Apr 17 01:00:03 Darchrai systemd[793]: Reached target Paths.
Apr 17 01:00:03 Darchrai systemd[793]: Reached target Timers.
Apr 17 01:00:03 Darchrai systemd[793]: Starting D-Bus User Message Bus Socket...
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GnuPG network certificate management daemon.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GCR ssh-agent wrapper.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Apr 17 01:00:03 Darchrai systemd[793]: Listening on GnuPG cryptographic agent and passphrase cache.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on p11-kit server.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on PipeWire PulseAudio.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on PipeWire Multimedia System Socket.
Apr 17 01:00:03 Darchrai systemd[793]: Listening on D-Bus User Message Bus Socket.
Apr 17 01:00:03 Darchrai systemd[793]: Reached target Sockets.
Apr 17 01:00:03 Darchrai systemd[793]: Reached target Basic System.
Apr 17 01:00:03 Darchrai systemd[1]: Started User Manager for UID 971.
Apr 17 01:00:03 Darchrai systemd[793]: Starting Update XDG user dir configuration...
Apr 17 01:00:03 Darchrai systemd[1]: Started Session c1 of User lightdm.
Apr 17 01:00:03 Darchrai systemd[793]: Finished Update XDG user dir configuration.
Apr 17 01:00:03 Darchrai systemd[793]: Reached target Main User Target.
Apr 17 01:00:03 Darchrai systemd[793]: Startup finished in 127ms.
Apr 17 01:00:03 Darchrai systemd[793]: Created slice User Core Session Slice.
Apr 17 01:00:03 Darchrai dhcpcd[448]: wlan0: Router Advertisement from fe80::9a42:65ff:fe2d:3800
Apr 17 01:00:03 Darchrai dhcpcd[448]: wlan0: adding address 2a01:cb08:8c43:a00:1774:ef37:a75b:297a/64
Apr 17 01:00:03 Darchrai systemd[793]: Starting D-Bus User Message Bus...
Apr 17 01:00:03 Darchrai dhcpcd[448]: wlan0: adding route to 2a01:cb08:8c43:a00::/64
Apr 17 01:00:03 Darchrai dhcpcd[448]: wlan0: adding default route via fe80::9a42:65ff:fe2d:3800
Apr 17 01:00:03 Darchrai dhcpcd[448]: wlan0: requesting DHCPv6 information
Apr 17 01:00:03 Darchrai systemd[793]: Started D-Bus User Message Bus.
Apr 17 01:00:03 Darchrai dbus-daemon[810]: [session uid=971 pid=810] Activating systemd to hand-off: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service' requested by ':1.0' (uid=971 pid=801 comm="/usr/bin/lightdm-webkit2-greeter")
Apr 17 01:00:03 Darchrai dbus-daemon[810]: [session uid=971 pid=810] Successfully activated service 'org.freedesktop.systemd1'
Apr 17 01:00:03 Darchrai systemd[793]: Starting Accessibility services bus...
Apr 17 01:00:03 Darchrai dbus-daemon[810]: [session uid=971 pid=810] Successfully activated service 'org.a11y.Bus'
Apr 17 01:00:03 Darchrai systemd[793]: Started Accessibility services bus.
Apr 17 01:00:03 Darchrai at-spi-bus-launcher[818]: dbus-daemon[818]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=971 pid=801 comm="/usr/bin/lightdm-webkit2-greeter")
Apr 17 01:00:03 Darchrai at-spi-bus-launcher[818]: dbus-daemon[818]: Successfully activated service 'org.a11y.atspi.Registry'
Apr 17 01:00:03 Darchrai at-spi-bus-launcher[831]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
Apr 17 01:00:03 Darchrai dbus-daemon[442]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.17' (uid=971 pid=828 comm="/usr/lib/webkit2gtk-4.0/WebKitWebProcess 11 24")
Apr 17 01:00:03 Darchrai systemd[1]: Starting RealtimeKit Scheduling Policy Service...
Apr 17 01:00:03 Darchrai dbus-daemon[442]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1'
Apr 17 01:00:03 Darchrai systemd[1]: Started RealtimeKit Scheduling Policy Service.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Successfully called chroot.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Successfully dropped privileges.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Successfully limited resources.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Canary thread running.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Running.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Watchdog thread running.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Supervising 0 threads of 0 processes of 0 users.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Successfully made thread 850 of process 828 owned by '971' RT at priority 5.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Supervising 1 threads of 1 processes of 1 users.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Supervising 1 threads of 1 processes of 1 users.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Successfully made thread 872 of process 828 owned by '971' RT at priority 5.
Apr 17 01:00:03 Darchrai rtkit-daemon[873]: Supervising 2 threads of 1 processes of 1 users.
Apr 17 01:00:03 Darchrai systemd[1]: systemd-rfkill.service: Deactivated successfully.

And shutdown log :

Apr 17 00:59:30 Darchrai systemd[1]: Stopping Wireless service...
Apr 17 00:59:30 Darchrai systemd[1]: dbus.service: Deactivated successfully.
Apr 17 00:59:30 Darchrai dhcpcd[458]: enp0s13f0u1u2u1: removing interface
Apr 17 00:59:30 Darchrai iwd[461]: Removing scan context for wdev 2
Apr 17 00:59:30 Darchrai kernel: wlan0: deauthenticating from 98:42:65:2d:38:08 by local choice (Reason: 3=DEAUTH_LEAVING)
Apr 17 00:59:30 Darchrai systemd[1]: Stopped D-Bus System Message Bus.
Apr 17 00:59:30 Darchrai iwd[461]: Terminate
Apr 17 00:59:30 Darchrai systemd[1]: dhcpcd.service: Deactivated successfully.
Apr 17 00:59:30 Darchrai systemd[1]: Stopped dhcpcd on all interfaces.
Apr 17 00:59:31 Darchrai acpid[450]: exiting
Apr 17 00:59:31 Darchrai systemd[1]: acpid.service: Deactivated successfully.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped ACPI event daemon.
Apr 17 00:59:31 Darchrai iwd[461]: Removing scan context for wdev 3
Apr 17 00:59:31 Darchrai systemd[1]: iwd.service: Deactivated successfully.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped Wireless service.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped target Basic System.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped target Path Units.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped target Slice Units.
Apr 17 00:59:31 Darchrai systemd[1]: Removed slice User and Session Slice.
Apr 17 00:59:31 Darchrai systemd[1]: user.slice: Consumed 4.802s CPU time.
Apr 17 00:59:31 Darchrai systemd[1]: Stopped target Socket Units.
Apr 17 00:59:31 Darchrai systemd[1]: dbus.socket: Deactivated successfully.
.....
.....
Apr 17 00:59:32 Darchrai systemd[1]: systemd-reboot.service: Deactivated successfully.
Apr 17 00:59:33 Darchrai systemd[1]: Finished System Reboot.
Apr 17 00:59:33 Darchrai systemd[1]: Reached target System Reboot.
Apr 17 00:59:33 Darchrai systemd[1]: Shutting down.
Apr 17 00:59:33 Darchrai systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog0
Apr 17 00:59:33 Darchrai systemd[1]: Watchdog running with a timeout of 10min.
Apr 17 00:59:33 Darchrai kernel: watchdog: watchdog0: watchdog did not stop!
Apr 17 00:59:33 Darchrai systemd-shutdown[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog0
Apr 17 00:59:33 Darchrai systemd-shutdown[1]: Watchdog running with a timeout of 10min.
Apr 17 00:59:33 Darchrai systemd-shutdown[1]: Syncing filesystems and block devices.
Apr 17 00:59:33 Darchrai systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Apr 17 00:59:33 Darchrai systemd-journald[225]: Received SIGTERM from PID 1 (systemd-shutdow).
Apr 17 00:59:33 Darchrai systemd-journald[225]: Journal stopped
-- Boot 16d88c940a99447c8e8e4df79a0dff9d --

I will put the topic as solved and not erase it because it could be useful for anyone else.
I will reopen it if the problem occurs again.

TL;DR
I wasnt able to boot fast or shutdown without force shutdowning watchdog when my laptop was connected to my monitor so I just waited 5 minutes after watchdog did not stop shutdown prompt and eventually it works now.
I think the problem was that I never did let the post watchdog activities run and I force shutdowned every time it took more than 30 secondes because to me it was stuck.
Anyway, thanks for reading.

Edit :
2 reboots after posting this, the problem happened again.
I used the same fix.

Last edited by Rupioe (2023-04-16 23:21:45)