"onlinechanged" wird manchmal nicht ausgeführt

[kriegaex]

Edit 2: Vergeßt den Post und das Multid-Log von heute morgen, ich hatte durchs Remote-Editieren einen Bug in meinem /bin/onlinechanged: Der Aufruf von onlinechanged.sh war durch einen versehentlich gelöschten Zeilenvorschub ans Ende der Log-Ausgabe (echo) gerutscht. *schäm*

[RalfFriedl]

Damit ist schon mal klar, dass der Aufruf vom multid kommt. Dann wird vermutlich das kill auch vom multid kommen. Wir bräuchten jetzt nur noch den Fall, dass das kill tatsächlich ausgeführt wird. Mit etwas Glück kann man aus dem strace sogar erkennen, was das auslöst.

[kriegaex]

Heute nacht ganz normale Zwangstrennung bzw. Neuverbinden durch die FB:

2011-09-19T04:04:18+0200  -  /bin/onlinechanged  -  offline
2011-09-19T04:04:18+0200  -  /bin/onlinechanged  -  trap 0
2011-09-19T04:04:18+0200  -  /bin/onlinechanged.sh  -  offline
2011-09-19T04:04:22+0200  -  /bin/onlinechanged  -  online
2011-09-19T04:04:19+0200  -  /bin/onlinechanged  -  trap 0
2011-09-19T04:04:23+0200  -  /etc/onlinechanged/00-aaa  -  offline
2011-09-19T04:04:23+0200  -  /etc/onlinechanged/00-aaa  -  trap 0
2011-09-19T04:04:27+0200  -  /bin/onlinechanged.sh  -  online
2011-09-19T04:04:31+0200  -  /tmp/onlinechanged/new_ip_email  -  offline
2011-09-19T04:04:30+0200  -  /tmp/onlinechanged/new_ip_email  -  trap 0
2011-09-19T04:04:18+0200  -  /bin/onlinechanged.sh  -  trap 0
2011-09-19T04:04:36+0200  -  /etc/onlinechanged/00-aaa  -  online
2011-09-19T04:04:33+0200  -  /etc/onlinechanged/00-aaa  -  trap 0
2011-09-19T04:05:16+0200  -  /tmp/onlinechanged/new_ip_email  -  online
2011-09-19T04:05:12+0200  -  /tmp/onlinechanged/new_ip_email  -  trap 0
2011-09-19T04:04:23+0200  -  /bin/onlinechanged.sh  -  trap 0

Ich hänge trotzdem das Log an als Referenz und Gegenbeispiel zu einem zukünftigen Log im Falle eines Scheiterns von onlinechanged-Aufrufen.

Edit: Ich habe mal absichtlich heute morgen stündlich das Zwangstrennungsintervall stündlich einmal so verändert, daß in der folgenden Stunde immer getrennt wurde, und jedesmal hat es geklappt, siehe oben. Jetzt habe ich mal auf den Verdacht hin, daß das Versagen von onlinechanged nur bei der Zwangstrennung von außen durch den Provider passieren könnte, die Zwangstrennung deaktiviert, ohne eine bestimmte Stunde dafür anzugeben, so daß die Box wirklich wartet auf die Trennung. Spekulier, spekulier... :-/

[hermann72pb]

Bei mir "hängt" die Box schon seit mehreren Tagen und meldet sich nicht beim ddns-Server. Interessant sind "hängende" Prozesse:

...
 5090 root      1072 S <  /sbin/udevd --daemon
 5167 root      1176 S    /sbin/chronyd -f /var/tmp/chrony.conf
 5819 nobody     952 S    dnsmasq --pid-file=/var/run/dnsmasq/dnsmasq.pid -p 53
 6259 root         0 SWN  [kdsld_token]
 7306 root      2544 S    vsftpd
 7868 root      1152 S    inetd
 8509 root      3188 S N  /sbin/mount.davfs -o conf=/var/tmp/davfs2.conf -o dir_mode=777 -o file_mode=777 https://sd2dav.1und1.de/
 8515 root      3188 S N  /sbin/mount.davfs -o conf=/var/tmp/davfs2.conf -o dir_mode=777 -o file_mode=777 https://sd2dav.1und1.de/
 8516 root      3188 S N  /sbin/mount.davfs -o conf=/var/tmp/davfs2.conf -o dir_mode=777 -o file_mode=777 https://sd2dav.1und1.de/
 8611 root      1156 S    /bin/sh /bin/onlinechanged.sh online
