Callmonitor 1.11 - unerklärliches Verhalten

[Telefonmännchen]

Hallo Leute,

ich will den Originalsammelthread zum Callmonitor nicht mir Individualproblemen zumüllen, darum mal ein separater Thread. Zumal das Problem, sollte es ein systematisches sein, mit einer nächsten Version gelöst sein könnte.

Ich habe auf meiner Box innerhalb des Freetz auch den Callmonitor 1.11 laufen. Vor längerer Zeit hatte ich schon mal ein Phänomen, das aber im Rahmen der Fehlersuche verschwunden ist. Heute ist es, nachdem ich gestern meine Box rebooten mußte, wieder da. Bei mir scheint der Callmonitor irgendwie doppelt zu laufen. Zumindest werden alle Aktionen doppelt im Log aufgeführt und auch ausgeführt. Bei der dBox-Information fällt dieses ja nicht unbedingt auf. Ich habe jedoch einen Listener, der mir eine Mail bei einem verpassten Anruf schickt. Diese Mails kommen immer doppelt an (und damit die SMS-Infos meines Mailproviders). Alle Listener sind jeweils nur einfach vorhanden. Dieses Verhalten war nach dem ersten Auftauchen für ein paar Tage verschwunden. Im Anhang mal das anaonymisierte Log eines Anrufes sowie die Ausgabe eines ps auf der Konsole.

Sep 16 09:54:02 fritz user.warn kernel: [avm_power]event: 27 not handled
Sep 16 09:54:02 fritz user.err telefon[548]: '/var/calllog' script not found!
Sep 16 09:54:02 fritz user.err telefon[548]: '/var/flash/calllog' script not found!
Sep 16 09:54:05 fritz daemon.info callmonitor: [1] EVENT=in:request SOURCE='047110815' DEST='123456' SOURCE_NAME='Name des Anrufers' DEST_NAME='Mein Name'
Sep 16 09:54:05 fritz daemon.info callmonitor: [1+] SOURCE_DISP='047110815' DEST_DISP='123456' ID=0 EXT= DURATION= TIMESTAMP='16.09.08 09:54:02' PROVIDER=ISDN
Sep 16 09:54:05 fritz daemon.info callmonitor: [1:0] ACTION: 'dboxpopup 192.168.170.8 " Ankommender Anruf von %0A %0A $SOURCE_NAME %0A $SOURCE %0A %0Afür Privat"'
Sep 16 09:54:05 fritz daemon.info callmonitor: [1:3] ACTION: 'dboxlcd2 192.168.170.8 "%0A %0A $SOURCE_NAME"'
Sep 16 09:54:06 fritz user.info kernel: kdsld: internet: masq_dst_gc: 1 of 1 checked (1 mappings, 1 hash)
Sep 16 09:54:07 fritz daemon.info callmonitor: [1] EVENT=in:request SOURCE='047110815' DEST='123456' SOURCE_NAME='Name des Anrufers' DEST_NAME='Mein Name'
Sep 16 09:54:07 fritz daemon.info callmonitor: [1+] SOURCE_DISP='047110815' DEST_DISP='123456' ID=0 EXT= DURATION= TIMESTAMP='16.09.08 09:54:02' PROVIDER=ISDN
Sep 16 09:54:07 fritz daemon.info callmonitor: [1:0] ACTION: 'dboxpopup 192.168.170.8 " Ankommender Anruf von %0A %0A $SOURCE_NAME %0A $SOURCE %0A %0Afür Privat"'
Sep 16 09:54:07 fritz daemon.info callmonitor: [1:3] ACTION: 'dboxlcd2 192.168.170.8 "%0A %0A $SOURCE_NAME"'
Sep 16 09:54:11 fritz user.warn kernel: [speedup] -> 125 MHz
Sep 16 09:54:16 fritz user.info kernel: kdsld: internet: masq_dst_gc: 1 of 1 checked (1 mappings, 1 hash)
Sep 16 09:54:26 fritz user.info kernel: kdsld: internet: masq_dst_gc: 1 of 1 checked (1 mappings, 1 hash)
Sep 16 09:54:32 fritz user.warn kernel: [avm_power]event: 27 not handled
Sep 16 09:54:33 fritz daemon.info callmonitor: [2] EVENT=in:cancel SOURCE='047110815' DEST='123456' SOURCE_NAME='Name des Anrufers' DEST_NAME='Mein Name'
Sep 16 09:54:33 fritz daemon.info callmonitor: [2+] SOURCE_DISP='047110815' DEST_DISP='123456' ID=0 EXT= DURATION=0 TIMESTAMP='16.09.08 09:54:32' PROVIDER=ISDN
Sep 16 09:54:34 fritz daemon.info callmonitor: [2:4] ACTION: 'mailmessage -t name@provider'
Sep 16 09:54:34 fritz daemon.info callmonitor: [2] EVENT=in:cancel SOURCE='047110815' DEST='123456' SOURCE_NAME='Name des Anrufers' DEST_NAME='Mein Name'
Sep 16 09:54:34 fritz daemon.info callmonitor: [2+] SOURCE_DISP='047110815' DEST_DISP='123456' ID=0 EXT= DURATION=0 TIMESTAMP='16.09.08 09:54:32' PROVIDER=ISDN
Sep 16 09:54:34 fritz daemon.info callmonitor: [2:4] ACTION: 'mailmessage -t name@provider'

Bemerken möchte ich noch, daß ich den Callmonitor wegen Instabilitäten per cron restarten lasse ("1 * * * * /mod/etc/init.d/rc.callmonitor restart"). Das sollte aber hoffentlich nicht die Ursache für dieses Verhalten sein.

/var/mod/root # ps
  PID USER       VSZ STAT COMMAND
    1 root      1168 S    init
    2 root         0 SWN  [ksoftirqd/0]
    3 root         0 SW<  [events/0]
    4 root         0 SW<  [khelper]
    5 root         0 SW<  [kthread]
    6 root         0 SW<  [kblockd/0]
   23 root         0 SW<  [pdflush]
   24 root         0 SW<  [pdflush]
   26 root         0 SW<  [aio/0]
   25 root         0 SW   [kswapd0]
   62 root         0 SW   [pm_info]
   66 root         0 SW<  [CPMAC]
   70 root         0 SW   [mtdblockd]
   96 root         0 SW   [tffsd_mtd_0]
  362 root         0 SW<  [capi_oslib]
  363 root         0 SW<  [capi_oslib]
  364 root         0 SW   [capitransp]
  371 root         0 SW   [glob_codecs]
  386 root         0 SW<  [khubd]
  451 root      8112 S N  /usr/bin/avm/ctlmgr
  487 root      8112 S N  /usr/bin/avm/ctlmgr
  488 root      8112 S N  /usr/bin/avm/ctlmgr
  489 root      8112 S N  /usr/bin/avm/ctlmgr
  522 root      2188 S    usermand
  526 root      2768 S    igdd
  531 root      2388 S    multid
  540 root      2968 S    dsld -i -n
  548 root      4712 S    telefon a127.0.0.1
  551 root      4712 S    telefon a127.0.0.1
  553 root      4288 S <  voipd
  556 root      4712 S    telefon a127.0.0.1
  557 root      4712 S    telefon a127.0.0.1
  558 root      2488 S    pbd
  559 root      2488 S    pbd
  564 root      2488 S    pbd
  565 root      2488 S    pbd
  575 root      3836 S    /bin/avmike
  578 root         0 RWN  [kdsld_token]
  585 root       656 S    /bin/run_clock -c /dev/tffs -d
  596 root      2212 S    /usr/bin/faxd -a
  616 root      1424 S    capiotcp_server -p5031 -m99
  633 root      2768 S    igdd
  634 root      2768 S    igdd
  635 root      2768 S    igdd
  648 root      1184 S    crond -b
  656 root      1168 S    httpd -P /var/run/webcfg.pid -p 81 -c /mod/etc/httpd.
  672 root      1184 S    syslogd -L -C
  674 root      1168 S    /sbin/klogd -c 4
  734 root      4712 S    telefon a127.0.0.1
  735 root      4712 S    telefon a127.0.0.1
  736 root      4712 S    telefon a127.0.0.1
  919 root      1292 S    /bin/ash /usr/sbin/callmonitor
  920 root      1172 S    logger -t callmonitor -p daemon.info
  976 root      1292 S    /bin/ash /usr/sbin/callmonitor
  977 root      1160 S    sleep 20000d
  978 root      1164 S    busybox nc 127.0.0.1 1012
  979 root      1292 S    /bin/ash /usr/sbin/callmonitor
 1056 root      1152 S    dropbear -p 22
 1068 root      1168 S    httpd -P /var/run/webcfg-wol.pid -p 82 -c /mod/etc/ht
 1070 root      1168 S    init
 1097 root      1172 S    logger -t callmonitor -p daemon.info
 1450 root      1172 S    logger -t callmonitor -p daemon.info
 1562 root      1768 S    wpa_authenticator
 1566 root      2476 S    wstart -m 00:04:0E:00:00:00 -p 2731575424769416 -d FR
 1695 root      1172 S    logger -t callmonitor -p daemon.info
 1812 root      1172 S    logger -t callmonitor -p daemon.info
 1935 root      1172 S    logger -t callmonitor -p daemon.info
 2052 root      1172 S    logger -t callmonitor -p daemon.info
 2169 root      1172 S    logger -t callmonitor -p daemon.info
 2286 root      1172 S    logger -t callmonitor -p daemon.info
 2403 root      1172 S    logger -t callmonitor -p daemon.info
 2520 root      1172 S    logger -t callmonitor -p daemon.info
 3141 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3142 root      1172 S    logger -t callmonitor -p daemon.info
 3153 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3154 root      1160 S    sleep 20000d
 3155 root      1168 S    busybox nc 127.0.0.1 1012
 3156 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3246 root      1208 S    dropbear -p 22
 3247 root      1188 S    -sh
 3285 root      1168 R    ps
/var/mod/root #

Was mir auffällt ist, daß einige Sachen mehrfach unter verschieden PIDs laufen. Ob das so sein muß kann ich nicht beurteilen.

Gruß Telefonmännchen

 

[wengi]

Auf meiner 7170 sieht das so aus:

/var/mod/root # ps | grep -i callmonitor
 1135 root      1296 S    /bin/ash /usr/sbin/callmonitor
 1136 root      1160 S    logger -t callmonitor -p daemon.info
 1163 root      1296 S    /bin/ash /usr/sbin/callmonitor
 1165 root      1296 S    /bin/ash /usr/sbin/callmonitor
 1167 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3508 root      1156 S    grep -i callmonitor

Callmonitor läuft bei mir ohne jegliches Problem und führt alles auch nur ein mal aus.
Dennoch läuft er momentan, also ohne aktivität auf den Leitungen, vier mal.

wengi

 

[buehmann]

Hi,

bei wengi sieht alles richtig aus: Mehrere (3 bis 5) Prozesse mit dem Namen "callmonitor" sind ganz normal; sie stellen u.a. mehrere Teile einer Pipe da, die im Callmonitor abläuft.

Bei Telefonmännchen ist allerdings etwas gründlich schiefgegangen. Auffällig sind über die 2 Instanzen des Haupt-Callmonitors hinaus das zehnfache Auftauchen des Logger-Prozesses (davon gibt es normalerweise nur einen Logger pro laufendem Callmonitor (und der läuft natürlich normalerweise auch nur einmal zur Zeit)).

Das ganze scheint aber nicht nur ein Callmonitor-Problem zu sein: Die AVM-Komponenten laufen auch mehrfach: Sieben telefon-Prozesse parallel habe ich noch nie gesehen. (4 x igdd ist glaube ich normal, bei 4 x ctlmgr bin ich mir nicht sicher).

Andreas

 

[Telefonmännchen]

Hmmm....
Das irritiert mich schon etwas. Bis vor kurzem hatte ich noch eine normale Freetz-1.0-Version auf der Box. Da ist mir das mit der doppelten Mail auch schon mal aufgefallen. Das Freetz-Update habe ich allerdings ohne Neueingabe der Daten gemacht. Es wurde alles von vorher übernommen. Der aktuelle Freetz-Mod ist ein stable branch (wegen der Laborfirmware). Ich werde auf alle Fälle die Box mal durchbooten. Ich habe sie bis jetzt laufen lassen, falls noch jemand eine Idee hätte, wo man eventuell noch nachschauen kann.

Im Moment sieht ein ps auf der Konsole sogar so aus:

/var/mod/root # ps
  PID USER       VSZ STAT COMMAND
    1 root      1168 S    init
    2 root         0 RWN  [ksoftirqd/0]
    3 root         0 SW<  [events/0]
    4 root         0 SW<  [khelper]
    5 root         0 SW<  [kthread]
    6 root         0 SW<  [kblockd/0]
   23 root         0 SW<  [pdflush]
   24 root         0 SW<  [pdflush]
   26 root         0 SW<  [aio/0]
   25 root         0 SW   [kswapd0]
   62 root         0 SW   [pm_info]
   66 root         0 SW<  [CPMAC]
   70 root         0 SW   [mtdblockd]
   96 root         0 SW   [tffsd_mtd_0]
  362 root         0 SW<  [capi_oslib]
  363 root         0 SW<  [capi_oslib]
  364 root         0 SW   [capitransp]
  371 root         0 SW   [glob_codecs]
  386 root         0 SW<  [khubd]
  451 root      8160 S N  /usr/bin/avm/ctlmgr
  487 root      8160 S N  /usr/bin/avm/ctlmgr
  488 root      8160 S N  /usr/bin/avm/ctlmgr
  489 root      8160 S N  /usr/bin/avm/ctlmgr
  522 root      2224 S    usermand
  526 root      2768 S    igdd
  540 root      2968 S    dsld -i -n
  548 root      4712 S    telefon a127.0.0.1
  551 root      4712 S    telefon a127.0.0.1
  553 root      4288 S <  voipd
  556 root      4712 S    telefon a127.0.0.1
  557 root      4712 S    telefon a127.0.0.1
  558 root      2488 S    pbd
  559 root      2488 S    pbd
  564 root      2488 S    pbd
  565 root      2488 S    pbd
  575 root      3836 S    /bin/avmike
  578 root         0 RWN  [kdsld_token]
  585 root       656 S    /bin/run_clock -c /dev/tffs -d
  596 root      2212 S    /usr/bin/faxd -a
  616 root      1504 S    capiotcp_server -p5031 -m99
  633 root      2768 S    igdd
  634 root      2768 S    igdd
  635 root      2768 S    igdd
  648 root      1184 S    crond -b
  656 root      1168 S    httpd -P /var/run/webcfg.pid -p 81 -c /mod/etc/httpd.
  672 root      1184 S    syslogd -L -C
  674 root      1168 S    /sbin/klogd -c 4
  734 root      4712 S    telefon a127.0.0.1
  735 root      4712 S    telefon a127.0.0.1
  736 root      4712 S    telefon a127.0.0.1
  919 root      1292 S    /bin/ash /usr/sbin/callmonitor
  920 root      1172 S    logger -t callmonitor -p daemon.info
  976 root      1292 S    /bin/ash /usr/sbin/callmonitor
  977 root      1160 S    sleep 20000d
  978 root      1164 S    busybox nc 127.0.0.1 1012
  979 root      1292 S    /bin/ash /usr/sbin/callmonitor
 1056 root      1152 S    dropbear -p 22
 1068 root      1168 S    httpd -P /var/run/webcfg-wol.pid -p 82 -c /mod/etc/ht
 1070 root      1168 S    init
 1097 root      1172 S    logger -t callmonitor -p daemon.info
 1450 root      1172 S    logger -t callmonitor -p daemon.info
 1562 root      1768 S    wpa_authenticator
 1566 root      2476 S    wstart -m 00:04:0E:00:00:00 -p 2731575424769416 -d FR
 1695 root      1172 S    logger -t callmonitor -p daemon.info
 1812 root      1172 S    logger -t callmonitor -p daemon.info
 1935 root      1172 S    logger -t callmonitor -p daemon.info
 2052 root      1172 S    logger -t callmonitor -p daemon.info
 2169 root      1172 S    logger -t callmonitor -p daemon.info
 2286 root      1172 S    logger -t callmonitor -p daemon.info
 2403 root      1172 S    logger -t callmonitor -p daemon.info
 2520 root      1172 S    logger -t callmonitor -p daemon.info
 3142 root      1172 S    logger -t callmonitor -p daemon.info
 3562 root      1172 S    logger -t callmonitor -p daemon.info
 3918 root      1172 S    logger -t callmonitor -p daemon.info
 1047 root      1172 S    logger -t callmonitor -p daemon.info
 1169 root      1172 S    logger -t callmonitor -p daemon.info
 1240 root      2412 S    multid
 1628 root      1172 S    logger -t callmonitor -p daemon.info
 1821 root      1172 S    logger -t callmonitor -p daemon.info
 2150 root      1172 S    logger -t callmonitor -p daemon.info
 2268 root      1172 S    logger -t callmonitor -p daemon.info
 2790 root      1172 S    logger -t callmonitor -p daemon.info
 3403 root      1172 S    logger -t callmonitor -p daemon.info
 3520 root      1172 S    logger -t callmonitor -p daemon.info
 3637 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3638 root      1172 S    logger -t callmonitor -p daemon.info
 3649 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3650 root      1160 S    sleep 20000d
 3651 root      1168 S    busybox nc 127.0.0.1 1012
 3652 root      1296 S    /bin/ash /usr/sbin/callmonitor
 3653 root      1208 S    dropbear -p 22
 3654 root      1188 S    -sh
 3689 root      1168 R    ps

Es sind sogar noch ein paar Logger weiter dazugekommen. Es wurden in der Zwischenzeit sechs gehende Gespräche, ein kommendes und ein Anruf bei Besetzt geführt. Das legt den Verdacht nahe, daß das immer wieder weitere gestartet werden, wenn ein Gespräch geführt wird oder wenn der Callmonitor restartet wird. Darum kann ich mich aber erst morgen kümmern. Ich muß für heute in die Waagerechte. Trotzdem erst mal danke.

Gruß Telefonmännchen

 

[hermann72pb]

Ist das nicht dieses alte Problem mit dem nicht bis zu Ende durchgelaufenen Boot-Prozess der Box?

Z.B. eine Endlosschleife in debug.cfg? Oder was ähnliches?

Das hatte ich schon mal gehabt. Schuld waren alte "Leichen" in debug.cfg von den Modifikationen "vor dem mod".

MfG

 

[Telefonmännchen]

Der Speedport war vor meiner Modifikation absolut jungfräulich und hatte nur Betriebsstunden im einstelligen Bereich drauf. Kann aber sein, daß die T-Com da was drin hat. Das schaue ich mir mal an. Eigentlich sollte das leer sein. Vor dem Aufspielen des "alten" Freetz 1.0 hat er aber einen Werksreset erhalten. Beim "Update" auf den stable branch jetzt aber nicht. Da wurden alle Sachen, sowohl AVM-FW als auch Freetz betreffend übernommen. Die Doppelmailsymptomatik hatte ich aber auch schon mal beim 1.0. Vielleicht war da schon was verbogen. Danke erst mal.

Gruß Telefonmännchen


UPDATE:
Weil ich noch testen wollte habe ich bis jetzt nicht neu gebootet, mich dafür aber per PuTTY mal ein wenig auf der Box umgesehen. Aufgefallen ist mir da erst mal nichts. Allerdings stecke ich auch nicht so tief in der Materie drin. Der Logger des Callmonitors läuft jetzt zur Zeit 24 mal. Mit jedem Anruf kommt scheinbar einer dazu. Das irritiert mich schon irgendwie.

Alle Listener sind auch nur einfach aufgeführt (kann also schon mal nicht der Grund für die doppelte Abarbeitung sein). Ansonsten ist mir im Status-Log des Freetz aufgefallen, daß das Fehlen der "/var/cache/phonebook/avm" und "/etc/default.Fritz_Box_DECT_W900V/avm/ar7.cfg" mit "No such file or directory" bemängelt wird. Beide sind jedoch an den angegebenen Stellen vorhanden und auch lesbar.

