Freetz trunk 4162: Jeder eingehende Anruf löst "user.err telefon[1136]: SIGCHLD" aus

[KlBst]

Konfiguration:

• 
  Freetz Trunk 4162
  FB 7270 16MB, 4 DECT Telefone, Kabel-BW/ISDN Modem
  Packages: dnsmasq, mc, samba,
  WEB IF: syslogd

Jeder eingehende Anruf erzeugt offensichtlich die o.a. Meldung. Erst kurze Zeit später klingeln die DECT Telefone und dies mit unterschiedlicher Verzögerung.

In Freetz V4100 trat dieser Fehler nicht auf.

--> Wie und wo kann ich nach der Ursache suchen?

Klaus

 

[meiser79]

Ich sehe dies auch mit meiner 7170. Aktuell ist die Rev. 3976 drauf.

Jan  5 23:24:51 fritz user.err telefon[1034]: SIGCHLD received!

Leider weiss ich spontan auch nicht, wo ich anfangen soll zu suchen.

 

[olistudent]

Das muss doch auch keine Fehlermeldung sein oder? Kommt natürlich darauf an, ob es von AVM gewollt ist, dass der Kindprozess beendet wird oder nicht...

War Freetz-r4100 die gleiche Firmware?

MfG Oliver

 

[RalfFriedl]

Generell ist es eine Meldung aus einem AVM-Programm, auf die wir keinen Einfluß haben. Wenn die Meldung vorher nicht kam, ist die wahrscheinlichste Erklärung, daß sich etwas an der Protokollierung im syslog geändert hat, was bewirkt, daß jetzt die Meldung ausgegeben wird.
Das Signal SIGCHLD wird generiert, wenn ein gestarteter Prozeß beendet wird. Da fast jeder gestartete Prozeß irgendwann auch wieder beendet wird, sollte das nicht überraschen. Es ist eher seltsam, daß das als Fehler protokolliert wird. Möglicherweise bedeutet die Meldung nicht nur, daß SIGCHLD empfangen wurde, sondern auch, daß der Prozeß mit einem Fehler beendet wurde, auch wenn das aus dem Wortlaut nicht hervor geht.

Ein strace des telefon Prozesses könnte zeigen, welches Programm da aufgerufen wird und mit welchem Ergebnis. Damit die Option -f funktioniert, muß man replace Kernel aktivieren.

strace -f -s200 -p $(pidof telefon)

 

[KlBst]

[Edit frank_m24: Mehrere Beiträge zusammengefasst. Man kann seine Beiträge auch editieren.]

[Edit frank_m24: Sinnfreies Vollzitat gelöscht, siehe Forumregeln.]

Ja, in beiden Fällen die aktuelle 7270 54.04.80

Klaus

[Beitrag 2:]

Ein strace des telefon Prozesses könnte zeigen, welches Programm da aufgerufen wird und mit welchem Ergebnis. Damit die Option -f funktioniert, muß man replace Kernel aktivieren.

strace -f -s200 -p $(pidof telefon)

O.K.: Werde das Morgen mal testen.

Interessant ist doch, dass eine Änderung an der Umgebung ohne Änderung an den AVM Teilen diese Fehlermeldung hervorruft.

Klaus

 

[KlBst]

Sorry, hat etwas länger gedauert, da ich unsere Telefonanlage nur in Ausnahmefällen stillegen darf

Folgende Schritte habe ich zur Isolation inzwischen unternommen:

1. Recover mit der aktuellen AVM Release, um evtl. Seiten Effekte zu vermeiden
2. Neues SVN Check-Out der Freetz stable.1.1 / Rev. 4188
3. Build mit
   • Replace Kernel
   • strace
   • dnsmasq
   • samba
   • syslog CGI

Resultat:

• die Fehlermeldung wird bei eingehenden Anrufen weiterhin erzeugt

strace Aufruf:

/var/media/ftp/uStor01/freetz # strace -f -s200 -p 1276 -o t2.log
Process 1276 attached - interrupt to quit
Process 2698 attached
Process 2698 detached
Process 1276 detached
/var/media/ftp/uStor01/freetz #

strace log (nur die letzten Zeilen):