13609 root      1156 S    /bin/sh /bin/onlinechanged.sh offline
13619 root      1156 S    /bin/sh /bin/onlinechanged.sh online
21083 root      1140 S    sleep 1
21084 root      1140 S    sleep 1
21085 root      1140 S    sleep 1
21086 root      1140 S    sleep 1
21087 root      1140 S    sleep 1
21088 root      1140 S    sleep 1
21089 root      1140 S    sleep 1
21090 root      1140 S    sleep 1
21091 root      1148 R    ps -w
21092 root      1140 S    sleep 1
25990 root      1156 S    /bin/sh /bin/onlinechanged.sh offline
26005 root      1156 S    /bin/sh /bin/onlinechanged.sh online
29231 root      1156 R    /bin/sh /bin/onlinechanged.sh offline
29236 root      1156 S    /bin/sh /bin/onlinechanged.sh online
31283 root      1156 S    /bin/sh /bin/onlinechanged.sh offline
31292 root      1156 S    /bin/sh /bin/onlinechanged.sh online

Ausgelöst wurde alles vermutlich durch einen DSL-Fehler:

19.09.11	02:35:09	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.13.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
19.09.11	02:35:06	Internetverbindung (Telefonie) wurde getrennt.
19.09.11	02:35:03	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
19.09.11	02:12:35	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
19.09.11	02:12:34	Internetverbindung wurde getrennt.
19.09.11	02:12:31	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
18.09.11	02:36:19	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
18.09.11	02:36:18	Internetverbindung (Telefonie) wurde getrennt.
18.09.11	02:36:14	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
18.09.11	02:13:34	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
18.09.11	02:13:33	Internetverbindung wurde getrennt.
18.09.11	02:13:29	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
17.09.11	02:37:40	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
17.09.11	02:37:38	Internetverbindung (Telefonie) wurde getrennt.
17.09.11	02:37:34	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
17.09.11	02:14:48	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
17.09.11	02:14:46	Internetverbindung wurde getrennt.
17.09.11	02:14:42	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
16.09.11	02:38:50	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
16.09.11	02:38:49	Internetverbindung (Telefonie) wurde getrennt.
16.09.11	02:38:45	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
16.09.11	02:16:10	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.13.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
16.09.11	02:16:09	Internetverbindung wurde getrennt.
16.09.11	02:16:06	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
15.09.11	02:39:56	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
15.09.11	02:39:56	Internetverbindung (Telefonie) wurde getrennt.
15.09.11	02:39:52	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
15.09.11	02:17:07	Running onlinechanged: offline
15.09.11	02:17:07	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
15.09.11	02:17:06	Internetverbindung wurde getrennt.
15.09.11	02:17:02	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
14.09.11	20:36:55	Die FRITZ!Box-Einstellungen wurden über die Benutzeroberfläche geändert.
14.09.11	03:34:57	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.178.85, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
14.09.11	03:34:16	PPPoE-Fehler: Zeitüberschreitung. pado: wrong state
14.09.11	03:34:02	PPPoE-Fehler: Zeitüberschreitung. pado: wrong state
14.09.11	03:33:48	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:33:34	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:33:20	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:33:06	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:32:52	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:32:38	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:32:24	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:32:10	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:31:56	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:31:42	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:31:28	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:31:14	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:31:00	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:30:46	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:30:32	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:30:18	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:30:04	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:29:50	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:29:36	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:29:22	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:29:08	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:28:54	PPPoE-Fehler: Zeitüberschreitung.
14.09.11	03:28:40	Zeitüberschreitung bei der PPP-Aushandlung für Internettelefonie.
14.09.11	03:28:40	Internetverbindung (Telefonie) wurde getrennt.
14.09.11	02:18:19	Verbindung zum Online-Speicher hergestellt.
14.09.11	02:18:09	Running onlinechanged: online
14.09.11	02:18:08	Verbindung zum Online-Speicher beendet.
14.09.11	02:18:06	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
14.09.11	02:18:05	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
14.09.11	02:18:05	Internetverbindung (Telefonie) wurde getrennt.
14.09.11	02:18:03	Running onlinechanged: offline
14.09.11	02:18:03	Internetverbindung wurde getrennt.
14.09.11	02:18:01	Die Internetverbindung (Telefonie) wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
14.09.11	02:17:59	Die Internetverbindung wird kurz unterbrochen, um der Zwangstrennung durch den Anbieter zuvorzukommen.
13.09.11	18:13:17	Verbindung zum Online-Speicher hergestellt.
13.09.11	18:13:07	Running onlinechanged: online
13.09.11	18:13:07	Internetverbindung (Telefonie) wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226
13.09.11	18:13:07	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
13.09.11	18:13:03	DSL ist verfügbar (DSL-Synchronisierung besteht mit 7619/563 kbit/s).
13.09.11	18:12:50	DSL-Synchronisierung beginnt (Training).
13.09.11	18:12:35	Verbindung zum Online-Speicher beendet.
13.09.11	18:12:31	Running onlinechanged: offline
13.09.11	18:12:30	Internetverbindung (Telefonie) wurde getrennt.
13.09.11	18:12:29	Internetverbindung wurde getrennt.
13.09.11	18:12:29	DSL antwortet nicht (Keine DSL-Synchronisierung).
13.09.11	06:26:18	Verbindung zum Online-Speicher hergestellt.
13.09.11	06:26:01	Zeitserver ? antwortet nicht.
13.09.11	06:25:56	Running onlinechanged: online
13.09.11	06:25:57	Internetverbindung wurde erfolgreich hergestellt. IP-Adresse: 77.187.XXX.YYY, DNS-Server: 193.189.250.99 und 193.189.244.205, Gateway: 213.20.59.226, Breitband-PoP: rdsl-brsg-de01
13.09.11	06:25:36	PPPoE-Fehler: Zeitüberschreitung. pado: wrong state
13.09.11	06:25:22	PPPoE-Fehler: Zeitüberschreitung.