Allerdings wird mir das Syslog mit der Meldung "fritz user.info kernel: kdsld: internet: masq_dst_gc: 7 of 7 checked (6 mappings, 6 hash)" vollgemüllt, wobei die Zahlen etwas variieren. Da das nur eine Info ist, messe ich dem mal keine Bedeutung bei. Vielleicht kann sich einer der Profis mal äußern, was das ist. Mehr konnte ich auch noch nicht rausbekommen.

 

[buehmann]

Der Logger des Callmonitors läuft jetzt zur Zeit 24 mal. Mit jedem Anruf kommt scheinbar einer dazu.

Ich glaube, es hat keinen Sinn, weiterhin Loggers anzusammeln. Deine Box ist zumindest bezüglich des Callmonitors ja bereits in einem falschen Zustand und beim "restart" scheint der jeweils aktuelle Logger nicht beendet zu werden.

Interessanter wäre aus meiner Sicht jetzt, ob du die ganze Geschichte reproduzieren kannst, also ob das Problem nach einem Reboot wieder auftritt (oder nach manuellem Beenden und Aufräumen all dessen, was mit dem Callmonitor zusammenhängt).

Gruß,
Andreas

 

[Telefonmännchen]

Danke für Deine Antwort. Ich habe die Box jetzt mal rebootet. Ein ps auf der Konsole sieht bezüglich des Callmonitors eigentlich ganz normal aus.

  PID USER       VSZ STAT COMMAND
    1 root      1168 S    init       
    2 root         0 SWN  [ksoftirqd/0]
    3 root         0 SW<  [events/0]
    4 root         0 SW<  [khelper]
    5 root         0 SW<  [kthread]
    6 root         0 SW<  [kblockd/0]
   23 root         0 SW<  [pdflush]
   24 root         0 SW<  [pdflush]
   26 root         0 SW<  [aio/0]
   25 root         0 SW   [kswapd0]
   62 root         0 SW   [pm_info]
   66 root         0 SW<  [CPMAC]
   70 root         0 SW   [mtdblockd]
   96 root         0 SW   [tffsd_mtd_0]
  362 root         0 SW<  [capi_oslib]
  363 root         0 SW<  [capi_oslib]
  364 root         0 SW   [capitransp]
  371 root         0 SW   [glob_codecs]
  386 root         0 SW<  [khubd]
  459 root      7420 S N  /usr/bin/avm/ctlmgr 
  473 root      1764 S    wpa_authenticator 
  488 root      2476 S    wstart -m 00:04:0E:00:00:00 -p 2731575424769416 -d FR
  489 root      7420 S N  /usr/bin/avm/ctlmgr 
  490 root      7420 S N  /usr/bin/avm/ctlmgr 
  491 root      7420 S N  /usr/bin/avm/ctlmgr 
  520 root      2184 S    usermand 
  528 root      2768 S    igdd 
  533 root      2384 S    multid 
  542 root      2968 S    dsld -i -n 
  550 root      4712 S    telefon a127.0.0.1 
  553 root      4712 S    telefon a127.0.0.1 
  555 root      4284 S <  voipd 
  558 root      2488 S    pbd 
  562 root      4712 S    telefon a127.0.0.1 
  563 root      4712 S    telefon a127.0.0.1 
  564 root      2488 S    pbd 
  566 root      2488 S    pbd 
  567 root      2488 S    pbd 
  577 root      3836 S    /bin/avmike 
  580 root         0 RWN  [kdsld_token]
  588 root       656 S    /bin/run_clock -c /dev/tffs -d 
  612 root      2212 S    /usr/bin/faxd -a 
  620 root      1424 S    capiotcp_server -p5031 -m99 
  626 root      2768 S    igdd 
  627 root      2768 S    igdd 
  628 root      2768 S    igdd 
  650 root      1180 S    crond -b 
  658 root      1168 S    httpd -P /var/run/webcfg.pid -p 81 -c /mod/etc/httpd.
  677 root      1184 S    syslogd -L -C 
  679 root      1168 S    /sbin/klogd -c 4 
  689 root      4712 S    telefon a127.0.0.1 
  692 root      4712 S    telefon a127.0.0.1 
  693 root      4712 S    telefon a127.0.0.1 
  988 root      1152 S    dropbear -p 22 
 1000 root      1168 S    httpd -P /var/run/webcfg-wol.pid -p 82 -c /mod/etc/ht
 1002 root      1168 S    init       
 1104 root      1296 S    /bin/ash /usr/sbin/callmonitor 
 1105 root      1172 S    logger -t callmonitor -p daemon.info 
 1116 root      1296 S    /bin/ash /usr/sbin/callmonitor 
 1117 root      1160 S    sleep 20000d 
 1118 root      1168 S    busybox nc 127.0.0.1 1012 
 1119 root      1296 S    /bin/ash /usr/sbin/callmonitor 
 1176 root      1188 S    httpd -P /var/run/webcfg.pid -p 81 -c /mod/etc/httpd.
 1177 root       872 S    /usr/bin/haserl -u -U /var/tmp rudi_shellcmd.cgi 
 1178 root      1180 S    /bin/sh 
 1182 root      1172 S    sh 
 1183 root      1168 S    sed -e s/&/\&amp;/g ; s/</\&lt;/g ; s/>/\&gt;/g 
 1184 root      1164 S    head -c 64000 
 1185 root      1172 R    ps

