[Gelöst] "onlinechanged" wird manchmal nicht ausgeführt

[kriegaex]

Hast Du DnyDNS aktiv? Wenn ja, wurde den Eintrag aktualisiert?

Ja und ja. Das passiert zuverlässig, unabhängig davon, ob Onlinechanged ausgeführt wird oder nicht.

Die IP hat übrigens gewechselt, sie ist nicht gleich geblieben.

Oh, und an AVM habe ich das gestern mal gemailt. Noch keine Antwort, außer daß sie Debug-Logs haben wollten. Die habe ich auch geschickt und dabei auch die Hosen herunter gelassen, also geschrieben, daß ich Freetz nutze. Ich erwähnte aber auch, daß das Phänomen auch ohne Freetz mit in debug.cfg erzeugtem Onlinechanged-Skript auftritt.

Update: In den letzten beiden Nächten ist wieder mal gar nichts passiert bzgl. Onlinechanged: wie gehabt, Neuverbindung mit neuer IP, DynDNS klappt, aber keine Skripten werden ausgeführt.

 

[SaschaBr]

Es ist doch zum verrückt werden: Seit ich die 05.07er Labor auf meiner 7270 hatte, trat das Problem nicht mehr auf.
Am Donnerstag ist dann meine neue 7390 angekommen, welche natürlich auch gefreezt wurde. Hier habe ich allerdings (weil ich gehofft hatte, AVM hat das in der 07er behoben) auf die die Erweiterungen in onlinechanged.sh verzichtet.
Und was ist? Heute nacht, bei der Zwangstrennung, wieder einmal (bzw. das erste mal mit der 7390) gar kein Onlinechanged. Auch nach einem Klick im AVM-WebIf auf "neu verbinden" keine reaktion.
Habe dann onlinechanged offline und ... online in der Konsole ausgeführt.

 

[kriegaex]

Bei mir ähnlich wie bei Sascha. Nie ein Onlinechanged bei "Neu verbinden", ansonsten je nach Tagesform der Box. Gestern hatte ich wenigstens mal einen anderen Fall, bei dem es zwar ging, aber im Unterschied zu sonst nicht beide Event-Ketten (online und offline) komplett durchliefen, sondern, da offenbar "/bin/onlinechanged offline" noch lief, als "/bin/onlinechanged online" gestartet werden sollte, ersteres gekillt wurde, was man dann auch im (ungewohnt kurzen) Strace-Log des Multid sieht:

15237 04:47:01.464514 clock_gettime(CLOCK_MONOTONIC, {758814, 454598955}) = 0
15237 04:47:01.465525 wait4(17856, 0x7f8f6460, WNOHANG, NULL) = 0
15237 04:47:01.466220 wait4(17856, 0x7f8f6460, WNOHANG, NULL) = 0
15237 04:47:01.466812 clock_gettime(CLOCK_MONOTONIC, {758814, 456614772}) = 0
15237 04:47:01.467428 poll([{fd=3, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=5, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=6, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=7, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=8, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=9, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=10, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=12, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=14, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=15, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=16, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=17, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=18, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=19, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND|0x2000}, {fd=20, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=21, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}, {fd=24, events=POLLIN|POLLRDNORM|POLLRDBAND|0x2000}], 18, 692) = -1 EINTR (Interrupted system call)
15237 04:47:02.158687 --- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=17856, si_status=0, si_utime=3, si_stime=1} (Child exited) ---
15237 04:47:02.159525 clock_gettime(CLOCK_MONOTONIC, {758815, 149525510}) = 0
15237 04:47:02.160417 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.161092 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.161801 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.162460 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.163130 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.163810 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0xffffffff) = 0
15237 04:47:02.164471 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x2ac3c5f0) = 0
15237 04:47:02.165171 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.165855 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.166510 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.167166 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.167826 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.168479 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.170705 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0xffffffff) = 0
15237 04:47:02.171465 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x2ac3c5f0) = 0
15237 04:47:02.172126 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.172791 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.173453 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.174160 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0xffffffff) = 0
15237 04:47:02.174831 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.175497 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.176210 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0xffffffff) = 0
15237 04:47:02.176868 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x2ac3c5f0) = 0
15237 04:47:02.177527 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.178142 time(NULL)        = 1317264422
15237 04:47:02.179625 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.180355 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x2ac3c1b4) = 0
15237 04:47:02.181014 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.181673 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x2ac3c1b4) = 0
15237 04:47:02.182356 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.183026 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.183684 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0xffffffff) = 0
15237 04:47:02.184364 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.185352 sendto(3, "\x46\x20\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00\x08\x6b\x72\x69\x65\x67\x61\x65\x78\x06\x64\x79\x6e\x64\x6e\x73\x03\x6f\x72\x67\x00\x00\x01\x00\x01", 37, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.180.1")}, 16) = 37
15237 04:47:02.187612 open("/var/tmp/ddnsstatnew.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 25
15237 04:47:02.188600 ioctl(25, TIOCNXCL, 0x7f8f62f0) = -1 ENOTTY (Inappropriate ioctl for device)
15237 04:47:02.195642 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.196352 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x25) = 0
15237 04:47:02.197226 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.202723 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x25) = 0
15237 04:47:02.203446 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.204111 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.204770 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x4) = 0
15237 04:47:02.205442 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.206177 write(25, "1 672533 kriegaex.dyndns.org\n", 29) = 29
15237 04:47:02.206961 close(25)         = 0
15237 04:47:02.207647 rename("/var/tmp/ddnsstatnew.txt", "/var/tmp/ddnsstat.txt") = 0
15237 04:47:02.208638 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.209768 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x30) = 0
15237 04:47:02.210739 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.211437 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x30) = 0
15237 04:47:02.212093 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.212815 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.213473 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x7f8f63c8) = 0
15237 04:47:02.214132 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.214795 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.215490 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x30) = 0
15237 04:47:02.216166 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.216834 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x30) = 0
15237 04:47:02.217494 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.218159 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.218826 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x7f8f63c8) = 0
15237 04:47:02.219887 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.220526 time(NULL)        = 1317264422
15237 04:47:02.221166 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.221837 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x30) = 0
15237 04:47:02.222499 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0) = 0
15237 04:47:02.223162 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x30) = 0
15237 04:47:02.223821 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.224492 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0) = 0
15237 04:47:02.225151 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x7f8f63c8) = 0
15237 04:47:02.225952 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0) = 0
15237 04:47:02.226615 time(NULL)        = 1317264422
[B][COLOR="red"]15237 04:47:02.227218 open("/var/run/onlinestat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 25
[/COLOR][/B]15237 04:47:02.228042 ioctl(25, TIOCNXCL, 0x7f8f6338) = -1 ENOTTY (Inappropriate ioctl for device)
15237 04:47:02.229039 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.236261 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x1) = 0
15237 04:47:02.236919 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.237598 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x1) = 0
15237 04:47:02.238420 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
15237 04:47:02.239100 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x442cc0) = 0
15237 04:47:02.240222 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x10000) = 0
15237 04:47:02.240883 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
15237 04:47:02.241743 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.242715 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x1) = 0
15237 04:47:02.243408 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.244106 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x1) = 0
15237 04:47:02.244770 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
15237 04:47:02.245435 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x442cc0) = 0
15237 04:47:02.246094 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x10000) = 0
15237 04:47:02.246753 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
15237 04:47:02.247619 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.248312 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x1) = 0
15237 04:47:02.249511 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75cc, 0x442cc0) = 0
15237 04:47:02.250275 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x1) = 0
15237 04:47:02.250979 ipc(0x1, 0x8001, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
15237 04:47:02.251648 ipc(0x1, 0, 0x1, 0, 0x2abf75c4, 0x442cc0) = 0
15237 04:47:02.252306 ipc(0x1, 0x10002, 0x1, 0, 0x2abf75d4, 0x10000) = 0
15237 04:47:02.252964 ipc(0x1, 0, 0x1, 0, 0x2abf75d4, 0x442cc0) = 0
[B][COLOR="red"]15237 04:47:02.253775 write(25, "STATUS online\nIPADDR 217.81.136.152\nGATEWAY 87.186.225.35\nDNS 217.237.148.102\nDNS 217.237.151.115\n", 98) = 98
[/COLOR][/B]15237 04:47:02.254745 close(25)         = 0
[B][COLOR="blue"]15237 04:47:02.255404 access("/bin/onlinechanged", X_OK) = 0
15237 04:47:02.256222 kill(-17856, SIGTERM <unfinished ...>[/COLOR][/B]

Mein Log der Skript-Aufrufe sieht so aus:

2011-09-29T04:47:02+0200  -  /bin/onlinechanged  -  offline
2011-09-29T04:47:01+0200  -  /bin/onlinechanged  -  [B][COLOR="blue"]trap 0[/COLOR][/B]
2011-09-29T04:47:02+0200  -  /bin/onlinechanged  -  online
2011-09-29T04:47:02+0200  -  /bin/onlinechanged  -  trap 0
2011-09-29T04:47:02+0200  -  /bin/onlinechanged.sh  -  online
2011-09-29T04:47:03+0200  -  /etc/onlinechanged/00-aaa  -  online
2011-09-29T04:47:02+0200  -  /etc/onlinechanged/00-aaa  -  trap 0
2011-09-29T04:47:03+0200  -  /tmp/onlinechanged/new_ip_email  -  online
2011-09-29T04:47:03+0200  -  /tmp/onlinechanged/new_ip_email  -  trap 0
2011-09-29T04:47:02+0200  -  /bin/onlinechanged.sh  -  trap 0

Jetzt fragt mich aber nicht, wieso dort "trap 0" steht und kein "trap 15" (SIGTERM).

 

[SaschaBr]

Und? Gibt es neue Erkenntnisse?
Meine (zweite*) neue 7390 hat nämlich genau die gleiche Macke:
Diese Nacht wurde onlinechanged komplett "vergessen".

@AVM: Da läuft irgend etwas falsch, und das schon seit den 88er Firmwares!



(*die erste hat nach nur 9 Tagen Amtszeit der Blitz zerstört, genau wie so fast alle anderen Boxen in unserer Straße)

EDIT:
Ich weiß nicht, in wie weit das zusammen hängt:
Ich habe grade versucht von außen auf mien ftp-server zu kommen --> geht nicht, und das obwohl ich "onlinechanged offline & online" von Hand aus der Konsole aufgerufen hatte.
Darauf hin habe ich mir die Logs und das WebIf mal genauer durchgeschaut, und mir ist dabei was aufgefallen: Im Log steht bei opendd, dass keine Aktualisierung notwendig wäre (obwohl sich die IP bei der Zwangstrennung geändert hatte), und unter "ermittelte IP" (im WebIf bei get_ip) steht doch tasächlich noch die IP von gestern!? Also hat get_ip --all die falsche ip ermittelt!? Darauf hin habe ich in der Konsole mal getestet, welcher der verschiedenen Abfrageparameter dafür verantwortlich ist, mit folgendem Ergebniss:
get_ip --all --> IP von gestern
get_ip --ostat --> IP von gestern
get_ip --webcm --> korrekte IP von heute
get_ip --extquery --> korrekte IP von heute
get_ip --dsld --> get ip error

Hier scheint auch "--ostat" schief zu laufen, bzw. onlinestat enthält selbst auch noch falsche Informationen.
Um diesem Problem zukünftig aus dem Weg zu gehen, habe ich jetzt auf --webcm geändert.

 

[SaschaBr]

Statusbericht:
Die hängen bleibenden "onlinechanged" scheint es mit der 07er-Firmwarereihe (Labor) tatsächlich nicht mehr zu geben, zumindest habe ich dies nicht mehr beobachten können.
Was jedoch immer noch gelegentlich passiert: Onlinechanged wird garnicht ausgeführt.

Wie müsste denn ein Script aussehen, welches via crontab aufgerufen (z.B. nach der vollen Stunde der Zwangstrennung) auf die "Nicht-Aktualisierung" überprüft, und dementsprechend onlinechanged offline & online aufruft? Ich bin es nämlich langsam leid, das jeden morgen zu kontrollieren! Vor allem hat es immer dann nicht funktioniert, wenn ich mal nicht nachgeschaut habe (Grmmllll......). Alternativ wäre ich mitlerweile auch bereit, ein "Prüfscript" dauerhaft mitlaufen zu lassen.

 

[RalfFriedl]

Ganz einfach wäre Folgendes:

Cron Stunde X:
touch /tmp/onlinechange

Wenn onlinechanged funktioniert: ein Script unter onlinechanged:
rm /tmp/onlinechange

Cron Stunde X+1:
Wenn /tmp/onlinechange existiert, dann onlinechanged manuell aufrufen.

 

[SaschaBr]

Danke Ralf.

Nochmal zum Verständniss (Zwanstrennung ist z.B. auf "1-2" eingestellt):
Mit cron um 1 Uhr: Einen "Merker" setzen (touch /tmp/blabla).
Mit onlinechanged diesen "Merker" löschen lassen (rm /tmp/blabla)
Mit cron um 2 Uhr: Wenn "Merker" /tmp/blabla noch da, dann onlinechanged offline & online manuell aufrufen (wie muss die Befehlszeile für cron aussehen?).

Habe ich das richtig verstanden?

 

[RalfFriedl]

Ja, genau so.

if test -f /tmp/blabla; then
    onlinechanged offline
    onlinechanged online
    rm -f /tmp/blabla
fi

 

[kriegaex]

/var/run/onlinestat mit inotifywait beobachten = billiger IP-Watchdog

Man könnte dabei noch Folgendes als Verbesserung machen:

• Anstatt einfach nur eine Datei mit touch zu schreiben, könnte man sich in dieser Datei die IP merken (get_ip).
• Die vorherige IP könnte man durch Umbenennen der Datei in bla.old sichern. Das ließe Vergleiche zu.
• Mittels nslookup könnte man überprüfen, ob die DynDNS-Adresse auf dem aktuellen Stand ist.
• Man könnte ein Log schreiben oder mailen, wenn man feststellt, daß onlinechanged mal wieder nicht getriggert wurde und manuell aufgerufen werden mußte.
• Optional könnte man die Prüfung auch öfter laufen lassen, falls es mal einen ungeplanten Reconnnect gibt. Letzten Endes wäre das so eine Art Watchdog, der immer wieder schaut, ob sich die externe IP geändert hat.

(... Pause - Tee trinken hilft immer Nachdenken ...)

Hey, a propos Watchdog, so kann man den billig implementieren:

inotifywait -e modify /var/run/onlinestat

Kein Cronjob notwendig, einfach nur ein Skript, das beim Start der Box inotifywait aufruft, nach dessen Rückkehr prüft, ob onlinechanged aufgerufen werden muß (ggf. ein paar Sekunden warten, falls das gerade noch am Laufen ist, ich weiß nicht, ob die Datei vor oder nach onlinechanged von AVM aktualisiert wird), ggf. etwas tut und sofort wieder inotifywait startet (Endlosschleife).

Mann, daß ich da nicht früher drauf gekommen bin! Ist ein paar Jahre her, daß ich die inotify-tools als Paket in den DS-Mod eingebaut hatte...

Wie komme ich auf /var/run/onlinestat? Siehe get_ip.

 

[SaschaBr]

Öhm, blauäugig wie ich bin, habe ich grade ganz unbedacht inotify-tools mal mit eingebaut (allerdings mit freetz-Stable-1.2 für meine 7390 mit 91er Firmware, die ich ebentuel morgen wieder mal testen wollte). Erst danach habe ich mir den Wiki-Eintrag im Freetz-Trac durchgelesen, und auch den Thread von Dir hier in Forum gefunden.
Zu meiner Schande muss ich gestehen, dass ich glaube ich weniger als 10% von dem Verstanden habe, was Du da geschrieben hast. Ich glaube, ohne eine Schritt für Schritt Anleitung komme ich damit nicht weiter. :noidea:

 

[kriegaex]

Entschuldige bitte, ich war bei der FreetzConf.

Links wären gut. Was hast Du gelesen und nicht verstanden? Die eine Code-Zeile oben ist doch nicht weiter schwer zu verstehen. Selbst wenn nicht, kannst Du sie trotzdem benutzen. Was genau möchtest Du wissen?

 

[SaschaBr]

Das hier mit den dort enthaltenen Links: http://freetz.org/wiki/packages/inotify-tools

Ich habe grade aber mal probiert:
Ich habe

inotifywait -e modify /var/run/onlinestat &

grade mal in der Konsole ausgeführt, und im AVM-WebIf auf "Neu Verbinden" geklickt. Die Box hat eine neue IP bekommen, aber onlinestat hat sich nicht geändert (die IP blieb stehen, und auch Online)!? Habe daraufhin einfach mal den DSL-Stecker gezogen, sodass die Box neu syncen musste. Hierbei hat sich onlinestat dann auch auf "STATUS offline" geändert, und ich bekam auf der Konsole

[1]+  Done                       inotifywait -e modify /var/run/onlinestat

angezeigt.

So weit so gut. Aber wie baue ich daraus jetzt einen damon?
Interessante Frage ist auch, warum sich onlinestat bei "Neu verbinden" nicht ändert!


[OT]P.S.: Wie wars denn auf der FreetzConf?[/OT]

 

[kriegaex]

Kann ich so nicht nachvollziehen. Bei mir passiert an der Konsole das, wenn "Neu verbinden" angeklickt wird:

# while true; do inotifywait -e modify /var/run/onlinestat; cat /var/run/onlinestat; done

Setting up watches.
Watches established.

/var/run/onlinestat MODIFY
STATUS offline

Setting up watches.
Watches established.

/var/run/onlinestat MODIFY
STATUS online
IPADDR xxx.xxx.xxx.xxx
GATEWAY xxx.xxx.xxx.xxx
DNS xxx.xxx.xxx.xxx
DNS xxx.xxx.xxx.xxx

Setting up watches.
Watches established.

 

[kriegaex]

Inotify-Daemon in debug.cfg als Ersatz für onlinechanged-Skript

So, jetzt habe ich mal schnell etwas in die debug.cfg gehackt und gleichzeitig mein onlinechanged-Skript gelöscht, damit nichts doppelt ankommt bei mir. So sieht das dann aus - wirklich sehr simpel:

{
while true; do
  inotifywait -qq -e modify /var/run/onlinestat
  if grep -q "STATUS online" /var/run/onlinestat; then
    # your reconnect action here
  fi
done
} &

Typisches Beispiel: E-Mail mit neuer IP und ein paar Box-Infos schicken.

{
while true; do
  inotifywait -qq -e modify /var/run/onlinestat
  if grep -q "STATUS online" /var/run/onlinestat; then
    ip=$(/usr/bin/get_ip)
    uptime > /var/tmp/uptime.txt
    echo >> /var/tmp/uptime.txt
    free >> /var/tmp/uptime.txt
    mailer \
      -s "New IP: $ip" \
      -f "Fritz!Box <[email protected]>" \
      -t "[email protected], [email protected]" \
      -m "my.smtp.server" \
      -a "user_name" \
      -w "password" \
      -i /var/tmp/uptime.txt
    rm -f /var/tmp/uptime.txt
  fi
done
} &

Klappt bei mir wunderbar bisher. Ich lasse das mal ein paar Tage so laufen und schaue, ob es zuverlässiger ist als onlinechanged.

 

[RalfFriedl]

Ich vermute, dass /var/run/onlinestat an einer ähnlichen Stelle geändert wird wie onlinechanged aufgerufen wird. Wenn das eine nicht ausgeführt wird, dann vielleicht auch das andere nicht.
Kann jemand, bei dem onlinechanged nicht aufgerufen wurde, prüfen, ob /var/run/onlinestat trotzdem geändert wurde?

 

[kriegaex]

Bei mir ist es ja so, daß Onlinechanged nicht zuverlässig funktioniert, deshalb sagte ich ja, daß ich es testen würde. Insbesondere wird es nicht aufgerufen, wenn ich auf "Neu verbinden" klicke - die Watchdog-Methode über Inotify klappt hingegen nach ersten Tests. Außerdem würde get_ip falsche Informationen liefern mit der Standard-Methode (onlinestat), wenn die Datei nicht zuverlässig aktualisiert würde. Dergleichen ist mir jedoch bisher nie aufgefallen, was durchaus Anlaß zur Hoffnung gibt.

 

[SaschaBr]

... Außerdem würde get_ip falsche Informationen liefern mit der Standard-Methode (onlinestat), wenn die Datei nicht zuverlässig aktualisiert würde. Dergleichen ist mir jedoch bisher nie aufgefallen, was durchaus Anlaß zur Hoffnung gibt.

Oh doch, das Problem hatte ich schon, und habe auch hier davon berichtet: siehe EDIT im Post #120 dieses Threads.

 

[kriegaex]

Das wäre dann doof und würde auch Onlinestat als Default-Methode für get_ip infrage stellen. Bei mir hat es heute nacht jedenfalls erstmal geklappt, was aber nichts heißen will. Ich beobachte das weiter. Was bei mir noch nie passiert (oder aufgefallen) ist, ist eine falsche DynDNS-IP. Allerdings nutze ich auch nicht opendd, sondern die AVM-Funktionalität. Das genügt mir und ist sehr zuverlässig. An mehr als einem Dienst melde ich mich nicht an.

 

[kriegaex]

Erkenntnisse zu hängenden Onlinechanged-Skripten

Es gibt neue Erkenntnisse: Nachdem es die ersten drei Nächte sauber durchlief - auch onlinechanged lief durch und schrieb sich ins AVM-Ereignislog - sah man gestern morgen nur die Offline-Meldung im Log, die Online-Meldung fehlt, ebenso die für vergangene Nacht. Die AVM-Logzeilen für die neuen Internetverbindungen und IPs sind jedoch da. An der Konsole zeigt sich ein bekanntes Bild:

# [B]ps | grep onlinech[/B]
 8584 root      1380 S    /bin/sh /bin/onlinechanged.sh offline
 8594 root      1380 S    /bin/sh /bin/onlinechanged.sh online
15963 root      1188 S    /bin/sh /bin/onlinechanged.sh online
27631 root      1188 S    /bin/sh /bin/onlinechanged.sh offline
27680 root      1380 S    /bin/sh /bin/onlinechanged.sh online

Die Datei /var/run/onlinechanged hat, wie zu erwarten war, einen Zeitstempel von gestern morgen und ist vorhanden, verhindert also die weitere Ausführung der neu aufgerufenen Onlinechanged-Skripten, und zwar deswegen (sollte bekannt sein, aber ich erwähne es trotzdem):

PID_FILE=/var/run/onlinechanged
OC_STATE="$@"

# (...)

if [ -e $PID_FILE ]; then
    if [ ! -e /tmp/.modstarted ]; then
        # (...)
    else
        # no startup/shutdown: wait for other onlinechanged to finish
        [COLOR="blue"]log "waiting"
        while [ -e $PID_FILE ]; do
            sleep 1
        done[/COLOR]
    fi
fi

touch $PID_FILE

Wie wir uns hier selbst in den Fuß schießen, ist offenkundig: Wenn PID_FILE existiert, bleibt onlinechanged.sh hängen in einer Endlosschleife, und zukünftig stapeln sich alle laufenden Onlinechanged-Prozesse im Wartezustand. Wie es dazu kommen kann, wo doch am Ende der Datei immer Folgendes steht, ist eine andere Frage:

#execute onlinechanged scripts
eventadd 1 "Running onlinechanged: $OC_STATE"
log "approved"
for i in /etc/onlinechanged/* /tmp/onlinechanged/* /tmp/flash/onlinechanged/*; do
    [ ! -s "$i" ] && continue
    log "executing $i"
    sh "$i" "$OC_STATE" 2>&1 | while read line; do [ -n "$line" ] && log " * $line"; done
done
[COLOR="blue"]log "done"

rm -rf $PID_FILE 2>/dev/null[/COLOR]

Die Vermutung liegt nahe, daß das Skript irgendwie von außen gekillt wird, nachdem es das PID_FILE erzeugt, aber bevor es selbiges wieder gelöscht hat. Schauen wir uns doch mal genauer die hängenden Prozesse auf meiner Box an:

# [B]for PID in `pidof onlinechanged.sh`; do cat /proc/$PID/cmdline | tr '\0' '\n' | tail -n 1; ls -ld /proc/$PID; done[/B]
online
dr-xr-xr-x    4 root     root             0 Nov 19 15:34 /proc/27680
offline
dr-xr-xr-x    4 root     root             0 Nov 19 15:34 /proc/27631
online
dr-xr-xr-x    4 root     root             0 [COLOR="red"]Nov 19 07:03 /proc/15963[/COLOR]
online
dr-xr-xr-x    4 root     root             0 Nov 20 11:41 /proc/8594
offline
dr-xr-xr-x    4 root     root             0 Nov 20 11:41 /proc/8584

Aha, gestern früh um 07:03 bliebt also erstmals ein Skript hängen (rot markiert, die älteste der Proc-Dateien), und zwar im Status "online". Schauen wir mal, was das Onlinechanged-Log dazu sagt:

# [B]tail -n 25 /var/log/onlinechanged.log[/B]

# Altes Zeug
[10346]: [offline] approved
[10346]: [offline] executing /etc/onlinechanged/00-aaa
[10346]: [offline] executing /etc/onlinechanged/00-get_ip
[10346]: [offline] executing /etc/onlinechanged/onlinechanged-cgi
[10346]: [offline] executing /etc/onlinechanged/webdav_net
[10390]: [online] waiting
[10346]: [offline]  * killall: smbd: no process killed
[10346]: [offline] done
[10390]: [online] approved
[10390]: [online] executing /etc/onlinechanged/00-aaa
[10390]: [online] executing /etc/onlinechanged/00-get_ip
[10390]: [online] executing /etc/onlinechanged/onlinechanged-cgi
[10390]: [online] executing /etc/onlinechanged/webdav_net
[10390]: [online]  * killall: smbd: no process killed
[10390]: [online] done

[COLOR="blue"]# Ab hier wird es spannend[/COLOR]
[15929]: [offline] approved
[15929]: [offline] executing /etc/onlinechanged/00-aaa
[15929]: [offline] executing /etc/onlinechanged/00-get_ip
[15929]: [offline] executing /etc/onlinechanged/onlinechanged-cgi
[15929]: [offline] executing /etc/onlinechanged/webdav_net
[COLOR="blue"]# Wieso kein "done"?[/COLOR]

[COLOR="red"]# Unsere alten Bekannten, die hängenden Prozesse[/COLOR]
[15963]: [online] waiting
[27631]: [offline] waiting
[27680]: [online] waiting
[8584]: [offline] waiting
[8594]: [online] waiting

Offenbar wurde Prozeß 15929 gekillt, als er noch auf die Rückkehr von /etc/onlinechanged/webdav_net wartete. Ergo konnte er nicht mehr das PID_FILE löschen, und den Rest habe ich ja oben bereits erklärt.

Meine Schlußfolgerung aus dieser Untersuchung ist, daß diese ganze PID_FILE-Mechanik problematisch ist. AVM kommt ohne solche Mätzchen aus in seinen eigenen Skripten. Weiß jemand, wieso das in Freetz überhaupt eingebaut wurde? Meine Vermutung wäre, daß es wohl irgendwelche lange laufenden Onlinechanged-Skripten bei uns (oder einzelnen unserer Nutzer) gibt, bei denen es zu Race Conditions kam, wenn der Reconnect so schnell ging, daß die Offline-Skripten noch nicht sauber durchgelaufen waren.

Mögliche Abhilfe könnten verschiedene Maßnahmen schaffen:

• Auf PID_FILEs verzichten, einfach die Skripten normal durchlaufen lassen. Vorteil: Ursache eliminiert, keine hängenden Onlinechanged-Skripten mehr. Nachteil: Aufgerufene Skripten müssen so geschrieben sein, daß sie nicht ihrerseits Probleme bekommen, wenn mehrere Instanzen von ihnen laufen.
• Wartezustand zeitlich limitieren. Vorteil: Es würden sich keine endlos langen Stapel von hängenden Prozessen mehr bilden, nach einigen Minuten würde sich alles auflösen - hoffentlich in Wohlgefallen. Nachteil: Die Problemurache wäre immer noch da, nur die Symptome würden gemildert.
• Skript intelligenter machen. Wir könnten die Entscheidung, ob gewartet werden soll, nicht rein von einem Timeout abhängig machen, sondern von Indizien wie Anzahl und Startzeit weiterer laufender Onlinechanged-Skripten. Vor-/Nachteile wie bei der vorherigen Möglichkeit.

Zur Emittlung des Alters von Prozessen kann man, wie oben gesehen, den Zeitstempel von /proc/<PID> anschauen. Skriptgesteuert geht das z.B. so:

# Prüfen, ob der Prozeß schon 5 Minuten oder älter ist
[ "`find /proc/27680 -prune -mmin +5`" == "/proc/27680" ] && echo ja

# Gleiche Prüfung mittels stat
[ $(( (`date +%s` - `stat -c "%Y" /proc/27680`) / 60 )) -ge 5 ] && echo ja

Die zweite Methode würde aber auf der Box nur funktionieren, wenn man stat in die Busybox mit aufnehmen würde, was momentan nicht der Fall ist, aber leicht änderbar wäre.

 

[kriegaex]

Erkenntnis: Inotify-Watchdog funktioniert trotz hängender Onlinechanged-Skripten

Dies ist ein separates Thema, daher der Doppelpost.

Wie oben erwähnt, hingen bei mir zuletzt die Onlinechanged-Skripten in Endlosschleifen. Die gute Nachricht ist: Ich habe trotzdem dank meines Inotify-Watchdogs brav meine E-Mails für die neuen IPs bekommen.

Nichts sagen kann ich aktuell zu der Frage, was passieren würde in den Fällen, in denen Onlinechanged gar nicht aufgerufen wird, und von denen hatte ich ja auch diverse (nur keine, seitdem der Watchdog aktiv ist). Das bleibt also abzuwarten.

Was ich außerdem beobachte, ist, ob und wie oft es vorkommt, daß get_ip für verschiedene Methoden unterschiedliche Ergebnisse zurückliefert, da Sascha ja anscheinend erlebt hat, daß zumindest die Onlinestat-Methode nicht immer für ihn funktioniert. Seit gestern läuft bei mir im Hintergrund folgendes Skript:

{
while true ; do
  /var/media/ftp/Generic-FlashDisk-03/compare_ext_ip
  sleep 300
done
} &

Es führt alle fünf Minuten (300 Sekunden) einen Vergleich der IPs mit allen vier get_ip-Methoden wie folgt durch:

#!/bin/sh

ip_dsl=`get_ip -d`
ip_ext=`get_ip -e`
ip_ost=`get_ip -o`
ip_wcm=`get_ip -w`

[ "$ip_dsl" == "$ip_ext" ] && [ "$ip_ext" == "$ip_ost" ] && [ "$ip_ost" == "$ip_wcm" ] \
	&& exit 0;

echo "$(date -Iseconds)
    ip_dsl=$ip_dsl
    ip_ext=$ip_ext
    ip_ost=$ip_ost
    ip_wcm=$ip_wcm
" >> /var/media/ftp/Generic-FlashDisk-03/compare_ext_ip.log

Bisher ist die Log-Datei leer, und das seit ca. 38 Stunden. Es ist also nicht vorgekommen, daß /var/run/onlinestat eine falsche IP enthalten hat - zumindest nicht länger als fünf Minuten am Stück.