Deswegen konnte schon die Idee von Alexander mit der Zwangstrennung stimmen.

MfG

[kriegaex]

@Hermann: Das scheint mir ein anderes Problem zu sein: onlinechanged wird ja ausgeführt, es bleibt aber hängen. Bei uns ist es ja so, daß es manchmal augenscheinlich gar nicht aufgerufen wird. Zombies habe ich hier nicht beobachtet. Aber vielleicht kannst Du ja ein zweites Thema dafür aufmachen und ebenfalls mal unsere Log-Ausgaben in Deine Skripten einpflegen und stracen, um zu sehen, wo es hängt.

@Andere: Meine Box hat heute Morgen unter mysteriösen Umständen einen Reboot gehabt, also gibt es von hier erst einmal nichts Neues. Onlinechanged lief beim ersten Connect nach dem Start normal durch.

[RalfFriedl]

@Hermann
Hast Du auch das syslog? Das ist etwas detaillierter.
Es kann gut sein, dass ein onlinechanged gestoppt wurde. Das würde erklären, dass die anderen Prozesse warten.

Wenn man das mit DSL-Fehler auslösen kann, kann man versuchen, das DSL-Kabel zu ziehen und wieder einzustecken, um den Fall zu provozieren, dass onlinechanged gekillt wird. Es gibt aber auch Berichte, dass das Problem bei einer ganz normalen Zwangstrennung auftritt.

[hermann72pb]

