[Problem] [freetz labor-branch] multid läuft nicht - keine Namensauflösung

[otherland]

Könnt ihr mal bitte schauen, ob in /var/flash/crash.log eine Meldung vom multid steht? Irgendwas muss ja passiert sein, dass der nicht mehr läuft.

Hier brauche ich glaube ich wieder einen Tip - die Datei verhält sich eigenartig:

root@fritz:/etc/init.d# ls -la  /var/flash/crash.log 
crw-r--r--    1 root     root      240,  95 Jan  1  2000 /var/flash/crash.log

root@fritz:/etc/init.d# cat /var/flash/crash.log 
cat: can't open '/var/flash/crash.log': No such file or directory

Die Datei ist ein Character Device, ist vorhanden und lesbar, aber cat liefert 'No such file' ... häh?

Ausserdem wollte cuma noch den Inhalt der verschiedenen *resolv.conf haben - aktuell erstmal im Gutfall, den Schlechtfall werde ich heute Abend noch provozieren und dann die *resolv.conf im Schlechtfall nachtragen.

Ich finde bei mir vier verschiedene *resolv.conf

Gutfall:

root@fritz:/etc/init.d# cat /etc/resolv.conf
nameserver 127.0.0.1
domain fonwlan.box

root@fritz:/etc/init.d# cat /var/tmp/avm-resolv.conf
nameserver 192.168.180.1
nameserver 192.168.180.2

root@fritz:/etc/init.d# cat /var/tmp/resolv.conf 
nameserver 127.0.0.1

root@fritz:/etc/init.d# cat /var/tmp/etc-resolv.conf
nameserver 127.0.0.1
domain fonwlan.box

[Schlechtfall kommt per Edit nach, wenn ich das Problem wieder provoziert habe]

 

[olistudent]

Okay. Danke. In deiner crash.log steht schon mal nichts drin. Dann stürzt der multid wohl doch nicht ab. Sollen wir die Ausgabe von rc.multid in eine Datei loggen?

Gruß
Oliver

 

[otherland]

Okay. Danke. In deiner crash.log steht schon mal nichts drin. Dann stürzt der multid wohl doch nicht ab. Sollen wir die Ausgabe von rc.multid in eine Datei loggen?

Verflixt - bis gestern konnte ich das Problem in fünf von fünf Versuchen absolut sicher reproduzieren. Jede automatische Trennung hat zu dem Problem geführt.

Jetzt hat es weder gestern Abend noch heute Nacht funktioniert: in beiden Fällen hat die Trennung laut System-Log stattgefunden, danach war der multid aber noch aktiv und die Namensauflösung hat noch funktioniert.

Dazwischen habe ich nicht am System verändert.

Ich werde das weiter beobachten - wie konfiguriere ich multid so dass er in eine Datei logged, so dass ich das Log beim nächsten Auftreten verfügbar habe?

[---- edit ----]

Auch am Sonntag hat die Zwangstrennung wieder klaglos funktioniert, ohne dass das Problem mit dem sterbenden multid wieder aufgetreten wäre. Ich weis nicht wo der Unterschied liegt. Ich werde jetzt die Box neu starten und die Trennung in den Abend legen.

 

[pengu]

Nun dachte ich mit neuer FW und neuestem Trunk läuft es.
Den Reconnect letzte Nacht hat hat multid wohl überstanden, jedoch einen Reconnect per UPNP vorhin nicht.

Im crash.log steht bei mir auch nichts


Obwohl der Inhalt der 3 *resolv.conf genauso wie bei otherland ist, ist bei mir die Namensauflösung durch das "Verschwinden" von multid wieder komplett weg.
Heißt auf den angeschlossenen rechnern die 2 avm ips als nameserver eintragen.

 

[cuma]

Nun, der multid ist der DNS-Server von AVM.

 

[pengu]

Das ist mir schon klar.

 

[cuma]

Vielleicht ist es auch ein Problem von AVM das in einer der nächsten Labor behoben wird. Villeicht sollte es jemand ohne Freetz ausprobieren

 