Ein verpasster Anruf von meinem Handy brachte auch nur eine Mail. So wie es sein soll. Jetzt werde ich mal rumtelefonieren und abwarten, ab wann das Problem wieder auftritt.

Gruß Telefonmännchen

 

[Telefonmännchen]

Statusbericht:
So, reproduzieren konnte ich den Fehler, wenn ich auch der Ursache bis auf eine einzige Auffälligkeit nicht wirklich näher gekommen zu sein scheine. Seit heute ist wieder alles so, wie es war (doppelte Anruferinfo, doppelte Mail). Es fiel mir auf, weil bei einem eingehenden Anruf die Info zwei mal auf der dBox ausgegeben wurde. Das fällt einem nur auf, wenn man genau hinschaut. Verpasste Anrufe hatte ich bis dahin keine. Ein ps auf der Konsole brachte mir wieder 20 laufende logger.

In der Zwischenzeit hat die Box ein mal neu gebootet. Dieser Reboot wurde durch das Entmagnetisieren meines Fernsehers beim Einschalten ausgelöst. Irgendwie scheint der beim Einschalten dann viel Strom zu ziehen, oder Oberwellen zu produzieren, die das Netzteil der Box nicht verträgt, was die Box zum Abstürzen brachte. Sonstige Nebeneffekte habe ich an anderen Geräten dadurch nicht. Ich glaube, ich muß mal langsam über eine USV nachdenken. Das Booten ist aber auch der einzige Zwischenfall beim Betrieb der Box und sollte nicht die Fehlerursache sein. Keine sonstigen ungewöhnlichen Aktivitäten meinerseits. Ich habe die Box ganz bewußt in Ruhe gelassen. Nur ganz normales Surfen, Mailverkehr und Remotecontrolling eines anderen Rechners 650km entfernt. Dazu ganz normaler ein- und ausgehender Telefonverkehr. Keine RUL oder AWS, nichts besonderes. Das einzige was mir auffällt ist, daß es vor 19 Anrufen einen Anruf ohne Rufnummernübermittlungen gegeben hat, der angenommen wurde. Sonst kommen die Anrufe größtenteils mit Übermittlung rein. Beim letzen Mal, wurde pro Anruf ein zusätzlicher weiterlaufender Logger im System hinterlassen. Das ist aber auch die einzige Auffälligkeit. Kann es sein, daß sich die Box bei Anrufen ohne CLIP verschluckt? Aber das ist Glaskugelmodus.

Gruß Telefonmännchen

 

[hermann72pb]

Ich sag dir, weil ich zufällig von den Netzteilen Ahnung habe...

Es ist nicht normal, dass die Box darauf so sensibel reagiert. Hast du noch eine andere Box, dass du dein Netzteil mal tauschen könntest?

Verwendest du vielleicht eine dieser billig-made-in-china Mehrfachsteckdosen, wo alles dran hängt? Im Normalfall MUSST du ein relativ starres Netz haben, sodass egal welche Entmagnetisierung da hinter hängt, auch ein "schwächeres" Netzteil damit klar kommen sollte.

Wenn es am Netzteil liegen sollte, tausche es direkt bei AVM aus. Die sind diesbezüglich sehr kulant und fragen nicht mal, woher du die Box hast.

Wenn dein Netzteil so "empfindlich" ist, will ich gar nicht wissen wie viele "Mikroinfarkte" deine FritzBox überlebt, ohne dass du es merkst.

MfG

 

[Telefonmännchen]

Das mit dem Netzteil war nur so eine Vermutung. Ich werde das mal tauschen. Ich habe hier noch ein paar andere zur Auswahl (7050, W701V, W900V, und uralte Erst-Generations-FritzBox) Muß mal die Daten vergleichen, was am besten passt.

Die Beeinflussung kann aber auch durchaus über Potentialverschleppungen oder Induktionen in irgendwelche Kabelschlaufen kommen. Ich bin dem noch nicht weiter nachgegangen. Aber hinter meinem Fernsehrack tummelt sich so manche Kabelverbindung, angefangen von dBox, Paystation, Switch, HiFi-Anlage und was weiß ich noch. Der Fehlerquellen sind da viele und auf Glasfaser umzurüsten ist mir zu teuer. Und jedes Gerät hat da noch sein Netzteil, über das es mir irgendwelche Störungen einkoppeln kann. Ich glaube, ich fange mal mit dem Netzteil der Box an.

Letztenendes dürften das aber nicht die Ursache für mein ursprüngliches Problem sein, denn ein Spannungsimpuls dürfte kaum reproduzierbar irgendwelche Programme starten. Da muß es einen anderen softwarebasierten Grund geben. Dem bin ich aber leider immer noch nicht näher. Trotzdem, Danke für Deine Antwort.

Gruß Telefonmännchen

UPDATE:
Auch heute ein absolut unauffälliges ps auf der Konsole. Wie immer 7 telefon-Tasks und 1 callmonitor-logger. Ich überwache weiter.

