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

RalfFriedl · 17 Sep 2011

Du kannst versuchen, das am Anfang von onlinechanged offline auszuführen:

Code:

OUT=/var/...
for i in $(pidof ctlmgr); do
  strace -tt -p $i -o /$OUT/ctlmgr.$i.log &
done
(sleep 120; killall strace ) &

kriegaex · 17 Sep 2011

Ich habe das am Anfang von /bin/onlinechanged:

Code:

if [ "$1" = "offline" ] ; then
    OUT=/var/media/ftp/Generic-FlashDisk-03
    for i in $(pidof ctlmgr.bin); do
        strace -tt -f -F -v -x -s 2048 -p $i -o $OUT/ctlmgr.$i.log &
    done
    (sleep 60; killall strace ) &
fi

Wenn ich im AVM-Web-UI auf "Neu verbinden" klicke, wird onlinechanged gar nicht aufgerufen, also habe ich einfach mal den DSL-Stecker an der FB gezogen. Dadurch wird "offline" getriggert und ca. 45 Sekunden später "online". Das ausführliche strace-Log (5,4 MB) zeigt beim Durchsuchen keine Spur der Strings "online", "offline" oder "onlinechanged". Könnte es sein, daß ctlmgr gar nicht der Aufrufer ist?

sf3978 · 17 Sep 2011

kriegaex schrieb:
Könnte es sein, daß ctlmgr gar nicht der Aufrufer ist?

Wenn es um onlinechanged geht, das sollte von multid aufgerufen werden.

kriegaex · 17 Sep 2011

Ja, genau. Das hatte ich gerade via

Code:

find /oldroot -type f | xargs grep onlinechanged

herausgefunden und auch gleich nochmal mitgeloggt. Da sieht man auch etwas in der Log-Datei:

Code:

16361 14:41:28.069331 access("/bin/onlinechanged", X_OK) = 0
16361 14:41:28.070225 fork()            = 29939
(...)
29939 14:41:29.055278 execve("/bin/onlinechanged", ["/bin/onlinechanged", "online"], ...) = 0
(...)
29939 14:41:29.201480 open("/bin/onlinechanged", O_RDONLY|O_LARGEFILE) = 3
29939 14:41:29.202279 fcntl64(3, F_DUPFD, 10) = 10
29939 14:41:29.202898 close(3)          = 0
(...)
29939 14:41:29.212001 read(10, "#!/bin/sh\nif [ \"$1\" = \"offline\" ] ; then\n\tOUT=/var/media/ftp/Generic-FlashDisk-03\n\tfor i in $(pidof multid); do\n        strace -tt -f -F -v -x -s 2048 -p $i -o $OUT/multid.$i.log &\n\tdone\n\t(sleep 60; killall strace ) &\nfi\nfor i in 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 ; do\n\ttrap \"echo \\\"$(date -Iseconds)  -  $0  -  trap $i\\\" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log\" $i\ndone\necho \"$(date -Iseconds)  -  $0  -  $@\" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log\n/bin/onlinechanged.sh \"$@\" &\n", 1023) = 503
(...)
29939 14:41:32.472653 open("/var/media/ftp/Generic-FlashDisk-03/new_ip.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = 3
29939 14:41:32.473529 fcntl64(1, F_DUPFD, 10) = 11
29939 14:41:32.474183 dup2(3, 1)        = 1
29939 14:41:32.474800 close(3)          = 0
29939 14:41:32.475458 wait4(-1, 0x7fcd3170, WNOHANG, NULL) = -1 ECHILD (No child processes)
29939 14:41:32.476165 fcntl64(1, F_GETFL) = 0x2009 (flags O_WRONLY|O_APPEND|O_LARGEFILE)
29939 14:41:32.476996 write(1, "2011-09-17T14:41:32+0200  -  /bin/onlinechanged  -  online\n", 59) = 59
29939 14:41:32.478571 dup2(11, 1)       = 1
29939 14:41:32.479223 close(11)         = 0
29939 14:41:32.479941 fork()            = 29957
29939 14:41:32.481985 read(10, "", 1023) = 0
29939 14:41:32.483555 open("/var/media/ftp/Generic-FlashDisk-03/new_ip.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = 3
29939 14:41:32.484450 fcntl64(1, F_DUPFD, 10) = 11
29939 14:41:32.485116 dup2(3, 1)        = 1
29939 14:41:32.485738 close(3)          = 0
29939 14:41:32.486697 wait4(-1, 0x7fcd3068, WNOHANG, NULL) = 0
29939 14:41:32.487344 fcntl64(1, F_GETFL) = 0x2009 (flags O_WRONLY|O_APPEND|O_LARGEFILE)
29939 14:41:32.488688 write(1, "2011-09-17T14:41:29+0200  -  /bin/onlinechanged  -  trap 0\n", 59) = 59
(...)
29957 14:41:32.552506 execve("/bin/onlinechanged.sh", ["/bin/onlinechanged.sh", "online"], ...) = 0
(...)
29957 14:41:32.736846 open("/bin/onlinechanged.sh", O_RDONLY|O_LARGEFILE) = 3
29957 14:41:32.738069 fcntl64(3, F_DUPFD, 10) = 10
29957 14:41:32.738732 close(3)          = 0
29957 14:41:32.739454 fcntl64(10, F_SETFD, FD_CLOEXEC) = 0
29957 14:41:32.740105 rt_sigaction(SIGINT, NULL, {SIG_DFL, [RT_66], SA_NOCLDSTOP}, 16) = 0
29957 14:41:32.741100 rt_sigaction(SIGQUIT, NULL, {SIG_DFL, [RT_66], SA_NOCLDSTOP}, 16) = 0
29957 14:41:32.742116 rt_sigaction(SIGTERM, NULL, {SIG_DFL, [RT_66], 0}, 16) = 0
29957 14:41:32.743479 rt_sigaction(SIGTERM, {SIG_DFL, [RT_66], 0}, NULL, 16) = 0
29957 14:41:32.744631 read(10, "#!/bin/sh\nfor i in 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 ; do\n\ttrap \"echo \\\"$(date -Iseconds)  -  $0  -  trap $i\\\" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log\" $i\ndone\necho \"$(date -Iseconds)  -  $0  -  $@\" >> /var/media/ftp/Generic-FlashDisk-03/new_ip.log\nPID_FILE=/var/run/onlinechanged\nOC_STATE=\"$@\"\n\nlog() {\n\techo \"[$$]: [$OC_STATE] $*\" >>/var/log/onlinechanged.log\n\techo \"ONLINECHANGED[$$]: [$OC_STATE] $*\" >/dev/console\n\tlogger -t ONLINECHANGED[$$] \"[$OC_STATE] $*\"\n}\n\n# shutdown: do nothing\nif [ -e /var/run/shutdown ]; then\n\tlog \"disabled\"\n\texit 0\nfi\n\nif [ -e $PID_FILE ]; then\n\tif [ ! -e /tmp/.modstarted ]; then\n\t\t# startup: quit if another onlinechanged is yet running\n\t\t[ \"$OC_STATE\" == \"offline\" ] && rm -rf $PID_FILE 2>/dev/null\n\t\tlog \"rejected\"\n\t\texit 0\n\telse\n\t\t# no startup/shutdown: wait for other onlinechanged to finish\n\t\tlog \"waiting\"\n\t\twhile [ -e $PID_FILE ]; do\n\t\t\tsleep 1\n\t\tdone\n\tfi\nfi\n\ntouch $PID_FILE\n\n# startup: wait for rc.mod, abort if status changes to \"offline\"\nif [ ! -e /tmp/.modstarte", 1023) = 1023
(...)

Und so weiter für "online". Der multid ist also unser Verdächtiger. Anbei der vollständige Trace für eine erzwungene Trennung durch Ziehen des Steckers für 5-10 Sekunden. Mal sehen, was des Nachts passiert. Um das Ganze noch separat für jedes Offline-Ereignis festzuhalten, ändere ich den Code in /bin/onlinechanged wie folgt:

Code:

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 -v -x -s 2048 -p $i -o $OUT/multid.$i.$DATE.log &
    done
    (sleep 75; killall strace ) &
fi

Außerdem hänge ich hier mal das oben teilweise zitierte Log an: (Edit: Anhang gelöscht)

kriegaex · 18 Sep 2011

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 · 18 Sep 2011

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 · 19 Sep 2011

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

Code:

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 · 19 Sep 2011

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

Code:

...
 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:

Code:

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.
[COLOR="red"][B]15.09.11	02:17:07	Running onlinechanged: offline[/B][/COLOR]
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
[COLOR="blue"][B]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.
[/B][/COLOR]14.09.11	03:28:40	Internetverbindung (Telefonie) wurde getrennt.
14.09.11	02:18:19	Verbindung zum Online-Speicher hergestellt.
[B][COLOR="green"]14.09.11	02:18:09	Running onlinechanged: online[/COLOR][/B]
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 · 20 Sep 2011

@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 · 20 Sep 2011

@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 · 20 Sep 2011

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 · 21 Sep 2011

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 · 21 Sep 2011

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 · 21 Sep 2011

RalfFriedl schrieb:
... 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 · 21 Sep 2011

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 · 21 Sep 2011

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 · 21 Sep 2011

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

hermann72pb · 22 Sep 2011

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 · 24 Sep 2011

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:

Code:

#!/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 · 24 Sep 2011

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.

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

IPPF-Urgestein

Aktives Mitglied

IPPF-Promi

Aktives Mitglied

Aktives Mitglied

IPPF-Urgestein

Aktives Mitglied

Anhänge

IPPF-Promi

Aktives Mitglied

IPPF-Urgestein

IPPF-Promi

Aktives Mitglied

IPPF-Urgestein

Aktives Mitglied

IPPF-Urgestein

IPPF-Promi

IPPF-Urgestein

IPPF-Promi

Aktives Mitglied

IPPF-Urgestein

Statistik des Forums