[pengu]

Das hab ich anfangs auch gemacht, mit der vorherigen Labor, doch kann ich es nicht mit Sicherheit sagen.

[Edit]

multid von "Hand" gestartet scheint ein paar Reconnects zu "überleben"

 

[otherland]

Nach einem Reboot der Box hatte ich jetzt zunächst wieder das bekannt Verhalten:

- Reboot der Box, Zwangstrennung auf 14-15 Uhr eingestellt
- Nach Zwangstrennung läuft der multid nicht mehr, keine Namensauflösung
- Inhalt der verschiedenen *resolv.conf ist dabei genau wie im Gutfall, ist also nicht die Ursach des Problems

Diesmal habe ich zweimal hintereinander versucht den multid zu starten:

root@fritz:/var/mod/root# ps | grep multi
27928 root      1156 S    grep multi
root@fritz:/var/mod/root# cd /etc/init.d/
root@fritz:/etc/init.d# ./rc.multid start
Starting AVM multid ... done.
root@fritz:/etc/init.d# ps | grep multi
28102 root      1156 S    grep multi

Multid läßt sich beim ersten Versuch nicht starten - keine auffällige Ausgabe im syslog

root@fritz:/etc/init.d# ./rc.multid start
Starting AVM multid ... done.
root@fritz:/etc/init.d# ps | grep multi
28116 root      4120 S    multid -t
28222 root      1156 R    grep multi

Beim zweiten Mal hat es dann geklappt, und abweichend von meinen bisherigen Beobachtungen hat diesmal der Start des multid gereicht damit die Namensauflösung wieder geht - ein 'rc.net restart' war nicht erforderlich.

Ich glaube der Weg weiter führt über die Frage, warum der multid bei der Zwangstrennung stirbt - hat jemand einen Tip, wie man den multid dazu bringt erweiterte Debug-Informationen in ein File auf dem USB-Stick oder im Box-Speicher zu schreiben? Der multid braucht eine Option '-v', aber wie bringe ich ihn dazu in ein File und nicht über den syslogd zu loggen? Hat jemand hier vielleicht einen Patch für die rc.multid?

 

[cuma]

Dz könntest dich mit "strace -p pid-vom-multid" an den multid hängen. Dann könnte man sehen weshalb er abstürzt. Das "-p" kann mehrfach angegeben werden

 

[otherland]

Dz könntest dich mit "strace -p pid-vom-multid" an den multid hängen. Dann könnte man sehen weshalb er abstürzt. Das "-p" kann mehrfach angegeben werden

Super, daran hatte ich gar nicht gedacht. Ich habe jetzt folgendes gemacht:

- neue FW gebaut, diesmal mit strace -> FW geflashed
- Zwangstrennung ist wieder auf zwischen 1-2 Uhr Nachts gestellt
- zwei ssh-Logins auf der Box

Auf Terminal A:

root@fritz:/var/media/ftp/uStor11# mkfifo fifo
root@fritz:/var/media/ftp/uStor11# gzip -c < ./fifo > strace_multid.log.gz

Auf Terminal B:

root@fritz:/var/media/ftp/uStor11# strace -p 3087 -p 3099 &> fifo

Ich schreibe also auf Terminal B den Output (stdout und stderr) des strace aus den beiden multid-Prozessen (PIDs 3087 und 3099) in einen FIFO, den ich auf Terminal A auslese und als Input für ein gzip verwende.

Grund für den gzip ist die Menge an Daten - ich befürchte dass mir das Volumen den Platz auf der Box/Stick sprengt.
Grund für die Verrenkung mit dem FIFO ist einfach, dass ich auf die Schnelle keine Möglichkeit gefunden habe den stderr des strace in gzip hineinzubekommen.

Ich werde morgen früh mal nachsehen was über Nacht passiert ist, und dann diesen Post mit dem Ergebnis erweitern.

[---- edit ----]