Nochmal Update:
Der Fehler mit dem Reboot beim Einschalten des Fernsehers hat sich (hoffentlich) geklärt. Aus irgendeinem Grunde habe ich an der Box noch das Netzteil der 7050 mit 1A gehabt. Das originale des Speedportes hat 1,5A. Ich denke mal, das dürfte geklärt sein. An dem Anderen bin ich dran. Bis dato kein Auffälligkeiten.

 

[Telefonmännchen]

So, nachdem die Box 14 Tage ohne besondere Auffälligkeiten lief (keine doppelten callmonitor-Prozesse, keine mehrfachen logger und keine Reboots beim Einschalten des Fernsehers!) kam es zu einem Absturz bei einem doppelt gleichzeitigen Anruf auf eine MSN. Die Box hat dann automatisch neu gebootet. Seit dem hatte ich wieder die mehrfachen Callmonitor-Prozesse und auch doppelte Mailinformation und doppelte Anzeige an der dBox und auch die verbleibenden logger. Dieses Verhalten ist auch nach mehrfachem Reboot zu reproduzieren.

Was mir auffält ist, daß die vom CM gestarteten logger auch bei einem manuellen Stop/Restart des Prozesses im System verbleiben. Sollten diese nicht auch beendet werden? Darum vermehren die sich auch bei einem Restart des CM. Eben gerade ausprobiert. Ist also reproduzierbar.

Ich restarte ja wie oben im ersten Post beschrieben den CM zyklisch. Jetzt habe ich noch ein "1 * * * * killall logger" vor den restart-Befehl in die crontab gesetzt um die logger-Vermehrung mal einzudämmen. Was ich mir da für Nebeneffekte einhandle weiß ich noch nicht. Wo kann ich noch suchen?

Ich habe neulich auch schon mal versucht, mir ein neues stable-Freetz-1.0-Image mit manueller Integration des CM-Ver. 1.12.3 zu bauen. Leider wird das das Image zu groß für meinen Flash bei identischer Packetauswahl wie mein jetziges Image (enthaltenen CM natürlich abgewählt). Ich habe dann mal Remove tr069-stuff und den Assitenten angewählt um Platz zu schaffen. Auf dem dann erstellten Image hatte ich keinen Zugriff mehr aufs normale Web-IF der Box. Das Freetz-IF funktionierte problemlos. Habe dann mein "altes" Image wieder geflasht, weil mir die Zeit für weitere Experimente nicht reichte. Irgendetwas ist bei mir verbogen, nur was?

Gruß Telefonmännchen

 

[buehmann]

Hi,

Seit dem hatte ich wieder die mehrfachen Callmonitor-Prozesse

direkt nach dem Reboot? Reproduzierbar? Irgendetwas muss bei dir nicht stimmen (bisher bist du auch der einzige, der von so etwas berichtet).

Was mir auffält ist, daß die vom CM gestarteten logger auch bei einem manuellen Stop/Restart des Prozesses im System verbleiben. Sollten diese nicht auch beendet werden?

Ja, sollten sie und werden sie normalerweise auch. Wenn du erst in einem Fehlerzustand bist, ist es aber nicht verwunderlich, dass dann weitere Fehler reproduzierbar sind.

Wo kann ich noch suchen?

Du könntest den regelmäßigen Restart des Callmonitors entfernen und bei der Suche nach der Ursache für Instabilitäten mithelfen, anstatt die Symptome zu bekämpfen. Wir hatten schon Berichte, dass stellenweise die Box 14 Tage problemlos durchläuft, bevor sie sich wieder mal aufhängt. Izzy konnte die Aufhänger verhindern (oder in der Häufigkeit verringern), indem er einen Hitzestau der Box vermieden hat. Nach seiner Hypothese könnte es sich um ein Hardwareproblem handeln, das durch die zusätzliche Last, die der Callmonitor bei Anrufen verursacht, zu Tage tritt.

Grüße,
Andreas

 

[Telefonmännchen]

Erste mal danke für Deine Antwort.

Du könntest den regelmäßigen Restart des Callmonitors entfernen und bei der Suche nach der Ursache für Instabilitäten mithelfen, anstatt die Symptome zu bekämpfen.

Gern, aber leider scheitert dieses an einem recht niedrigen WAF. Das Problem ist, daß da auch die Geschäftsnummer meiner Frau über unseren ISDN-Anschluß und somit über die Box läuft. Wenn dann nun die Box, wie vor meinem Eingriff bereits mehrfach geschehen, bei Kundenanrufen ein Eigenleben entwickelt und durch Reboots das Telefonieren unmöglich macht, bzw. bestehende Gespräche unterbricht, ist das dem WAF nicht gerade förderlich. Darum kämpfe ich lieber im Moment mit Symptomen, als den Kampf ganz zu verlieren. Das Merkwürdige ist ja, daß es manchmal funktioniert. Im Moment auch ein ganz normales Bild bei einer Prozessabfrage. Ende des Monats ist sie mal übers Wochenende weg, da kann ich derartige Versuche fahren.

Izzy konnte die Aufhänger verhindern (oder in der Häufigkeit verringern), indem er einen Hitzestau der Box vermieden hat...
...Hardwareproblem handeln, das durch die zusätzliche Last, die der Callmonitor bei Anrufen verursacht.

