Re: Debugging 20s pause in boot time in rawhide

["Jason D. Clinton" <me@xxxxxxxxxxxxxxxx>]

On Mon, Jan 17, 2011 at 15:09, Lennart Poettering <mzerqung@xxxxxxxxxxx> wrote:

> getting default adapter: Activation of org.bluez timed out

Smells like a bluez problem. Note sure what is going on there.

It might be a good idea to pass systemd.log_level=debug and
systemd.log_target=kmsg on the kernel cmdline and then inspect "dmesg"
after boot to figure out what is going on.

I tried this here is some interesting output during boot:

Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475805] systemd[1]: sys-devices-pci0000:00-0000:00:1a.1-usb4-4\x2d2-4\x2d2:1.0-bluetooth-hci0.device changed dead -> plugged
Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475823] systemd[1]: Trying to enqueue job bluetooth.target/start/fail
Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475840] systemd[1]: Installed new job bluetooth.target/start as 146
Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475853] systemd[1]: Enqueued job bluetooth.target/start as 146
Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475863] systemd[1]: bluetooth.target changed dead -> active
Jan 17 20:56:22 jclinton-laptop kernel: [ÂÂ 19.475871] systemd[1]: Job bluetooth.target/start finished, success=yes

So the bluetooth.target is now satisfied. Later on after 20s pause:

Jan 17 20:56:47 jclinton-laptop NetworkManager[1214]: <warn> bluez error getting default adapter: Activation of org.bluez timed out

And then 4 seconds later when pulseaudio is starting, it triggers the D-Bus Activation and then everything is fine.

Jan 17 20:56:51 jclinton-laptop pulseaudio[1721]: module-alsa-card.c: Failed to find a working profile.
Jan 17 20:56:51 jclinton-laptop pulseaudio[1721]: module.c: Failed to load module "module-alsa-card" (argument: "device_id="29" name="platform-thinkpad_acpi" card_name="alsa_c
ard.platform-thinkpad_acpi" tsched=yes ignore_dB=no card_properties="module-udev-detect.discovered=1""): initialization failed.
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.825082] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.826717] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Activator.ActivationRequest() on /org/freedesktop/DBus
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.826726] systemd[1]: Got D-Bus activation request for bluetooth.service
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.827703] systemd[1]: Trying to enqueue job bluetooth.service/start/replace
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.827929] systemd[1]: Installed new job bluetooth.service/start as 658
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.827936] systemd[1]: Enqueued job bluetooth.service/start as 658
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.827980] systemd[1]: About to execute: /usr/sbin/bluetoothd -n
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838118] systemd[1]: Forked /usr/sbin/bluetoothd as 1727
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838223] systemd[1]: bluetooth.service changed dead -> start
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838255] systemd[1]: Incoming traffic on systemd-logger.socket
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838290] systemd[1]: Trying to enqueue job systemd-logger.service/start/replace
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838315] systemd[1]: Installed new job systemd-logger.service/start as 759
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838325] systemd[1]: Enqueued job systemd-logger.service/start as 759
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838350] systemd[1]: systemd-logger.socket changed listening -> running
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.838398] systemd[1]: About to execute: /lib/systemd/systemd-logger
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.850099] systemd[1]: Forked /lib/systemd/systemd-logger as 1728
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.850302] systemd[1]: systemd-logger.service changed dead -> running
Jan 17 20:56:51 jclinton-laptop kernel: [ÂÂ 60.850323] systemd[1]: Job systemd-logger.service/start finished, success=yes
Jan 17 20:56:51 jclinton-laptop bluetoothd[1727]: Bluetooth deamon 4.85

My uneducated guess is that for some reason bluez is ordered after NM
but NM wants to use bluez and hence we have a deadlock which is resolved
via the timeout you see. On my own machine I do not see that behaviour
however, which makes this very suspicious.

I did an rpm -Va and I have no unit files which are not verified so it appears that I am starting Networkmanager before pulseaudio instead of with/after it. Perhaps my system has a unit file which requires network.target but comes before pulseaudio?

I tried to generate a dot file of the dep. graph but dot in rawhide infinite loops on the output.

This interesting though:
$ ls -l /etc/systemd/system/dbus-org.freedesktop.NetworkManager.service
lrwxrwxrwx. 1 root root 42 Oct 22 13:33 /etc/systemd/system/dbus-org.freedesktop.NetworkManager.service -> /lib/systemd/system/NetworkManager.service

-- 
devel mailing list
devel@xxxxxxxxxxxxxxxxxxxxxxx
https://admin.fedoraproject.org/mailman/listinfo/devel