Bug 16078 - Netzwerk wird während des Updates deaktiviert
Netzwerk wird während des Updates deaktiviert
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: Network
UCS 2.3
Other Linux
: P5 normal (vote)
: UCS 2.3
Assigned To: Arvid Requate
Daniel Hofmann
:
Depends on:
Blocks: 8994 14412
  Show dependency treegraph
 
Reported: 2009-10-23 14:06 CEST by Andre Fenske
Modified: 2009-12-21 08:49 CET (History)
1 user (show)

See Also:
What kind of report is it?: ---
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments
Anbei die Updater.log (1.16 MB, text/plain)
2009-10-23 14:07 CEST, Andre Fenske
Details
syslog vom update (14.11 KB, application/octet-stream)
2009-10-27 18:20 CET, Arvid Requate
Details
syslog.0 vom Update (201.19 KB, application/octet-stream)
2009-10-27 18:27 CET, Arvid Requate
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Andre Fenske univentionstaff 2009-10-23 14:06:35 CEST
Beim Update auf UCS 2.3-0 von UCS 2.2-0 (sec 0) wird recht spät das interface eth0 abgeschaltet. Dies führt dazu das einige Pakete nicht installiert werden können.

Beispielsweise wird das Paket univention-thin-client-x-base auf dem System in der Version aus 2.3-0 installiert, jedoch bleibt die Version in der Thin-Client Umgebung bei der aus 2.2-2 da in der Zwischenzeit das Netzwerk weg ist und apt das Paket nicht laden kann.
Comment 1 Andre Fenske univentionstaff 2009-10-23 14:07:40 CEST
Created attachment 1939 [details]
Anbei die Updater.log
Comment 2 Arvid Requate univentionstaff 2009-10-27 18:20:54 CET
Created attachment 1943 [details]
syslog vom update

Das könnte etwas mit NetworkManager und dbus zu tun haben.

In Tests verliert kurze Zeit (ein paar postinst später) nach dem Lauf von network-manager postinst das Interface eth0 seine IPv4 Adresse und wird wenig später ggf. auch ganz deaktiviert (nicht immer).

Am Ende des Syslogs sind auch Fehlermeldungen protokolliert, die nach dem Update-Versuch bei manuellem '/etc/init.d/network-manager restart' auftreten (dabei blieb das manuell aktivierte eth0 aber unverändert) und auf ein dbus Problem hinweisen. Folgende Versionen sind zu dem Zeitpunkt installiert:

ii  dbus                                         1.2.1-5.28.200909150210
ii  ifupdown                                     0.6.8.15.200909161109
ii  network-manager                              0.7.1-1.8.200910211709
Comment 3 Arvid Requate univentionstaff 2009-10-27 18:27:05 CET
Created attachment 1944 [details]
syslog.0 vom Update

Das hier angehängte syslog.0 war schon wegrotiert worden, enthält aber die Meldung bei der Installation von NetworkManager.
Comment 4 Arvid Requate univentionstaff 2009-10-28 19:12:00 CET
Es handelt sich hier ggf. um ein Timingproblem.

6 Zeilen aus dem Syslog direkt nach dem Start des NetworkManager während des Updates mit Anmerkungen, wo die Meldungen wahrscheinlich herkommen:
Interssant ist dabei der 5 Sekunden Aussetzer zwischen der dritten und der vierten Meldung und ein Code-Fragment das dazu passt:
===========================================================================
Oct 22 06:43:49 NetworkManager: <info>  Trying to start the supplicant...
Oct 22 06:43:49 NetworkManager: <info>  Trying to start the system settings daemon...

  probably called by src/nm-manager.c:initial_get_connections
  ( maybe calling query_connections )

Oct 22 06:43:49 NetworkManager: <info>  (eth0): carrier now ON (device state 1)

   This is from the function src/nm-device.c:nm_device_ethernet_carrier_on
   called by src/nm-device-ethernet.c:constructor
   maybe called by src/nm-device.c:constructor

   From the constructor code:
   -----------------------------------------------------------------------
   /* Delay transition from UNMANAGED to UNAVAILABLE until we've given the
    * system settings service a chance to figure out whether the device is
    * managed or not.
    */
    priv->start_timer = g_timeout_add_seconds (4, device_start, dev);
   -----------------------------------------------------------------------

