Re: Delay at boot - network
Hi Brian,
> systemd is waiting for some script to complete. It doesn't just carry on
> immediately in case something gets broken.
>
> Boot with 'systemd.log_level=debug' and examine 'journalctl --alb' closely.
I did, as you told, and strangely, at the moment this behaviour disappered.
However, it may be related to a new behaviour: After booting the system up,
wlan is not available. I have to do:
rmmod ath5k
modprobe ath5k
then start wicd and connection works.
This is part of the output of the journal, maybe it helps.
......
......
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/21
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=28
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 kernel: ieee80211 phy0: Selected rate control
algorithm 'minstrel_ht'
Mai 25 20:10:02 protheus2 kernel: ath5k: phy0: Atheros AR2425 chip found (MAC:
0xe2, PHY: 0x70)
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/83
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=30
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/83
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=29
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/45
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/45
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=30
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/92
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=32
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/92
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=31
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/55
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=33
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/55
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=32
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1
interface=org.freedesktop.systemd1.Manager member=JobNew cookie=34
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1
interface=org.freedesktop.systemd1.Manager member=JobNew cookie=33
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/16
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=35
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/16
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=34
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/57
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=36
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/57
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=35
reply_cookie=0 error=n/a
.....
.....
.....
Mai 25 20:10:02 protheus2 systemd[1]: dev-sda5.device: Merged into installed
job dev-sda5.device/start as 93
Mai 25 20:10:02 protheus2 systemd[1]: laptop-mode.service: Enqueued job
laptop-mode.service/start as 183
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=method_return
sender=n/a destination=n/a object=n/a interface=n/a member=n/a cookie=46
reply_cookie=1 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/93
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=47
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/93
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=47
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/4
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=48
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/4
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=48
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/84
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=49
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/84
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=49
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/30
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=50
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/30
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=50
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/45
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=51
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/45
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=51
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/307
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=52
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/307
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=52
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/92
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=53
reply_cookie=0 error=n/a
Mai 25 20:10:02 protheus2 systemd[1]: Sent message type=signal sender=n/a
destination=n/a object=/org/freedesktop/systemd1/job/92 interface=org.
.....
.....
....
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Sent message type=method_call
sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus
interface=org.freedesktop.DBus member=GetConnectionUnixProcessID cookie=11
reply_cookie=0 error=n/a
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> rfkill1: found WiFi
radio killswitch (at
/sys/devices/pci0000:00/0000:00:0d.0/0000:05:00.0/ieee80211/phy0/rfkill1)
(driver ath5k)
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Got message type=method_return
sender=org.freedesktop.DBus destination=:1.0 object=n/a interface=n/a
member=n/a cookie=10 reply_cookie=11 error=n/a
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> rfkill0: found WiFi
radio killswitch (at /sys/devices/platform/acer-wmi/rfkill/rfkill0) (platform
driver acer-wmi)
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Sent message type=method_call
sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus
interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=12
reply_cookie=0 error=n/a
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Got message type=method_return
sender=org.freedesktop.DBus destination=:1.0 object=n/a interface=n/a
member=n/a cookie=11 reply_cookie=12 error=n/a
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Inhibitor NetworkManager
(NetworkManager muss Netzwerke abschalten) pid=1502 uid=0 mode=delay started.
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Sent message type=signal
sender=n/a destination=n/a object=/org/freedesktop/login1
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=13
reply_cookie=0 error=n/a
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Sent message
type=method_return sender=n/a destination=:1.6 object=n/a interface=n/a
member=n/a cookie=14 reply_cookie=14 error=n/a
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> WiFi hardware radio set
enabled
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> WWAN hardware radio set
enabled
Mai 25 20:10:25 protheus2 systemd-rfkill[1178]: All events read and idle,
exiting.
Mai 25 20:10:25 protheus2 systemd-logind[1549]: Got message type=signal
sender=:1.1 destination=n/a
object=/org/freedesktop/systemd1/unit/systemd_2drfkill_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=126
reply_cookie=0 error=n/a
.....
.....
.....
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> Loaded device plugin:
/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-wifi.so
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> Loaded device plugin:
/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-adsl.so
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> Loaded device plugin:
/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-bluetooth.so
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> Loaded device plugin:
/usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-wwan.so
Mai 25 20:10:25 protheus2 dbus[1585]: [system] Activating service
name='org.freedesktop.ModemManager' (using servicehelper)
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> WiFi enabled by radio
killswitch; enabled by state file
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> WWAN enabled by radio
killswitch; enabled by state file
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> WiMAX enabled by radio
killswitch; enabled by state file
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> Networking is enabled
by state file
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (lo): link connected
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (lo): carrier is ON
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (lo): new Generic
device (driver: 'unknown' ifindex: 1)
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (lo): exported as
/org/freedesktop/NetworkManager/Devices/0
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (eth0): carrier is OFF
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (eth0): new Ethernet
device (driver: 'forcedeth' ifindex: 2)
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (eth0): exported as
/org/freedesktop/NetworkManager/Devices/1
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): using nl80211
for WiFi device control
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): driver
supports Access Point (AP) mode
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): new 802.11
WiFi device (driver: 'ath5k' ifindex: 3)
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): exported as
/org/freedesktop/NetworkManager/Devices/2
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): device state
change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Mai 25 20:10:25 protheus2 NetworkManager[1502]: <info> (wlan0): preparing
device
Mai 25 20:10:25 protheus2 systemd[1]: Started Network Manager.
Mai 25 20:10:25 protheus2 dnsmasq[2398]: lese /var/run/dnsmasq/resolv.conf
Mai 25 20:10:26 protheus2 wpa_supplicant[2177]: wlan0: CTRL-EVENT-DISCONNECTED
bssid=00:1a:4f:21:8e:32 reason=0
Mai 25 20:10:26 protheus2 NetworkManager[1502]: <info> (wlan0): reset MAC
address to 00:1D:D9:4C:88:10
.....
....
.....
............................................................
And lots of more errors, the whole file is 1,4MB big. I am wondering, what
Network-Manager has to do with it, it is not installed!
At last. I see these, what appears a dozen times:
Mai 25 20:10:29 protheus2 NetworkManager[1502]: <error> [1464199829.950194]
[supplicant-manager/nm-supplicant-interface.c:856] interface_add_cb():
(wlan0): error adding interface: wpa_supplicant couldn't grab this interface.
Mai 25 20:10:29 protheus2 NetworkManager[1502]: <info> (wlan0): supplicant
interface state: starting -> down
Mai 25 20:10:29 protheus2 wpa_supplicant[2671]: ctrl_iface exists and seems to
be in use - cannot override it
Mai 25 20:10:29 protheus2 wpa_supplicant[2671]: Delete
'/run/wpa_supplicant/wlan0' manually if it is not used anymore
Mai 25 20:10:29 protheus2 wpa_supplicant[2671]: Failed to initialize control
interface '/run/wpa_supplicant'.
You may have another
wpa_supplicant process already running or the file was
left by an unclean termination
of wpa_supplicant in which case you will need
to manually remove this file
before starting wpa_supplicant again.
Mai 25 20:10:30 protheus2 NetworkManager[1502]: <error> [1464199830.056549]
[supplicant-manager/nm-supplicant-interface.c:856] interface_add_cb():
(wlan0): error adding interface: wpa_supplicant couldn't grab this interface.
Mai 25 20:10:30 protheus2 NetworkManager[1502]: <info> (wlan0): supplicant
interface state: starting -> down
Mai 25 20:10:30 protheus2 wpa_supplicant[2671]: ctrl_iface exists and seems to
be in use - cannot override it
Mai 25 20:10:30 protheus2 wpa_supplicant[2671]: Delete
'/run/wpa_supplicant/wlan0' manually if it is not used anymore
Mai 25 20:10:30 protheus2 wpa_supplicant[2671]: Failed to initialize control
interface '/run/wpa_supplicant'.
You may have another
wpa_supplicant process already running or the file was
left by an unclean termination
of wpa_supplicant in which case you will need
to manually remove this file
before starting wpa_supplicant again.
.....
....
I have to onspect this, too. Please do nothing at the moment, I have to check
several things, and then I will send message again.
Thanks for the hints, I will come back.
Best
Hans
Reply to: