search

systemd / systemd

The systemd System and Service Manager
https://systemd.io
GNU General Public License v2.0
12.81k stars 3.68k forks source link

Setting systemd.log_level=debug breaks system boot #31921

Open thx1111 opened 3 months ago

thx1111 commented 3 months ago

systemd version the issue has been seen with

255.4-2

Used distribution

Arch

Linux kernel version used

6.8.1.arch1-1

CPU architectures issue was seen on

i686

Component

systemd

Expected behaviour you didn't see

Normal system boot with systemd debug messages

Unexpected behaviour you saw

Of course, "debug" is not of much use when it causes the system to fail on boot. Is there some "trick" to using systemd debug? Does it only work in "emergency mode"? Or, systemd debug is "broken"?

Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: start operation timed out. Terminating.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Changed start -> stop-sigterm
Mar 23 10:38:18 topaz systemd[1]: Received SIGCHLD from PID 327 (systemd-modules).
Mar 23 10:38:18 topaz systemd[1]: Child 327 (systemd-modules) died (code=killed, status=15/TERM)
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Child 327 belongs to systemd-modules-load.service.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Main process exited, code=killed, status=15/TERM
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Failed with result 'timeout'.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Service will not restart (restart setting)
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Changed stop-sigterm -> failed
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Job 66 systemd-modules-load.service/start finished, result=failed
Mar 23 10:38:18 topaz systemd[1]: Failed to start Load Kernel Modules.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Unit entered failed state.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Consumed 72ms CPU time.
Mar 23 10:38:18 topaz systemd[1]: systemd-modules-load.service: Releasing resources...
Mar 23 10:38:18 topaz systemd[1]: dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8705fb1757bc.device: Job dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8
705fb1757bc.device/start timed out.
Mar 23 10:38:18 topaz systemd[1]: dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8705fb1757bc.device: Job 79 dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8705fb1757bc.device/start finished, result=timeout
Mar 23 10:38:18 topaz systemd[1]: Timed out waiting for device /dev/disk/by-uuid/ef985b6a-511b-41a2-a0e3-8705fb1757bc.
Mar 23 10:38:18 topaz systemd[1]: dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8705fb1757bc.swap: Job 78 dev-disk-by\x2duuid-ef985b6a\x2d511b\x2d41a2\x2da0e3\x2d8705fb1757bc.swap/start finished, result=dependency
Mar 23 10:38:18 topaz systemd[1]: Dependency failed for /dev/disk/by-uuid/ef985b6a-511b-41a2-a0e3-8705fb1757bc.
...
Mar 23 10:38:18 topaz systemd[1]: Dependency failed for Local File Systems.
Mar 23 10:38:18 topaz systemd[1]: local-fs.target: Job local-fs.target/start failed with result 'dependency'.
Mar 23 10:38:18 topaz systemd[1]: local-fs.target: Triggering OnFailure= dependencies.
Mar 23 10:38:18 topaz systemd[1]: emergency.target: Trying to enqueue job emergency.target/start/replace-irreversibly
...
Mar 23 10:38:18 topaz systemd[1]: emergency.target: Enqueued job emergency.target/start as 173
Mar 23 10:38:18 topaz systemd[1]: local-fs.target: Triggering OnFailure= dependencies done (1 job).
...
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Child 344 belongs to emergency.service.
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Control process exited, code=exited, status=0/SUCCESS (success)
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Got final SIGCHLD for state start-pre.
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Will spawn child (service_enter_start): /usr/lib/systemd/systemd-sulogin-shell
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Passing 0 fds to service
Mar 23 10:38:18 topaz systemd[1]: emergency.service: About to execute: /usr/lib/systemd/systemd-sulogin-shell emergency
Mar 23 10:38:18 topaz systemd[1]: Serializing sd-executor-state to memfd.
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Forked /usr/lib/systemd/systemd-sulogin-shell as 347
Mar 23 10:38:18 topaz systemd[1]: Closing set fd 29 (socket:[3224])
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Changed start-pre -> running
Mar 23 10:38:18 topaz systemd[1]: emergency.service: Control group is empty.
...

Steps to reproduce the problem

system boot with systemd.log_level=debug

Additional program output to the terminal or log subsystem illustrating the issue

No response

poettering commented 3 months ago

works fine here.

the truncated logs you provide suggest that kmod loading times out, i.e. that some driver you load via /etc/modules-load.d/ hangs during initialization, and systemd just detects this.

poettering commented 3 months ago

in order to determine the actual cause, consider pasting the full debug logs around systemd-modules-load.service and the kernel's own log output.

Or just comment the drivers listed for explicit loading.

typically closed source nvidia garbage can trigger something like this.