Hitzeprobleme kann ich fast ausschließen. Die Box hängt frei an der Wand und hat eine gute Luftzirkulation. Auch ist sie nicht übermäßig warm. Nur im oberen Bereich ist sie etwas wärmer (handwarm). Sonst hat sie Zimmertemperatur. Auch übermäßige Last scheint nicht drauf zu sein, denn ich bekomme im Syslog das Rauf- und Runterschalten der Taktfrequenz gemeldet.
Die Ausgabe von top auf der Konsole

Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   0% usr   0% sys   0% nice  98% idle   0% io   0% irq   0% softirq
Load average: 0.00 0.00 0.00
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   2% top
  480     1 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  528     1 root     S     2768   9%   0% igdd
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
  560     1 root     S     2488   8%   0% pbd

und bei einem laufenden Telefongespräche

  717   553 root     S     4712  16%   0% telefon a127.0.0.1
Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   1% usr   2% sys   0% nice  95% idle   0% io   0% irq   0% softirq
Load average: 0.18 0.12 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   3% top
  415   989 root     S     1208   4%   1% dropbear -p 22
  480     1 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  528     1 root     S     2768   9%   0% igdd
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   1% usr   2% sys   0% nice  95% idle   0% io   0% irq   0% softirq
Load average: 0.16 0.12 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   2% top
  415   989 root     S     1208   4%   1% dropbear -p 22
  480     1 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  528     1 root     S     2768   9%   0% igdd
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   1% usr   1% sys   0% nice  96% idle   0% io   0% irq   0% softirq
Load average: 0.15 0.12 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   3% top
  415   989 root     S     1208   4%   0% dropbear -p 22
  480     1 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8168  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     R     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  528     1 root     S     2768   9%   0% igdd
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   1% usr   2% sys   0% nice  95% idle   0% io   0% irq   0% softirq
Load average: 0.14 0.11 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   3% top
  415   989 root     S     1208   4%   1% dropbear -p 22
  480     1 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  528     1 root     S     2768   9%   0% igdd
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
Mem: 28276K used, 1984K free, 0K shrd, 996K buff, 8252K cached
CPU:   1% usr   2% sys   0% nice  94% idle   0% io   0% irq   1% softirq
Load average: 0.13 0.11 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   3% top
  528     1 root     S     2768   9%   2% igdd
  415   989 root     S     1208   4%   1% dropbear -p 22
  480     1 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
  623   528 root     S     2768   9%   0% igdd
  624   623 root     S     2768   9%   0% igdd
  625   623 root     S     2768   9%   0% igdd
Mem: 29012K used, 1248K free, 0K shrd, 968K buff, 8188K cached
CPU:  11% usr  14% sys   0% nice  57% idle   0% io   0% irq  15% softirq
Load average: 0.12 0.11 0.04
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  550     1 root     S     4712  16%   4% telefon a127.0.0.1
  451   416 root     R     1172   4%   3% top
 4076  4060 root     S     1296   4%   2% /bin/ash /usr/sbin/callmonitor --debug
  415   989 root     S     1208   4%   1% dropbear -p 22
  363     5 root     SW<      0   0%   1% [capi_oslib]
   70     1 root     SW       0   0%   0% [mtdblockd]
  604   480 root     S     1424   5%   0% capiotcp_server -p5031 -m99
  480     1 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike
  542     1 root     S     2968  10%   0% dsld -i -n
Mem: 28088K used, 2172K free, 0K shrd, 884K buff, 7832K cached
CPU:  31% usr  23% sys   0% nice  22% idle   0% io   0% irq  22% softirq
Load average: 0.43 0.17 0.06
  PID  PPID USER     STAT   VSZ %MEM %CPU COMMAND
  451   416 root     R     1172   4%   3% top
  677     1 root     S     1184   4%   1% syslogd -L -C
 4062  4060 root     S     1172   4%   1% logger -t callmonitor -p daemon.debug
 4061  4060 root     S     1172   4%   0% logger -t callmonitor -p daemon.info
  533     1 root     S     2388   8%   0% multid
  415   989 root     S     1208   4%   0% dropbear -p 22
   25     1 root     SW       0   0%   0% [kswapd0]
  480     1 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  489   480 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  491   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  490   489 root     S N   8164  27%   0% /usr/bin/avm/ctlmgr
  550     1 root     S     4712  16%   0% telefon a127.0.0.1
  714   553 root     S     4712  16%   0% telefon a127.0.0.1
  554   553 root     S     4712  16%   0% telefon a127.0.0.1
  555   553 root     S     4712  16%   0% telefon a127.0.0.1
  553   550 root     S     4712  16%   0% telefon a127.0.0.1
  718   553 root     S     4712  16%   0% telefon a127.0.0.1
  717   553 root     S     4712  16%   0% telefon a127.0.0.1
  557     1 root     S <   4280  14%   0% voipd
  570     1 root     S     3836  13%   0% /bin/avmike

Gruß Telefonmännchen

 

[buehmann]

Gern, aber leider scheitert dieses an einem recht niedrigen WAF.

OK, akzeptiert. Das Herumprobieren geht natürlich nur, wenn nicht jemand anderes auf das Funktionieren der Box angewiesen ist.

Gruß,
Andreas