[Gelöst] Wheezy: networking Init-Skript zu schnell?

[Sigi44]

Hallo,

habe mir auf zwei Rechnern Debian Wheezy installiert (i686) und hatte Probleme mit dem Netzwerk:

Der eine Rechner ist Blech mit einem NIC und einer IPv4- und einer IPv6-Adresse (per DHCP bzw. IPv6 automatisch bezogen) und ein NFS-Client und manchmal war der NFS-Mount nach dem Booten nicht da, manchmal war er da.

Der andere Rechner ist ein Apache- und Cups-Server in einer KVM (Kernel Virtual Machine), mit ebenfalls nur einer NIC und einer IPv4-Adresse per DHCP und einer statischen IPv6-Adresse. Hier war es so, dass die beiden Dienste nach dem (sehr flotten) Booten nicht ansprechbar waren, sondern erst neugestartet (/etc/init.d/cups restart) werden mussten, dann waren sie erreichbar.

Ich hatte nun das Dependency Based Booting im Verdacht. Bei Squeeze konte man dies ja noch mit

Code: Alles auswählen

# echo 'CONCURRENCY=none' >> /etc/default/rcS

deaktivieren, doch das geht jetzt wohl nicht mehr? Ich brauche kein besonders schnelles Booten, es soll lieber alles ordentlich funktionieren...

Die Lösung war jetzt, dass ich in /etc/init.d/networking in Zeile 137 (letzte Zeile in der "start"-Sektion) ein

Code: Alles auswählen

sleep 5

eingefügt habe.

Es scheint so zu sein, dass das Network angeblich gestartet ist, aber die interfaces noch nicht wirklich up sind, und die Server-Dienste dann zu schnell starten und sich nicht an die Network Interfaces binden können?

Durch den sleep-Befehl sind die Dienste jetzt wie gewohnt nach dem Booten verfügbar, und der NFS-Client mountet zuverlässig seinen Mountpoint.

Was meint Ihr dazu?

[rendegast]

Betrifft das dann nicht auch andere Dienste wie ssh?

Hast Du vielleicht auf die Bootreihenfolge der Skripte Einfluß genommen,
zBsp. in /etc/insserv/overrides/?
networks sollte in rcS.d/ sein,
apache / cups in den anderen.

Ein erster Test für invalide Bootabfolge wäre 'insserv -v'
mit ständigen oder ständig wechselnden Ausgaben.

Fremdskripte?

Es scheint so zu sein, dass das Network angeblich gestartet ist, aber die interfaces noch nicht wirklich up sind,

Meldungen (auch des Treibers), dmesg ?

Der andere Rechner ist ein Apache- und Cups-Server in einer KVM