Oct 22 06:43:54 NetworkManager: <info>  (eth0): device state change: 1 -> 2

   WHY STATE 1 (NM_DEVICE_STATE_UNMANAGED) ?   [See definition of states below]
   Should be state 0 (NM_DEVICE_STATE_UNKNOWN) !?!
     -> new state: 2 (NM_DEVICE_STATE_UNAVAILABLE)

   This is from the function src/nm-device.c:nm_device_state_changed
   either called by 
   a) src/nm-device.c:device_start with managed=TRUE:
   b) src/nm-device.c:nm_device_set_managed with
       NM_DEVICE_STATE_REASON_NOW_MANAGED
      maybe called by handle_unmanaged_devices (or sync_devices)

Oct 22 06:43:54 NetworkManager: <info>  (eth0): preparing device.

   This is from the function src/nm-device.c:nm_device_bring_up

Oct 22 06:43:54 NetworkManager: <info>  (eth0): deactivating device (reason: 2).

   This is from the function src/nm-device.c:nm_device_deactivate
   Reason 2: NM_DEVICE_STATE_REASON_NOW_MANAGED
===========================================================================


Dokumentation für die Device States aus include/NetworkManager.h:
-------------------------------------------------------------------------
        NM_DEVICE_STATE_UNKNOWN = 0,

        /* Initial state of all devices and the only state for devices not
         * managed by NetworkManager.
         *
         * Allowed next states:
         *   UNAVAILABLE:  the device is now managed by NetworkManager
         */
        NM_DEVICE_STATE_UNMANAGED,

        /* Indicates the device is not yet ready for use, but is managed by
         * NetworkManager.  For Ethernet devices, the device may not have an
         * active carrier.  For WiFi devices, the device may not have it's radio
         * enabled.
         *
         * Allowed next states:
         *   UNMANAGED:  the device is no longer managed by NetworkManager
         *   DISCONNECTED:  the device is now ready for use
         */
        NM_DEVICE_STATE_UNAVAILABLE,

        /* Indicates the device does not have an activate connection to anything.
         *
         * Allowed next states:
         *   UNMANAGED:  the device is no longer managed by NetworkManager
         *   UNAVAILABLE:  the device is no longer ready for use (rfkill, no carrier, etc)
         *   PREPARE:  the device has started activation
         */
-------------------------------------------------------------------------

Das ist sprachlich etwas verworren: Demnach sollte eth0 den Zustand NM_DEVICE_STATE_UNKNOWN (0) haben und nicht NM_DEVICE_STATE_UNMANAGED (1), den es anscheinend anfänglich tatsächlich hat.

Das Timeout Code-Fragement oben liest sich so, als würde der NetworkManager dem nm-system-settings Prozess Zeit geben wollen den Zustand entsprechend zu ändern, falls das device mit 'managed=False' markiert sein sollte.

Leider bekommen ich weder Debug Meldungen von nm-system-settings noch vom SCPluginIfupdown, das die /etc/network/interfaces lesen sollte.


Randbemerkung:
Mir ist die Interaktion zwischen nm-system-settings und NetworkManager noch unklar, aber beide scheinen unterschiedliche nm_device_init Funktionen zu verwenden:

./src/nm-device.c:nm_device_init setzt state auf NM_DEVICE_STATE_UNMANAGED !?!

Die Library mit der nm-system-settings gelinkt ist (libnm_glib) hingegen definiert die Funktion nm_device_init hingegen anders:

./libnm-glib/nm-device.c:nm_device_init setzt state auf NM_DEVICE_STATE_UNKNOWN
Comment 5 Arvid Requate univentionstaff 2009-10-28 19:37:43 CET
Die kritische Codepassage wird durch

http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=c9067d8fedf6f6f2d530fd68bbfca7ce68638d38&h=NETWORKMANAGER_0_7

