[solved] A start job is running ...

[whiizy]

... for Connection service.

Endlich wird mir auch mal die Freude zuteil, in systemd zu debuggen, hosianna! Seit wenigen Tagen legt der Boot-Vorgang eine Pause von 1 min 32 mit obiger Konsolenmeldung ein und setzt dann ohne Problem fort. Damit ist der Beschleunigungsgewinn durch systemd momentan mehr als egalisiert

Wie an dem Timer und animierten roten Sternchen in der Konsole zu sehen ist, wird ein voller Time-Out von 1m32s abgewartet. Ich interpretiere es so, daß mein connection-manager connman an dieser Stelle schon einen Netzwerkkonnekt erwartet, der an dieser Stelle aber noch nicht erfolgt ist. Wenn das so ist, wäre das m.E. auch etwas zu früh, denn die automatische WLAN-Verbindung des Laptop reicht eigentlich mit dem Start des Desktop (LXQt unter Sid mit cmst als Network-Applet).

Mit "journalctl -b" habe ich die zentralen Stellen des connman mal herausgesucht. Auch am Zeitstempel kann man den Timeout ab 17:54:45 gut erkennen:

Code: Alles auswählen

Aug 17 17:54:45 amy systemd[1]: Started LSB: daemon to balance interrupts for SMP systems.
Aug 17 17:54:45 amy systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:intel_backlight.
Aug 17 17:56:15 amy systemd[1]: connman.service: Start operation timed out. Terminating.
Aug 17 17:56:15 amy systemd[1]: Failed to start Connection service.
Aug 17 17:56:15 amy systemd[1]: Dependency failed for Wait for network to be configured by ConnMan.
Aug 17 17:56:15 amy systemd[1]: connman-wait-online.service: Job connman-wait-online.service/start failed with result 'dependency'.
Aug 17 17:56:15 amy systemd[1]: connman.service: Unit entered failed state.
Aug 17 17:56:15 amy systemd[1]: connman.service: Failed with result 'timeout'.
Aug 17 17:56:15 amy systemd[1]: Reached target Network.
Aug 17 17:56:15 amy systemd[1]: Starting OpenBSD Secure Shell server...
Aug 17 17:56:15 amy systemd[1]: Starting Permit User Sessions...
Aug 17 17:56:15 amy systemd[1]: Reached target Network is Online.
[...]
Aug 17 17:56:15 amy systemd[1]: connman.service: Service hold-off time over, scheduling restart.
Aug 17 17:56:15 amy systemd[1]: Stopped Connection service.
Aug 17 17:56:15 amy systemd[1]: Starting Connection service...
[...]
Aug 17 17:56:19 amy systemd[1]: Started Connection service.
Aug 17 17:56:19 amy systemd[1]: Startup finished in 3.956s (kernel) + 1min 37.036s (userspace) = 1min 40.992s.
Aug 17 17:56:19 amy connmand[1791]: Connection Manager version 1.32
Aug 17 17:56:19 amy connmand[1791]: Checking loopback interface settings
[...]

Demnach sieht es für mich so aus, als wenn systemd im weiteren Verlauf des Boots dann aber zufrieden ist und den Connection service starten kann, nochmals verkürzte Darstellung von oben:

Code: Alles auswählen

Aug 17 17:56:19 amy systemd[1]: Started Connection service.
Aug 17 17:56:19 amy systemd[1]: Startup finished in 3.956s (kernel) + 1min 37.036s (userspace) = 1min 40.992s

Systemd resümiert dort, daß der Kernel nur knapp 4 s gebraucht hat, aber 1 min 37 s im userspace vergeigt wurden.

Mein Desktop läuft am Ende übrigens ohne Beanstandung und hat auch seine WLAN-Verbindung erfolgreich automatisch aufgebaut. Meine Gewöhnung an systemctl ist noch sehr beschränkt, aber für mich sieht der Status des Connection service am Ende eigentlich auch ok aus:

Code: Alles auswählen