1276  write(10, "trigger"..., 7)        = 7
1276  poll([{fd=22, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=24, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=25, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=26, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=27, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=13, events=POLLIN}], 1, 0) = 0 (Timeout)
1276  poll([{fd=14, events=POLLIN}], 1, 0) = 0 (Timeout)
1276  time(NULL)                        = 1263237575
1276  recv(22, 0x2aab6700, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(24, 0x2aab6800, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(25, 0x2aab6900, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(26, 0x2aab6a00, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(27, 0x2aab6b00, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  read(18, ""..., 1)                = 0
1276  _newselect(6, [5], NULL, NULL, {0, 10000}) = 0 (Timeout)
1276  read(23, 0x7fb40440, 1)           = -1 EAGAIN (Resource temporarily unavailable)
1276  clock_gettime(CLOCK_MONOTONIC, {6606, 954043484}) = 0
1276  read(5, 0x2ad57a24, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  read(6, 0x2ad68224, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  read(7, 0x2ad6c0e4, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  write(10, "trigger"..., 7)        = 7
1276  poll([{fd=22, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=24, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=25, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=26, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=27, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=13, events=POLLIN}], 1, 0) = 0 (Timeout)
1276  poll([{fd=14, events=POLLIN}], 1, 0) = 0 (Timeout)
1276  time(NULL)                        = 1263237575
1276  recv(22, 0x2aab6700, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(24, 0x2aab6800, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(25, 0x2aab6900, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(26, 0x2aab6a00, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  recv(27, 0x2aab6b00, 256, MSG_PEEK|MSG_TRUNC) = -1 EAGAIN (Resource temporarily unavailable)
1276  read(18, ""..., 1)                = 0
1276  _newselect(6, [5], NULL, NULL, {0, 10000}) = 0 (Timeout)
1276  read(9, 0x7fb40840, 8)            = -1 EAGAIN (Resource temporarily unavailable)
1276  gettimeofday({1263237575, 530139}, {0, 0}) = 0
1276  clock_gettime(CLOCK_MONOTONIC, {6606, 974368308}) = 0
1276  clock_gettime(CLOCK_MONOTONIC, {6606, 974808881}) = 0
1276  clock_gettime(CLOCK_MONOTONIC, {6606, 975250742}) = 0
1276  clock_gettime(CLOCK_MONOTONIC, {6606, 976031257}) = 0
1276  read(5, 0x2ad58224, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  read(6, 0x2ad68a24, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  time(NULL)                        = 1263237575
1276  read(7, 0x2ad6c8e4, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  write(10, "trigger"..., 7)        = 7
1276  poll([{fd=22, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=24, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=25, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=26, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0 <unfinished ...>

Soweit ich sehe, gibt der Log keine Info zum Child Prozess.

 

[olistudent]

War denn der telefon Prozess mit der PID 1276 der Master oder hast du ein Child erwischt? Andererseits sieht man ja im strace Output, dass er geforkt hat!?

MfG Oliver

 

[RalfFriedl]

strace log (nur die letzten Zeilen):
Soweit ich sehe, gibt der Log keine Info zum Child Prozess.

Soweit ich sehe, gibt der Log in den letzten Zeilen keine Info zum Child Prozess.

 

[KlBst]

War denn der telefon Prozess mit der PID 1276 der Master oder hast du ein Child erwischt? Andererseits sieht man ja im strace Output, dass er geforkt hat!?

Das war der Prozess, der sich mit:

 user.err telefon[1276]: SIGCHLD received!

bemerkbar gemacht hat. Up's ... das könnte natürlich auch das "Child" sein. Werde mir das lieber noch einmal ansehen.

Nachtrag: Leider gibt es für "ps" ja keine "-f" Option --> Wie stelle ich fest, wer wessen Kind ist?

Soweit ich sehe, gibt der Log in den letzten Zeilen keine Info zum Child Prozess.

Es gibt in keiner Zeile einen Hinweis. Ich habe die im Ruhezustand erzeugten, sich anfänglich immer wiederholenden Zeilen herausgeschnitten.

Gruß

Klaus

 

[RalfFriedl]

Aus dem Abschnitt oben ergibt sich, daß ein Prozeß 2698 erzeugt und auch wieder beendet wurde. Das muß auch irgendwo im Protokoll vom strace erscheinen.

Und meinst Du hier mit "herausgeschnitten" wiedergegeben oder weggelassen?

 

[KlBst]

"herausgeschnitten" --> Ich habe den langen Anfang des Logs, der nur den Idle Zustand (offensichtlich eine Art Polling) darstellt, nicht wiedergegeben, wohl aber das Ende.

Im strace-Log erscheint kein anderer Prozess!

 

[olistudent]

Aber von dem fork müsste auf alle Fälle was drin stehen. Oder clone() oder was da auch immer gemacht wird.

MfG Oliver

 

[RalfFriedl]

Im strace-Log erscheint kein anderer Prozess!

Ich meine das hier:

/var/media/ftp/uStor01/freetz # strace -f -s200 -p 1276 -o t2.log
Process 1276 attached - interrupt to quit
[B]Process 2698 attached
Process 2698 detached
[/B]Process 1276 detached
/var/media/ftp/uStor01/freetz #

 

[KlBst]

Ich meine das hier:

Ja klar, das habe ich wohl gesehen.
Wie gesagt: Nur der Prozess 1276 erscheint im strace Logfile.

 

[RalfFriedl]

Das wäre sehr seltsam. Häng doch mal die komplette Datei hier an.

 

[KlBst]

Das wäre sehr seltsam. Häng doch mal die komplette Datei hier an.

Gern! Die Aktion:

/var/media/ftp/uStor01/freetz # strace -f -s200 -p 1276 -o t2.log
Process 1276 attached - interrupt to quit
Process 4554 attached  --> Hier wurde der Hörer bei eingehendem Ruf abgehoben
Process 4554 detached --> hier der Hörer aufgelegt
Process 1276 detached --> hier <CTRL>C zum Beenden von strace
/var/media/ftp/uStor01/freetz #

... und der gesamte Log als Anhang.

Danke!

Klaus

 

[olistudent]

1276  read(7, 0x2ad6f0e4, 2048)         = -1 EAGAIN (Resource temporarily unavailable)
1276  write(10, "trigger"..., 7)        = 7
1276  poll([{fd=22, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
1276  poll([{fd=24, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0) = 0 (Timeout)
4554  <... read resumed> ""..., 4095)   = 0
1276  poll([{fd=25, events=POLLERR|POLLHUP|POLLNVAL}], 1, 0 <unfinished ...>
4554  exit(0)                           = ?
1276  <... poll resumed> )              = 0 (Timeout)
1276  --- SIGCHLD (Child exited) @ 0 (0) ---
1276  rt_sigaction(SIGPIPE, {SIG_DFL, [], SA_STACK|SA_INTERRUPT|0x2c609b4}, {0x10000000, [], SA_STACK|SA_INTERRUPT|SA_SIGINFO|0x2ac6ae0}, 16) = 0
1276  time([1263325432])                = 1263325432
1276  getpid()                          = 1276
1276  write(30, "<11>Jan 12 20:43:52 telefon[1276]: SIGCHLD received!\0"..., 53) = 53

Den Log solltest du vielleicht wieder rausnehmen. Da steht eine Telefonnummer von Beckestetts oder so drin. ;-)

MfG Oliver

 

[RalfFriedl]

Und davor wird eine Shell für /var/flash/calllog aufgerufen. Ist das etwas eigenes oder eine Konstruktion von AVM? /var/flash/calllog ist übrigens leer, und deswegen passiert nicht. Der Prozeß beendet sich ohne Fehler. Von daher ist es seltsam, daß eine Meldung ausgegeben wird, nur weil ein Prozeß, der von dem Programm selbst gestartet wurde, auch wieder beendet wird.

 

[KlBst]

Den Log solltest du vielleicht wieder rausnehmen. Da steht eine Telefonnummer von Beckestetts oder so drin. ;-)

MfG Oliver

Ja! Herzlichen Dank!

Nur: Wie lösche ich den Anhang? Mit "Ändern" komme ich nur in den Text

Nachtrag: Ist aber auch nicht sehr problematisch, da auch im Telefonbuch nachzuschlagen

Klaus

 

[olistudent]

Unter Anhänge verwalten kannst du den Anhang löschen.

MfG Oliver