ersetzt, In 0.8~a~git.20091005t192303 ist der Code z.B. nicht mehr drin.
Comment 6 Stefan Gohmann univentionstaff 2009-10-28 20:19:56 CET
(In reply to comment #5)
> Die kritische Codepassage wird durch
> 
> http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=c9067d8fedf6f6f2d530fd68bbfca7ce68638d38&h=NETWORKMANAGER_0_7
> 
> ersetzt, In 0.8~a~git.20091005t192303 ist der Code z.B. nicht mehr drin.

Meinst du ein Backport wäre denkbar bzw. bringt das etwas?

Können wir ansonsten in irgendeiner Art und Weise einen Workaround schaffen, also so dass wir den Networkmanager erst nach dem Reboot aktiv werden lassen?
Comment 7 Arvid Requate univentionstaff 2009-10-28 20:59:17 CET
Dafür benötigen wir ein aktuelleres udev aus squeeze, das libgudev mitbringt:
http://packages.debian.org/source/squeeze/udev

libgudev:
 This library makes it much simpler to use libudev from programs already using
 GObject. It also makes it possible to easily use libudev from other
 programming languages, such as Javascript, because of GObject introspection
 support.
Comment 8 Arvid Requate univentionstaff 2009-10-29 18:31:21 CET
Es scheint ja so zu sein, dass der nm-system-settings Prozess und damit das SCPlugin-Ifupdown nicht rechtzeitig gestartet wird, dass es die Frage des NetworkManager nach unmanaged Devices beantworten könnte.

Ich schicke jetzt im init Script network-manager vor den Start des NetworkManager Prozesses per dbus-send eine Anfrage an nm-system-settings, und warte auf die Antwort, sodass er danach gestartet sein sollte. In einem Test hat das dafür gesorgt, dass sowohl beim network-manager start im postinst von network-manager als auch beim dbus restart im postinst von univention-network-manager das Interface eth0 als unmanaged erkannt und in Ruhe gelassen wird.

Man sieht das schön im syslog: Da tauchen jetzt SCPlugin-Ifupdown Init Meldungen vor den beiden NetworkManager Starts auf.
Comment 9 Stefan Gohmann univentionstaff 2009-11-02 10:09:53 CET
Auf meiner Test-VM ist das erneut aufgetreten. Nach dem Update ist das Interface da, allerdings hat das System keine IP.

@Arvid: UCS.2.2-0.Master.amd64 auf albert.
Comment 10 Arvid Requate univentionstaff 2009-11-02 16:34:06 CET
Da war das Paket im testmirror noch das alte, aktuell ist network-manager_0.7.1-1.12.200910291514_amd64.deb
Comment 11 Daniel Hofmann univentionstaff 2009-11-24 12:38:07 CET
Thinclient-Pakete lt. updater.log alle erfolgreich installiert, bzw. zumindest keine Probleme beim Herunterladen der Pakete.

Exemplarisch im client-root:
qamaster:/# dpkg -l univention-gdm univention-gdm-sessions univention--xnumlock univention-x-core xserver-xorg xbase-clients univention-fonts xserver-xorg-video-all x11-common xorg xserver-xorg-video-via xserver-xorg-video-i810
Gewünscht=Unbekannt/Installieren/R=Entfernen/P=Vollständig Löschen/Halten
| Status=Nicht/Installiert/Config/U=Entpackt/Fehlgeschl. Konfiguration/
         Halb installiert/Trigger erWartet/Trigger anhängig
|/ Fehler?=(kein)/Halten/R=Neuinst notw/X=beide (Status, Fehler: GROSS=schlecht)
||/ Name                        Version                     Beschreibung
+++-===========================-===========================-======================================================================
ii  univention-fonts            1.0.0-3.15.200909182138     UCS - X Fonts
ii  univention-gdm              5.0.12-4.191.200911161640   UCS - GDM configuration
ii  univention-gdm-sessions     5.0.12-4.191.200911161640   UCS - GDM DefaultWM
ii  univention-x-core           3.0.8-2.75.200910261307     UCS - X System
ii  univention-xnumlock         4.0.2-3.34.200911041427     UCS - active numlock on login
ii  x11-common                  1:7.3+18.27.200909190753    X Window System (X.Org) infrastructure
ii  xbase-clients               1:7.3+18.27.200909190753    miscellaneous X clients - metapackage
ii  xorg                        1:7.3+18.27.200909190753    X.Org X Window System
ii  xserver-xorg                1:7.3+18.27.200909190753    the X.Org X server
ii  xserver-xorg-video-all      1:7.3+18.27.200909190753    the X.Org X server -- output driver metapackage
ii  xserver-xorg-video-i810     2:2.3.2-2.18.200910151451   X.Org X server -- Intel i8xx, i9xx display driver
ii  xserver-xorg-video-via      1:0.2.2-6.10.200910051956   X.Org X server -- VIA display driver
Comment 12 Arvid Requate univentionstaff 2009-11-26 09:50:53 CET
Zur Doku an diesem Bug:

Die irritierende Meldung '(eth0): deactivating device (reason: 2)' bedeutet anscheinend also nur, dass NM anfängt, das Device als 'managed' zu handhaben (2:NM_DEVICE_STATE_REASON_NOW_MANAGED) und ist an sich normal, alles weitere passiert danach.
Comment 13 Stefan Gohmann univentionstaff 2009-12-21 08:49:07 CET
UCS 2.3 wurde veröffentlicht. Sollte der hier beschriebene Bug mit einer neueren Version von UCS erneut auftreten, so sollte der Bug dupliziert werden: "Clone This Bug".