Es hat geklappt - das Problem ist heute Nacht wieder aufgetreten, und ich habe den strace
Ich muss jetzt zur Arbeit, werde die Datei heute Abend ansehen/anhängen

 

[RalfFriedl]

dass ich auf die Schnelle keine Möglichkeit gefunden habe den stderr des strace in gzip hineinzubekommen.

strace -p 3087 -p 3099 2>&1 | gzip > strace_multid.log.gz
# oder
strace -p 3087 -p 3099 -o /dev/stdout | gzip > strace_multid.log.gz

 

[otherland]

strace -p 3087 -p 3099 2>&1 | gzip > strace_multid.log.gz
# oder
strace -p 3087 -p 3099 -o /dev/stdout | gzip > strace_multid.log.gz

Hallo Ralf,

vielen Dank fuer die Tips - den ersten der beiden hatte ich genau so auch versucht, habe da aber irgendetwas in der Art 'illegal operator before |' oder so (bin gerade nicht an meinem Rechner) bekommen. Komischerweise ging ' strace -p ... > | gzip' aber - bringt natürlich nichts, weil strace nach stderr schreibt.

Auf die Idee '-o /dev/stdout' zu verwenden bin ich nicht gekommen.

 

[RalfFriedl]

Vielleicht war es doch nicht ganz exakt das Gleiche. Beide Ansätze haben den Nachteil, daß die normale Ausgabe mit dem strace vermischt wird, was aber hier keine Rolle spielt.

Ich hätte übrigens eher Bedenken gehabt, daß die CPU-Auslastung von gzip die Box zum Absturz bringt, als daß das Dateisystem voll wird. Das hängt aber auch von der Menge des verfügbaren Speicherplatzes ab.

 

[otherland]

Vielleicht war es doch nicht ganz exakt das Gleiche. Beide Ansätze haben den Nachteil, daß die normale Ausgabe mit dem strace vermischt wird, was aber hier keine Rolle spielt.

Du hast völlig recht - ich hatte nicht den Operator '2>&1' sondern '&>' verwendet - der funktioniert zwar ohne die Pipe dahinter, aber mit Pipe kommt 'syntax error: unexpected "|"'

Ich hätte übrigens eher Bedenken gehabt, daß die CPU-Auslastung von gzip die Box zum Absturz bringt, als daß das Dateisystem voll wird. Das hängt aber auch von der Menge des verfügbaren Speicherplatzes ab.

Das hat bei mir sehr gut geklappt: auf einer 7390 mit Output des gezippten Files auf einen USB-Stick bin ich über die gesamten zwei Stunden die das Ding gelaufen ist laut RRDstats nie ueber 5% CPU gekommen.

Zurück zum Topic:

Ich habe hier den strace angehängt.

Ganz am Ende:

[...]
[pid  3087] setsockopt(9, SOL_IP, 0xcb /* IP_??? */, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 16) = -1 EADDRNOTAVAIL (Cannot assign requested address)
[pid  3087] setsockopt(9, SOL_IP, 0xcb /* IP_??? */, "\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 16) = -1 EADDRNOTAVAIL (Cannot assign requested address)
[pid  3087] getpid()                    = 3087
[pid  3087] ipc(0x1, 0x18003, 0x1, 0, 0x2abe85cc, 0x2ae23240) = 0
[pid  3087] ipc(0x1, 0x10002, 0x1, 0, 0x2abe85c4, 0x2ae25c00) = 0
[pid  3087] ipc(0x1, 0x20004, 0x1, 0, 0x2abe85cc, 0x2ae23240) = 0
[pid  3087] ipc(0x1, 0x10002, 0x1, 0, 0x2abe85d4, 0x2ae25c00) = 0
[pid  3087] ipc(0x1, 0x18003, 0x1, 0, 0x2abe85d4, 0x2ae23240) = 0
[pid  3087] ipc(0x1, 0x20004, 0x1, 0, 0x2abe85d4, 0x101) = 0
[pid  3087] munmap(0x2ade4000, 61184)   = 0
[pid  3087] munmap(0x2ade2000, 4)       = 0
[pid  3087] close(7)                    = 0
[pid  3087] close(8)                    = 0
[pid  3087] close(9)                    = 0
[pid  3087] close(20)                   = 0
[pid  3087] close(24)                   = 0
[pid  3087] munmap(0x2ae23000, 4096)    = 0
[pid  3087] unlink("/var/run/multid.pid") = 0
[pid  3087] exit(0)                     = ?
Process 3087 detached
<... poll resumed> )                    = 0 (Timeout)
getppid()                               = 1
exit(0)                                 = ?
Process 3099 detached