Syslog ist bei mir zugemüllt, weil AVM-FTPD sich per inetd versucht auf dem Port 21 zu binden, wo bereits vsftpd läuft. Ist bekanntes Problem und sollte eigentlich auch mal gelöst werden, trägt hierzu aber nicht bei. Führt allerdings dazu, dass man syslog vergessen kann.
@Alexander: Auch die Art und Weise, wie es sich bei mir "aufhängt" wird hier ebenso diskutiert, wie deine Beobachtungen. Die Ursache ist vermutlich die gleiche. Daher halte ich es für unnötig, dass man dies anderswo diskutiert. Das Problem ist erst seit neuer AVM-Firmware aufgetreten. Auch dies bestätigt die Vermutung, dass es die gleichen Wurzeln hat. Und ich nutze auch dnsmasq.
Meine von 1und1 zu mutig als 16000 geschaltete Leitung ist ziemlich schlecht (Telekom würde hier nur 6000 frei geben, was der Realität näher liegt). Von daher sind DSL-Ausfälle durchaus möglich. Und genau so einen Ausfall vermute ich als Ursache dafür.
Bei mir ist die Sache noch dadurch etwas überspitzt, dass ich auch die 2.PVC per ddns update. Wie man oben in meinen Logs sehen kann, kam der Ausfall gerade bei der 2.PVC. Die 2.PVC schließe ich allerdings als einzige Ursache aus. Wenn man sie per ddns auch mitupdatet, dann führt dies höchstens dazu, dass man öfters Probleme provozieren kann, als nur mit 1.PVC, die Ursache steckt aber irgendwo in den Tiefen der AVM-Quellerei.

Die Box ist noch nicht rebootet und "schweigt" immer noch beim DDNS-Server. Daher würde ich gerne diesen Zustand analysieren, wenn ihr irgendwelche Ideen dazu habt, was ich ausführen/anschauen sollte.

MfG

[kriegaex]

Erste Zwangstrennung um 10:02 nach exakt 24 Stunden brachte keine neuen Erkenntnisse, d.h. onlinechanged lief sauber durch. Ich stelle wieder um auf Trennung zwischen 4 und 5 Uhr.

@Hermann: Schick mal das Syslog übers Netzwerk an einen Daemon auf Deinem Rechner, z.B. Kiwi unter Windows. Da wird dann alles mitgeschrieben und man kann später in dem zugemüllten Log - mein Favorit ist die ständig auftauchende Zeile "inetd[2024]: 23/tcp: bind: Address already in use" - bequem filtern (Excel-Export) oder suchen. Und ich nutze übrigens nicht dnsmasq.

@Ralf: Wie weiter oben beschrieben, habe ich mehrmals das Abziehen des DSL-Kabels probiert, dabei aber immer saubere Durchläufe bekommen. Ich wüßte auch gern, wie ich den Fehler provozieren kann. Seitdem ich strace laufen haben, trat er nicht mehr auf. Vorführeffekt...

[RalfFriedl]

Da Hermann von dem Zusammenhang geschrieben hat, hatte ich auch eher gedacht, dass er es vielleicht testen will.

Es kann durchaus sein, dass strace das Verhalten verändert, schließlich wird dadurch das Programm gebremst.

[SaschaBr]

... schließlich wird dadurch das Programm gebremst.

Hmm...
Das würde erklären, warum auch ich seit dem einbauen der Zeilen für den Extra-Log kein fehlerhaftes Onlinechanged mehr hatte.

[RalfFriedl]

Nicht ganz. Das strace auf multid bremst den multid, somit hat das Skript mehr Zeit, bis zum Ende durchzulaufen. Die Log Ausgaben im Skript bremsen das Skript, somit ist es wahrscheinlicher, dass das Skript vorher gestoppt wird. Irgendwo weiter oben war auch mal die Rede, dass mit Log Ausgaben ein Skript vorher abgebrochen wird.

[hermann72pb]