# systemctl status connman.service 
● connman.service - Connection service
   Loaded: loaded (/lib/systemd/system/connman.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2016-08-17 17:56:19 CEST; 34min ago
 Main PID: 1791 (connmand)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/connman.service
           └─1791 /usr/sbin/connmand -n
[...]

Für mich schwer zu beurteilen, ob der nervige Time-Out beim Boot ein neuer Bug oder Feature von systemd und connman darstellt (bis vor wenigen Tagen/Updates trat es noch nicht auf ). Ich würde diese Bremse auch gerne irgendwie abstellen, bis das geklärt ist, aber bisher versklavt mich systemd leider zu dieser Zwangspause.

Gruß

[reox]

Ich schieß mal ins blaue: aber bei mir am laptop hab ich auch manchmal probleme mit connman weil die Gruppe "connman" nicht existierte und dann irgendwas mit dbus nicht funktioniert hat. Ich hab noch nicht ganz herausgefunden was da mit dbus los ist, weil manchmal cmst nicht starten will und dann aber trotzdem alles da ist und connman komische sachen sagt wie er kann nicht verbinden und die verbindung trotzdem durchgeführt wird...
Evt ist das bei dir auch das problem?

[whiizy]

Also bei mir läuft connman 1.32-0.1 als root und eine group "connman" existiert bei meinem Debian Sid nicht:

Code: Alles auswählen

# ps aux| grep connman
root      1789  0.0  0.3  55748  5960 ?        Ss   19:13   0:00 /usr/sbin/connmand -n

Ich kann mir eigentlich nicht so recht vorstellen, wozu da eine spezielle group nötig sein sollte, zumal der connman.service ganz am Ende des Boots ja auch immer erfolgreich läuft. Cmst als Frontend auf dem Desktop verhält sich hier eigentlich recht vorhersehbar. Danke schonmal für den Ansatz, reox.

[reox]

du hast recht, ich hab nochmal das dbus file angeschaut und dort rennt es auch unter root. Ok dann hab ich vllt ein anderes problem als du

[whiizy]

Also zählt dbus wohl auch noch zum Kreis der Verdächtigen, danke reox. Das wären dann neben connman und systemd schon drei.

Ich steige da derzeit nicht durch, worauf connman.service eigentlich wartet, habe aber jetzt erstmal einen Workaround für mich gefunden. Den Timout von 1min 32 (genauer 90 s) habe ich in der /etc/systemd/system.conf skrupellos so weit wie möglich verkürzt (auf 1 s):

Code: Alles auswählen

#DefaultTimeoutStartSec=90s
DefaultTimeoutStartSec=1s

Weniger geht nicht, denn 0 s ist gleichbedeutend mit "no limit". Also warten bis zum Sankt Nimmerleinstag. Ich habe das testweise mal bis 5 min timen lassen, aber auch dann kommt connman nicht von selbst in die Pötte. Zum Glück kommt man aus der Warteschleife aber mit mehrfachem Drücken von Ctrl-C immer heraus.

Daß ein Timeout von nur 1 s ausreicht, um den connman erfolgreich durchstarten zu lassen (IPv4 und IPv6 gehen), deutet auf die Unnötigkeit dieser Warteschleife hin (die ja auch bis vor einigen Tagen nie auftrat). Ich gehe bis auf Weiteres von einem neuen Bug in Debian Stretch/Sid aus.

Gruß

[malzeit]

Code: Alles auswählen

#DefaultTimeoutStartSec=90s
DefaultTimeoutStartSec=1s

Bei mir das gleiche mit 2 SID Rechnern; erst läuft alles wie geschmiert (Tage, Wochen, Monate) nach einer Neuinstallation und dann kommt, nach irgendeinen beliebigen Update bei jedem Starten und Stoppen ein "a start (oder stop) job is running for network manager"

In meinem Falle benutze ich den network-manager

Und: DANKE für obige Info... genau das was ich suchte, jetzt booten meine SIDs wieder so schnell wie zuvor ...und mein WLan klappt immer noch. Habe allerdings den Timeout beim Stoppen auf 10 Sekunden gesetzt (zwecks cache-Leerung), da es auch auftaucht für "remov...device", was ich meiner externen USB-Platte zurechne!

[reox]

wird connman eigentlich noch irgendwie weiter entwickelt? Ich hatte mit meiner Intel WLAN Karte öfter Probleme mit network-manager und wicd (zB kein Netz nach Hibernate) und mit connman sind die alle weg.
Leider scheint mir, dass manche Dinge gar nicht gut klappen - zB Konfiguration. Nachdem ich ein paar Dinge die sogar in der manpage stehen eingebaut hatte, startete der gar nicht mehr.
Das wäre übrigens auch noch etwas das du schauen kannst. Hast du irgendwelche config files angelegt?

[whiizy]

@malzeit
Einerseits gut zu hören, daß unerwünschte Startverzögerungen auch auf anderen Debian/Sids schonmal auftreten, danke. Andererseits sind connman und network-manager zwei unterschiedliche Pakete und somit können es auch zwei Baustellen sein (selbst wenn beide ungefähr dieselbe Aufgabe erfüllen).

@reox
connman sieht mir recht lebendig aus, das letzte Update auf der Entwicklerseite https://01.org/connman ist von diesem Monat. Da Intel anscheinend mitmischt und connection-manager für embedded devices wichtig sind, wird das Zusammenspiel mit systemd hoffentlich noch etwas verbessert werden.

Ich habe connman nicht über irgendwelche config-files eingerichtet (Du meinst vermutlich eine selbst zu erstellende main.conf, die gelegentlich mal irgendwo auftaucht). Ich steuere die Netzwerkverbindungen auf dem Netbook einzig über das Frontend "QT GUI for Connman with system tray icon" namens cmst.

Letztlich landen die Optionen alle in files für systemd. Was mich in diesem Zusammenhang nur etwas nervt, daß es unter systemd offenbar dutzende elaborierte Befehle gibt, um etwas über die ganzen Objekte zu erfahren - aber am Ende (Stunden später) ist immer noch nicht richtig transparent, was dem connman.service denn nun zu seinem Glück fehlt. Oder ob es schlicht ein Bug oder PEBKAC ist.

[whiizy]

Wie gerufen ist gestern ein neuer Kommentar in einem ähnlichen Bugreport 827296 zu connman eingegangen!

Demnach soll eine neue libgnutls30 zu timeouts führen können!!
Ich habe daraufhin mal meine Update-Historie durchforstet und tatsächlich passt das Update-Datum dieser lib recht gut zum Auftreten meines Problems:

Code: Alles auswählen

zless /var/log/apt/term.log.1.gz
Log started: 2016-08-15  23:39:48
Unpacking libgnutls30:amd64 (3.5.3-2) over (3.5.2-2) ...

Zum Glück liegen ältere Versionen dieser lib noch in meinem apt-archiv ...

Code: Alles auswählen

/var/cache/apt/archives# ls -la libgnu*
-rw-r--r-- 1 root root 791028 Apr 26 21:26 libgnutls30_3.4.11-4_amd64.deb
-rw-r--r-- 1 root root 807932 May 21 09:27 libgnutls30_3.4.12-1_amd64.deb
-rw-r--r-- 1 root root 807930 May 28 20:17 libgnutls30_3.4.12-2_amd64.deb
-rw-r--r-- 1 root root 810592 Jun  6 22:16 libgnutls30_3.4.13-1_amd64.deb
-rw-r--r-- 1 root root 811404 Jul  9 15:16 libgnutls30_3.4.14-1_amd64.deb
-rw-r--r-- 1 root root 789108 Jul 27 20:13 libgnutls30_3.5.2-2_amd64.deb
-rw-r--r-- 1 root root 800326 Aug 15 15:46 libgnutls30_3.5.3-2_amd64.deb

... so daß ich ein Downgrade auf den Vorgänger probieren konnte:

Code: Alles auswählen

dpkg -i /var/cache/apt/archives/libgnutls30_3.5.2-2_amd64.deb

Und was soll ich sagen, danach startet connman doch tatsächlich wieder verzögerungsfrei durch:

Code: Alles auswählen

 journalctl -u connman
-- Logs begin at Tue 2016-08-23 09:52:15 CEST, end at Tue 2016-08-23 09:53:15 CEST. --
Aug 23 09:52:18 amy systemd[1]: Starting Connection service...
Aug 23 09:52:18 amy systemd[1]: Started Connection service.
Aug 23 09:52:18 amy connmand[1751]: Connection Manager version 1.32
Aug 23 09:52:18 amy connmand[1751]: Checking loopback interface settings
[...]

Zum Vergleich, vorher sah man den ominösen 90s-Timeout an derselben Stelle:

Code: Alles auswählen

journalctl -u connman
-- Logs begin at Tue 2016-08-23 09:18:54 CEST, end at Tue 2016-08-23 09:21:17 CEST. --
Aug 23 09:18:55 amy systemd[1]: Starting Connection service...
Aug 23 09:20:25 amy systemd[1]: connman.service: Start operation timed out. Terminating.
Aug 23 09:20:25 amy systemd[1]: Failed to start Connection service.
Aug 23 09:20:25 amy systemd[1]: connman.service: Unit entered failed state.
Aug 23 09:20:25 amy systemd[1]: connman.service: Failed with result 'timeout'.
Aug 23 09:20:25 amy systemd[1]: connman.service: Service hold-off time over, scheduling restart.
Aug 23 09:20:25 amy systemd[1]: Stopped Connection service.
Aug 23 09:20:25 amy systemd[1]: Starting Connection service...
Aug 23 09:20:36 amy systemd[1]: Started Connection service.
Aug 23 09:20:36 amy connmand[1758]: Connection Manager version 1.32
Aug 23 09:20:36 amy connmand[1758]: Checking loopback interface settings
[...]

Auf den Zusammenhang mit dieser sicherheitskritischen lib wäre ich nie im Leben gekommen und staune, wie der Bugreporter es herausgefunden hat. Chapeau!

Jetzt ist ein downgrade der libgnutls30 natürlich keine dauerhafte Lösung und ich werde sie auch gleich wieder updaten. Aber wenigstens besteht jetzt die Chance, daß die Pakete innerhalb der Distribution wieder gefixed werden.

[KP97]

Nur am Rande:

Zum Glück liegen ältere Versionen dieser lib noch in meinem apt-archiv ...

Dafür ist das Debian Archiv da, mit allen Paketen, die es mal in den Repos gab:
http://snapshot.debian.org/
Deshalb brauchst Du auch nach dem Installieren keine Pakete im apt-cache vorzuhalten, damit verschenkt man nur unnötig Platz.

[whiizy]

http://snapshot.debian.org/

Danke für den sehr nützlichen Tip, hatte ich nur noch im Hinterkopf, daß man das wohl irgendwo findet. -- Mich beschleicht bei der eingegrenzten Ursache übrigens etwas Unbehagen. Wie mir im syslog vorher schonmal aufgefallen war, telefoniert connmand anscheinend erstmal nach Hause, sobald eine IP bezogen wurde. Zumindest wird kurzzeitig eine Hostroute zu 82.165.8.211 (ipv4.connman.net) auf- und gleich wieder abgebaut:

Code: Alles auswählen

[...]
Aug 23 15:50:50 amy connmand[1799]: wlp2s0 {add} address 192.168.1.101/24 label wlp2s0 family 2
Aug 23 15:50:50 amy connmand[1799]: wlp2s0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
Aug 23 15:50:50 amy connmand[1799]: wlp2s0 {add} route 192.168.1.1 gw 0.0.0.0 scope 253 <LINK>
Aug 23 15:50:50 amy connmand[1799]: wlp2s0 {add} route 0.0.0.0 gw 192.168.1.1 scope 0 <UNIVERSE>
Aug 23 15:50:50 amy wpa_supplicant[1801]: wlp2s0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-77 noise=-94 txrate=6000
Aug 23 15:50:51 amy connmand[1799]: wlp2s0 {add} route 82.165.8.211 gw 192.168.1.1 scope 0 <UNIVERSE>
Aug 23 15:50:51 amy connmand[1799]: wlp2s0 {del} route 82.165.8.211 gw 192.168.1.1 scope 0 <UNIVERSE>
[...]

Das wird in den Sourcen zwar auch offen erwähnt, aber jetzt frage ich mich, wie das in Verbindung mit der genannten GnuTLS lib zu bringen ist. Gemäß der README http://git.kernel.org/cgit/network/conn ... git/about/ wird GnuTLS hier für "WISPr hotspot logins" verwendet. Wartet connman vielleicht erfolglos bis zum TimeOut auf die Verbindung zu seinem Login-Portal im Internet, weil er zufällig gerade einen Bug im Zusammenspiel mit GnuTLS hat??

[whiizy]

Seit einem der letzten Updates in Debian Sid ist das Problem von connman und libgnutls30 wieder behoben.
Danke allen Beteiligten!

[swap7]

Also zählt dbus wohl auch noch zum Kreis der Verdächtigen, danke reox. Das wären dann neben connman und systemd schon drei.

Ich steige da derzeit nicht durch, worauf connman.service eigentlich wartet, habe aber jetzt erstmal einen Workaround für mich gefunden. Den Timout von 1min 32 (genauer 90 s) habe ich in der /etc/systemd/system.conf skrupellos so weit wie möglich verkürzt (auf 1 s):

Code: Alles auswählen

#DefaultTimeoutStartSec=90s
DefaultTimeoutStartSec=1s

Weniger geht nicht, denn 0 s ist gleichbedeutend mit "no limit". Also warten bis zum Sankt Nimmerleinstag. Ich habe das testweise mal bis 5 min timen lassen, aber auch dann kommt connman nicht von selbst in die Pötte. Zum Glück kommt man aus der Warteschleife aber mit mehrfachem Drücken von Ctrl-C immer heraus.

Daß ein Timeout von nur 1 s ausreicht, um den connman erfolgreich durchstarten zu lassen (IPv4 und IPv6 gehen), deutet auf die Unnötigkeit dieser Warteschleife hin (die ja auch bis vor einigen Tagen nie auftrat). Ich gehe bis auf Weiteres von einem neuen Bug in Debian Stretch/Sid aus.

Gruß

Hallo, gibt es inzwischen eine bessere Lösung?
Bei Debian Testing LXQT (aktuell 6. Sept. 2017) habe ich das 1:30 Minuten Problem immer noch.

Bei mir funktioniert der Workaround nicht.

Beste Grüße

swap7

[TomL]

Bei mir funktioniert der Workaround nicht.

Ich halte das auch für einen völlig falschen Weg. Diese "Start-Job-is-Running"-Meldung.... systemd ist hier nicht das Problem, sonden imho die Lösung. Ich habe dazu mal ein paar Fragen:
- Tritt das generell bei jedem Start auf?
- Oder gibt es Situation wo es auch fehlerfrei durchläuft?
- Gibt es dementsprechende dann andere Situationen, in denen der Fehler reproduzierbar auftritt?
- Wie unterscheiden sich diese Situationen?
- Betrifft das WLAN-Verbindungen?
- Nur WLAN, oder auch bei Patchkabel-Verbindungen?
- Ist es ein mobiles Gerät mit wechselnden WLAN-Netzen
- Oder ist es ein stationäres Gerät am immer gleichen Netz? ETH oder WLAN?
- Sind an diese Netzwerkverbindung auch Remote-Mounts in der fstab eingebunden?

[swap7]

Hallo,

das Problem tritt generell bein direkten ausschalten vom Desktop auf.

Logge ich mich aus und schalte den PC mit der Displaymanager Oberfläche aus, geht der Shutdown ohne 1:30 Warteminute.

Mit dem LXDE Desktop gibt es dies Problem nicht.

Beste Grüße

swap7

[TomL]

das Problem tritt generell bein direkten ausschalten vom Desktop auf

Der Betreff des Threads lautet "A start job is running", was auch zu Whiizy's späterer Anmerkung "Seit wenigen Tagen legt der Boot-Vorgang eine Pause von 1 min 32..." passt. Nun sprichst Du von "Beim Ausschalten". Das ist aber ne andere Baustelle, ziwschen Boot und Shutdown gibts ein paar kleine und unwesentliche Unterschiede. Also, worum geht es hier eigentlich? Und sorry... wenn Dir die Beantwortung meiner Fragen zu viel Arbeit macht, nimms mir bitte nicht übel, wenn mir dann die Problemlösung auch zu viel Arbeit macht. Im Trüben stochern, weil die notwendigen Infos nicht gegeben werden und eine konkrete Problembeschreibung für die Ursachensuche fehlt, ist einigermaßen unbebefriedigend und letztendlich Zeitverschwendung.

[swap7]

Hallo Thomas,

Du hast recht, ich werde einen extra Thread aufmachen.

Die Suchfunktion hatte mich hierher geführt.

Beste Grüße

swap7