Kann damit jemand etwas anfangen?

 

[RalfFriedl]

Der angezeigte Teil vom Protokoll ist nur noch das Aufräumen vor dem Beenden.

Ich vermute das Problem hier:

[pid  3087] fork()                      = 22544
...
[pid  3087] wait4(22544, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG, NULL) = 22544

Ein Prozess, der von multid gestartet wird, wird mit status 1 beendet, kurz darauf beendet sich auch der multid selbst.

Funktioniert auf der Box Replace Kernel bzw. doe Option -f von strace? Was könnte der multid an dieser Stelle aufrufen?

 

[olistudent]

Mit der Labor sollte "replace kernel" funktionieren.

Gruß
Oliver

 

[otherland]

[...]
Funktioniert auf der Box Replace Kernel bzw. doe Option -f von strace? Was könnte der multid an dieser Stelle aufrufen?

'-f' scheint bei mir zu funktionieren (ohne 'replace kernel', da ich aktuell auf dem Trunk bin).

Ich habe wieder ueber Nacht ein strace gestartet, diesmal mit '-f'.

[--- edit ---]

Diesmal wieder kein Erfolg: die Internetverbindung wurde um 1:14:58 Uhr automatisch getrennt und wieder gestartet, multid (und der strace) läuft aber heute morgen noch. Ich habe den 'strace -f' verfügbar (diesmal sehr lang, weil er nicht im frühen morgen abgebrochen sondern die ganze Nacht durchgelaufen ist.

Ich kann wenn gewünscht das Log trotzdem posten - leider enthält es aber keine für mich erkennbaren Timestamps, so dass es schwer ist den Zeitpunkt des Reconnect aufzufinden.

Langsam erscheint mir folgendes Verhalten wahrscheinlich:
o wenn die Box neu gebootet ist tritt das Problem auf
o wenn ich dann den multid von Hand auf der Box starte, erfordert das in diesem Zustand zweimal hintereinander 'rcmultid start' hintereinander - beim ersten Mal startet er nicht, beim zweiten Mal klappt es dann
o danach überlebt der multid dann die automatische Trennung ohne Problem

Diese Abfolge habe ich jetzt mindestens zwei bis drei Mal (beim dritten Mal bin ich mir nicht 100%ig sicher) genau so gesehen.

 

[schmatke]

Langsam erscheint mir folgendes Verhalten wahrscheinlich:
o wenn die Box neu gebootet ist tritt das Problem auf
o wenn ich dann den multid von Hand auf der Box starte, erfordert das in diesem Zustand zweimal hintereinander 'rcmultid start' hintereinander - beim ersten Mal startet er nicht, beim zweiten Mal klappt es dann

Das Verhalten hatte ich beim Trunk 6731 auch festgestellt. Mittlerweile (Trunk 6786) hab ich das Problem nicht mehr. Woran es lag, weiß ich aber auch nicht.

 

[olistudent]

Der Zeitpunkt der Zwangstrennung sollte sich relativ leicht finden lassen...

[pid  3087] access("/bin/onlinechanged", X_OK) = 0
[pid  3087] kill(-22513, SIGTERM)       = 0
[pid  3087] --- {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=22513, si_status=SIGTERM, si_utime=2, si_stime=0} (Child exited) ---
[pid  3087] fork()                      = 22544

Hier sieht man den fork leider nicht was Ralf zu der Vermutung geführt hat, dass du "replace kernel" benötigst.

Gruß
Oliver