Mit dnsmasq gab es hier Erklärungen von Oliver und Vermutungen, dass (zumindest für meinen Fall zutreffend) multid den dnsmasq auf Port 53 erkennt und dadurch gar nicht mehr ddns bzw. onlinechanged anstoßt. Waren aber nur Vermutungen. Vom Verhalten her ähnelt es sich aber bei mir schon dem, was Alexander beschreibt. Denn meine DSL-Aussetzer stufe ich in eine Kategorie mit Experimenten mit dem Kabel ziehen ein.
Zum externen syslog komme ich leider mangels Zeit nicht. Rein progmatisch wäre es eher zu überlegen vsftpd oder inetd abzuschalten. Oder eben AVM-FTPD herauspatchen.

MfG

[olistudent]

Werfe bitte nicht onlinechanged mit dem AVM ddns in einen Topf.

[hermann72pb]

Auswirkungen sind ähnlich, Oliver. Oder funktioniert etwa bei allen hier mit onlinechanged-Problemen AVM-ddns? Ich vermute da die gleiche Ursache.

Edit:Nehme meine Worte zurück. Nach dem ich dnsmasq-Port von 53 auf 1053 geändert hatte, hat sich ddns sofort!!! (also, sogar ohne reconnect und ähnliches) bei meinem ddns-Server gemeldet. Weitere Diskussion im entsprechenden Thread.

MfG

[kriegaex]

Nachdem in den vergangenen Tagen alles immer sauber durchlief, war es heute nacht wieder so, daß keine einzige Log-Ausgabe erzeugt wurde mit dieser /bin/onlinechanged:

#!/bin/sh
if [ "$1" = "offline" ] ; then
	OUT=/var/media/ftp/Generic-FlashDisk-03
	DATE="$(date '+%Y-%m-%d_%H-%M-%S')"
	for i in $(pidof multid); do
		strace -tt -f -F -x -s 2048 -p $i -o $OUT/multid.$i.$DATE.log &
	done
	for i in $(pidof dsld); do
		strace -tt -f -F -x -s 2048 -p $i -o $OUT/dsld.$i.$DATE.log &
	done
	for i in $(pidof ctlmgr.bin); do
		strace -tt -f -F -x -s 2048 -p $i -o $OUT/ctlmgr.bin.$i.$DATE.log &
	done
	(sleep 120; killall strace ) &
fi
for i in 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 ; do
	trap "echo \"$(date -Iseconds)  -  $0  -  trap $i\" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log" $i
done
echo "$(date -Iseconds)  -  $0  -  $@" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log
/bin/onlinechanged.sh "$@" &

Nochmal zur Verdeutlichung: Kein Echo beim Start, kein Trap, keine Strace-Logs. Mist, was jetzt? Strace-Dauerüberwachung der drei Binaries zwischen 4 und 5 Uhr? Auf den USB-Stick passen würde es. Insgesamt 6,4 MB für 120 Sekunden mal 30 wären 192 MB in einer Stunde, das wäre okay.

Wer hat andere Ideen? Ich denke mal laut: Inotify-Tools zur Überwachung des Dateizugriffs auf Onlinechanged-Skripten benutzen und als Trigger für Strace benutzen?

[RalfFriedl]

Das war wohl der Fall onlinechanged offline/online wird gar nicht ausgeführt.
Das ist verschieden vom Fall onlinechanged offline wird gekillt und deswegen wartet onlinechanged online ewig.

Ich glaube nicht, das wir für den Fall, dass onlinechanged erst gar nicht aufgerufen wird, viel tun können. Das wäre ein Fall für AVM.

Hast Du DnyDNS aktiv? Wenn ja, wurde den Eintrag aktualisiert?
Kann es sein, das alte und neue IP-Adresse gleich sind und deswegen onlinechanged nicht ausgeführt wird? Andererseits kann die Box das ja noch gar nicht wissen zu dem Zeitpunkt, wo sie das offline Event starten sollte.

[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
15237 04:47:02.227218 open("/var/run/onlinestat", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 25
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
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
15237 04:47:02.254745 close(25)         = 0
15237 04:47:02.255404 access("/bin/onlinechanged", X_OK) = 0
15237 04:47:02.256222 kill(-17856, SIGTERM <unfinished ...>

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  -  trap 0
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.