Die emulierte Hardware ließe sich vorgeben, ne2k, realtek, intel ...
Änderungen dabei?
(Beachte, daß sich das in /etc/udev/rules.d/*persistent* auswirkt, also die Benahmung des Netzwerk-Interfaces)

[Sigi44]

Betrifft das dann nicht auch andere Dienste wie ssh?

Nein, ssh ist nicht betroffen

Hast Du vielleicht auf die Bootreihenfolge der Skripte Einfluß genommen,
zBsp. in /etc/insserv/overrides/?

Nein, es sind beides frische Minimal-Installationen, wo ich nur das notwendigste geändert habe.

networks sollte in rcS.d/ sein,
apache / cups in den anderen.

Ja, das ist so.

Ein erster Test für invalide Bootabfolge wäre 'insserv -v'
mit ständigen oder ständig wechselnden Ausgaben.

Ich weiß nicht genau, was Du meinst. Die Ausgabe sieht konstant so aus:

Code: Alles auswählen

# insserv -v
insserv: creating .depend.boot
insserv: creating .depend.start
insserv: creating .depend.stop

Fremdskripte?

Nein, s.o.

Meldungen (auch des Treibers), dmesg ?

In den Logs sehe ich meine Vermutung der zeitlichen Überschneidung bestätigt- zum Testen habe ich das "sleep 10" aus dem networking initskript auskommentiert:

In /var/log/syslog sieht man:
07:33:23 eth0: link is not ready
07:33:25 eth0: link becomes ready
07:33:31 dhclient: bound to 192.168.1.3

Cups will sich aber schon um 07:33:24 zu der IP-Adresse binden (/var/log/cups/error_log):
E [16/Jun/2013:07:33:24 +0200] Unable to bind socket for address 192.168.1.3:631 - Cannot assign requested address.

/var/log/syslog

Code: Alles auswählen

Jun 16 07:33:23 wheezy kernel: [    2.101942] loop: module loaded
Jun 16 07:33:23 wheezy kernel: [    2.641958] RPC: Registered named UNIX socket transport module.
Jun 16 07:33:23 wheezy kernel: [    2.641961] RPC: Registered udp transport module.
Jun 16 07:33:23 wheezy kernel: [    2.641962] RPC: Registered tcp transport module.
Jun 16 07:33:23 wheezy kernel: [    2.641963] RPC: Registered tcp NFSv4.1 backchannel transport modu
le.
Jun 16 07:33:23 wheezy kernel: [    2.646386] FS-Cache: Loaded
Jun 16 07:33:23 wheezy kernel: [    2.651820] FS-Cache: Netfs 'nfs' registered for caching
Jun 16 07:33:23 wheezy kernel: [    2.654931] Installing knfsd (copyright (C) 1996 okir@monad.swb.de
).
Jun 16 07:33:23 wheezy kernel: [    2.749728] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun 16 07:33:23 wheezy acpid: starting up with netlink and the input layer
Jun 16 07:33:23 wheezy acpid: 1 rule loaded
Jun 16 07:33:23 wheezy acpid: waiting for events: event logging is off
Jun 16 07:33:24 wheezy /usr/sbin/cron[2288]: (CRON) INFO (pidfile fd = 3)
Jun 16 07:33:24 wheezy /usr/sbin/cron[2290]: (CRON) STARTUP (fork ok)
Jun 16 07:33:24 wheezy /usr/sbin/cron[2290]: (CRON) INFO (Running @reboot jobs)
Jun 16 07:33:24 wheezy kernel: [    3.529165] lp0: using parport0 (interrupt-driven).
Jun 16 07:33:24 wheezy kernel: [    3.530794] ppdev: user-space parallel port driver
Jun 16 07:33:24 wheezy dbus[2336]: [system] Activating service name='org.freedesktop.ColorManager' (
using servicehelper)
Jun 16 07:33:24 wheezy dbus[2336]: [system] Successfully activated service 'org.freedesktop.ColorMan
ager'
Jun 16 07:33:24 wheezy dbus[2336]: [system] Activating service name='org.freedesktop.colord-sane' (u
sing servicehelper)
Jun 16 07:33:24 wheezy dbus[2336]: [system] Successfully activated service 'org.freedesktop.colord-s
ane'
Jun 16 07:33:25 wheezy kernel: [    4.752538] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow
 Control: RX
Jun 16 07:33:25 wheezy kernel: [    4.752925] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jun 16 07:33:31 wheezy dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 9
Jun 16 07:33:31 wheezy dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Jun 16 07:33:31 wheezy dhclient: DHCPOFFER from 192.168.1.1
Jun 16 07:33:31 wheezy dhclient: DHCPACK from 192.168.1.1
Jun 16 07:33:31 wheezy dhclient: bound to 192.168.1.3 -- renewal in 34652 seconds.

/var/log/cups/error_log

Code: Alles auswählen

I [16/Jun/2013:07:33:24 +0200] Listening to 192.168.1.3:631 (IPv4)
I [16/Jun/2013:07:33:24 +0200] Listening to /var/run/cups/cups.sock (Domain)
I [16/Jun/2013:07:33:24 +0200] Remote access is enabled.
I [16/Jun/2013:07:33:24 +0200] Loaded configuration file "/etc/cups/cupsd.conf"
I [16/Jun/2013:07:33:24 +0200] Using default TempDir of /var/spool/cups/tmp...
I [16/Jun/2013:07:33:24 +0200] Configured for up to 100 clients.
I [16/Jun/2013:07:33:24 +0200] Allowing up to 100 client connections per host.
I [16/Jun/2013:07:33:24 +0200] Using policy "default" as the default.
I [16/Jun/2013:07:33:24 +0200] Full reload is required.
I [16/Jun/2013:07:33:24 +0200] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 39 types, 56 filters...
I [16/Jun/2013:07:33:24 +0200] Registering ICC color profiles for "Samsung_ML-1510_700"
I [16/Jun/2013:07:33:24 +0200] Generating printcap /var/run/cups/printcap...
I [16/Jun/2013:07:33:24 +0200] Loading job cache file "/var/cache/cups/job.cache"...
I [16/Jun/2013:07:33:24 +0200] Full reload complete.
I [16/Jun/2013:07:33:24 +0200] Cleaning out old files in "/var/spool/cups/tmp"...
I [16/Jun/2013:07:33:24 +0200] Cleaning out old files in "/var/cache/cups"...
E [16/Jun/2013:07:33:24 +0200] Unable to bind socket for address 192.168.1.3:631 - Cannot assign requested address.
I [16/Jun/2013:07:33:24 +0200] Listening to /var/run/cups/cups.sock:631 on fd 9...
I [16/Jun/2013:07:33:24 +0200] Resuming new connection processing...

Hier die Ausgabe von /var/log/syslog mit dem "sleep 10" in /etc/init.d/networking
08:07:06 eth0: link becomes ready
Cups:
I [16/Jun/2013:08:07:07 +0200] Listening to 192.168.1.3:631 on fd 9...

Interessanterweise wird das DHCP auf dem Client nicht geloggt, wenn sleep 10 aktiviert ist. Ich sehe das dann nur auf dem DHCP-Server-Log (Zeit auf DHCP-Server und -Client ist exakt gleich):
/var/log/dhcp.log (auf DHCP-Server)

Code: Alles auswählen

Jun 16 08:06:59 regen dhcpd: DHCPDISCOVER 
Jun 16 08:06:59 regen dhcpd: DHCPOFFER on 192.168.1.3
Jun 16 08:06:59 regen dhcpd: DHCPREQUEST for 192.168.1.3
Jun 16 08:06:59 regen dhcpd: DHCPACK on 192.168.1.3

Kann jemand erklären, wieso das DHCP auf dem Client nicht geloggt wird?

/var/log/syslog (auf Client)

Code: Alles auswählen

Jun 16 08:07:06 wheezy kernel: [    2.087194] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
Jun 16 08:07:06 wheezy kernel: [    2.109316] loop: module loaded
Jun 16 08:07:06 wheezy kernel: [    2.743339] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun 16 08:07:06 wheezy kernel: [    4.748499] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
Jun 16 08:07:06 wheezy kernel: [    4.748877] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jun 16 08:07:06 wheezy kernel: [   12.641751] RPC: Registered named UNIX socket transport module.
Jun 16 08:07:06 wheezy kernel: [   12.641754] RPC: Registered udp transport module.
Jun 16 08:07:06 wheezy kernel: [   12.641755] RPC: Registered tcp transport module.
Jun 16 08:07:06 wheezy kernel: [   12.641756] RPC: Registered tcp NFSv4.1 backchannel transport module.
Jun 16 08:07:06 wheezy kernel: [   12.646054] FS-Cache: Loaded
Jun 16 08:07:06 wheezy kernel: [   12.651309] FS-Cache: Netfs 'nfs' registered for caching
Jun 16 08:07:06 wheezy kernel: [   12.654403] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
Jun 16 08:07:06 wheezy acpid: starting up with netlink and the input layer
Jun 16 08:07:06 wheezy acpid: 1 rule loaded
Jun 16 08:07:06 wheezy acpid: waiting for events: event logging is off
Jun 16 08:07:07 wheezy /usr/sbin/cron[2381]: (CRON) INFO (pidfile fd = 3)
Jun 16 08:07:07 wheezy /usr/sbin/cron[2391]: (CRON) STARTUP (fork ok)
Jun 16 08:07:07 wheezy /usr/sbin/cron[2391]: (CRON) INFO (Running @reboot jobs)
Jun 16 08:07:07 wheezy kernel: [   13.497417] lp0: using parport0 (interrupt-driven).
Jun 16 08:07:07 wheezy kernel: [   13.501259] ppdev: user-space parallel port driver

/var/log/cups/error_log

Code: Alles auswählen

I [16/Jun/2013:08:07:07 +0200] Listening to 192.168.1.3:631 (IPv4)
I [16/Jun/2013:08:07:07 +0200] Listening to /var/run/cups/cups.sock (Domain)
I [16/Jun/2013:08:07:07 +0200] Remote access is enabled.
I [16/Jun/2013:08:07:07 +0200] Loaded configuration file "/etc/cups/cupsd.conf"
I [16/Jun/2013:08:07:07 +0200] Using default TempDir of /var/spool/cups/tmp...
I [16/Jun/2013:08:07:07 +0200] Configured for up to 100 clients.
I [16/Jun/2013:08:07:07 +0200] Allowing up to 100 client connections per host.
I [16/Jun/2013:08:07:07 +0200] Using policy "default" as the default.
I [16/Jun/2013:08:07:07 +0200] Full reload is required.
I [16/Jun/2013:08:07:07 +0200] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 39 types, 56 filters...
I [16/Jun/2013:08:07:07 +0200] Registering ICC color profiles for "Samsung_ML-1510_700"
I [16/Jun/2013:08:07:07 +0200] Generating printcap /var/run/cups/printcap...
I [16/Jun/2013:08:07:07 +0200] Loading job cache file "/var/cache/cups/job.cache"...
I [16/Jun/2013:08:07:07 +0200] Full reload complete.
I [16/Jun/2013:08:07:07 +0200] Cleaning out old files in "/var/spool/cups/tmp"...
I [16/Jun/2013:08:07:07 +0200] Cleaning out old files in "/var/cache/cups"...
I [16/Jun/2013:08:07:07 +0200] Listening to 192.168.1.3:631 on fd 9...
I [16/Jun/2013:08:07:07 +0200] Listening to /var/run/cups/cups.sock:631 on fd 10...
I [16/Jun/2013:08:07:07 +0200] Resuming new connection processing...

P.S. Das heutige Upgrade auf Debian 7.1 hat nichts geändert

[rendegast]

Ein Hardware- / Treiberproblem? e1000.

Testweise mal eine andere Netzwerkkarte einbauen.
Testweise mal den kernel 3.8 / 3.10 aus sid (+initramfs-tools) installieren.
(3.2 - 3.10 sind zwar alle version: 7.3.21-k8-NAPI,
aber deren srcversion: ist unterschiedlich)
Anderen Router (DHCP-Server)? Kabeltausch?
Bios-Upgrade? Mit Bios-Einstellungen spielen?


Interessehalber,
der e1000 wird schon aus der initrd geladen? (dmesg ~ 1sec)
Wäre der Standard beim initrd-Erstellen,
also ohne Eintrag in initramfs-tools/modules.


"DHCP....." wird in die /var/log/boot geschrieben, wenn bootlogd installiert ist.
Die den Boot-Prozeß beschreibenden Dateien sind
boot daemon.log dmesg
kern.log messages syslog
Von den dreien kern.log, messages, syslog ist die syslog die informativste.

[Sigi44]

Die (zugegeben banale) Lösung: /etc/network/interfaces ändern:
Alt:

Code: Alles auswählen

# The primary network interface
allow-hotplug eth0
iface eth0 inet dhcp

Neu:

Code: Alles auswählen

# The primary network interface
auto eth0
allow-hotplug eth0
iface eth0 inet dhcp

Jetzt funzt alles mit dem Original-networking-Init-Skript, ohne sleep.
Gut, ich weiß aber auch nicht, wieso das Interface überhaupt hochkommt ohne "auto", sonst wäre ich natürlich früher darauf gestoßen...
Danke für den Tipp mit dem bootlogd, rendegast, nach Installation desselben wurde nämlich auch nichts in Sachen DHCP geloggt, und da schwante mir, dass das Interface anscheinend gar nicht richtig startet.