[gelöst] Start von rc.S debuggen und loggen

[hermann72pb]

Ich hatte bereits hier im Forum und in diversen Tickets darüber berichtet, dass meine 7170 letzte Zeit relativ viel Zeit zum Hochfahren braucht. Die Box schafft relativ schnell die module und AVM-Dienste zu starten, sowie Einiges auszuführen / zu starten (IP-Vergabe per dhcp, AVM-Web-IF, telnet und sogar LABEL-mounts durch FREETZMOUNT), bleibt aber irgendwo kurz vor dem Start der FREETZ-Dienste stecken. Danach erfolgt eine Pause, die unter Umständen bis zu 5 Minuten dauert, bis die FREETZ-Dienste endlich beginnen sich zu laden. Während dieser Zeit sehe ich per "top" und per "ps" nichts Verdächtiges. Lediglich, dass rc.S am pendeln ist. top zeigt auch keine erhöhte Prozessorlast.
Ich würde gerne dem Problem auf die Spur kommen, brauche jedoch eure Tipps, wie ich am besten rc.S und seine Umgebung vor dem Kompilieren so preparieren könnte, dass ich den "Hänger" sicher finden kann.
Würde z.B. ein "sh -x rc.S" an einer passenden Stelle was bringen? Oder soll ich zusätzlich die Ausgaben 1 und 2 in eine Datei im RAM umlenken. Nach USB zu lenken finde ich zu früh, weil evtl. noch nicht gemountet, RAM (z.B. /tmp/rc_s_log) ist jedoch ausreichend, weil die Box letztendlich doch durchbootet und die Datei im RAM erhalten bleibt. Ideal wäre aber für mich jede Logausgabe mit einem Zeitstempel zu versehen. Wie könnte ich sowas realisieren?
Serielle Konsole habe ich nicht.

MfG

 

[olistudent]

Kommst du in der Zeit per telnet/ssh auf die Box? Dann könntest du dir die Dateien unter /var/log anschauen wie weit er ist.

MfG Oliver

 

[Silent-Tears]

Vielleicht reichen dir ja die inotify-tools?

 

[buehmann]

Einen Zeitstempel könntest du bekommen, indem du einen "syslogd" (mit Ausgabe in Datei (im RAM)) startest, und die zu loggenden Ausgaben in "logger" hinein-pipe-st.

PS: Natürlich dran denken, dass auch die normalen RAM-Disks erst irgendwann innerhalb von rc.S gemountet werden ...

PPS: Mit "syslogd -C" brauchst du dir um Dateisysteme keine Gedanken zu machen.

 

[hermann72pb]

FREETZ ist zu dem Zeitpunkt noch gar nicht geladen. telnet ist da und ich komme per telnet auf die Box. dropbear ist noch nicht da, weil es zusammen mit FREETZ ja geladen wird. syslogd ist vermutlich zu dem Zeitpunkt noch nicht gestartet. Es wäre aber sicherlich eine gute Idee zu debug-Zwecken das Starten vom syslogd in einem der AVM-Startskripten zu platzieren: am Anfang von rc.S oder dort, wo rc.S aufgerufen wird. Das Problem am syslogd liegt darin, dass ich nur das sehe, was ausgegeben wird. AVM gestaltet seine Skripte allerdings meistens wenig gesprächig. Daher war meine Idee mit "sh -x".

Zu inotify-tools: Wird dazu "replace-kernel" benötigt? In WIKI steht etwas über kernel-args und ich habe diesbezüglich eine sehr starke Vermutung, dass es nur mit "replace-kernel" geht. Letzteres hatte ich bis jetzt noch nie gebraucht und vermute gerade bei 7170, dass durch das Ersetzen die Kernelgröße nicht unbedingt kleiner wird und ich damit allgemein Platzprobleme bekomme. Schon jetzt habe ich fast alles (inklusive Libs) ausgelagert und kämpfe um jede 10kB auf der Box.

MfG

 

[Silent-Tears]

Zum Grössenvergleich könntest du die Option simpel anwählen und die Grösse der Images vergleiche

Was inotify-tools angeht kannst du simpel schauen, ob du es ohne angewähltes Kernel ersetzen anwählen kannst. Dann sollten (ja, ich weiss, böses Wort) die Abhängigkeiten geklärt sein. Hast du btw. mal über USB-Root nachgedacht? Platzprobleme sind dann vorbei...

 

[olistudent]

FREETZ ist zu dem Zeitpunkt noch gar nicht geladen.

Das glaube ich nicht. Gibts wirklich noch keine Dateien unter /var/log?

MfG Oliver

 

[hermann72pb]

Ich hatte momentan Probleme mit der aktuellen Firmware gehabt. Die Box hat wie Lichtorgel vor sich geblinkt und es gab nur AVM-WebIF zu sehen. Daraufhin habe ich eine ältere Firmware flashen müssen, damit ich überhaupt die Box zum Laufen bringe. Leider war die Box derart zerschossen, dass einfache reboots und aufspielen einer noch älteren Firmware-Version nichts brachten. Erst als ich die Box kalt neu startete (Stecker ziehen), konnte die Box mit einer älteren Version durchstarten. Da die Box sich dabei mit DSL nicht verbinden konnte, vermute ich modulprobleme, die entweder durch neue Sourcen, neuere busybox oder was auch immer kommen. Um das Problem zu beseitigen werde ich wohl busybox cleanen müssen oder gar von vorne anfangen. Aber das ist jetzt ein anderes Thema, was mir lediglich wieder Zeit kosten würde und mit dem eigentlichen Vorhaben hier gar nichts zu tun hat.
Um die Fragen von Oliver zu beantworten, poste ich die Ausgaben, die ich über telnet während einer solchen "Wartephase" gewinnen konnte:

/var/mod/root # ps
  PID USER       VSZ STAT COMMAND
    1 root      1436 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]
   97 root      1616 S    /bin/sh /etc/init.d/rc.S
  459 root         0 SW<  [capi_oslib]
  460 root         0 SW<  [capi_oslib]
  461 root         0 SW   [capitransp]
  467 root         0 SW   [glob_codecs]
  481 root         0 SW<  [khubd]
  537 root      8588 S N  ctlmgr
  557 root      2228 S    wpa_authenticator
  635 root      4852 S    upnpd
  647 root         0 SWN  [scsi_eh_0]
  648 root         0 SWN  [usb-storage]
  725 nobody    1240 S    dnsmasq --pid-file=/var/run/dnsmasq/dnsmasq.pid -p 53
  732 root      3372 S    multid
  754 root      3780 S    dsld -i -n
  767 root      1620 S    telnetd -l /sbin/ar7login
  768 root      5748 S    telefon a127.0.0.1
  779 root      5056 S <  voipd
  783 root      3372 S    multid
  788 root      3188 S    pbd
  789 root      3188 S    pbd
  794 root      3188 S    pbd
  795 root      3188 S    pbd
  820 root      1116 S    /bin/run_clock -c /dev/tffs -d
  823 root      1616 S    /bin/sh /etc/init.d/rc.S
  856 root      4852 S    upnpd
  857 root      4852 S    upnpd
  858 root      4852 S    upnpd
  867 root         0 RWN  [kdsld_token]
  879 root      1276 S    /sbin/ftpd -D -q --pidfile=/var/run/ftpd.pid -t 30 -m
  920 root      8588 S N  ctlmgr
  924 root      8588 R N  ctlmgr
  925 root      8588 S N  ctlmgr
 1033 root      8588 S N  ctlmgr
 1034 root      8588 S N  ctlmgr
 1075 root      3128 S    /usr/bin/faxd -a
 1139 root         0 SWN  [kjournald]
 1210 root      1892 S    capiotcp_server -p5031 -m99
 1230 root      1448 S    -sh
 1266 root      1432 R    ps
/var/mod/root # cd /var/log
/var/log # ls
mod_load.log  mod_net.log
/var/log # cat mod_load.log
Loading /var/flash/freetz...done.
Loading users, groups and passwords...done.
Loading hosts...done.
Loading config...done.
Loading modules...done.
/var/log # cat mod_net.log
Starting dnsmasq...done.

Vielleicht erkennt schon ein oder anderer was daraus. Ich sehe darin nur Bestätigung meiner Theorien: Es klemmt isrgendwo in rc.S.

MfG

 

[olistudent]

Könnte man die rc.S stracen? Sieht man da wo er hängt?

Er hängt dann wohl bevor die Freetz Dienste gestartet werden. Wenn du das meintest.

/etc/init.d/rc.mod 2>&1 | tee /var/log/mod.log

Ansonsten müsste die mod.log vorhanden sein.

MfG Oliver

 

[RalfFriedl]

Für den Anfang könnte Folgendes in rc.S reichen, nachdem /var bereit ist:

exec 2> /var/log/rc.log 1>&2
set -x

Dann sollte man sehen, wie weit rc.S kommt, bzw. wo es lange dauert.
Auf der Box dann mit

tail -f /var/log/rc.log

die Datei beobachten.
Das sollte Anhaltspunkte geben, wo man weiter schauen kann.

 

[buehmann]

Ich sehe darin nur Bestätigung meiner Theorien: Es klemmt isrgendwo in rc.S.

rc.S liest rc.mod ein, anstatt es aufzurufen (keine Ahnung, warum). rc.mod läuft also in der Prozessliste auch unter dem Namen "rc.S". Es könnte also durchaus schon im Freetz-Teil die Probleme geben.

Andreas

PS: Habe die Bemerkung von Oliver übersehen: Wenn mod.log noch nicht existiert, spricht das natürlich dagegen, dass die Verarbeitung schon am Ende von rc.S angekommen ist.

 

[olistudent]

rc.S liest rc.mod ein, anstatt es aufzurufen (keine Ahnung, warum).

Fändest du es sinnvoller rc.mod aufzurufen? Welchen Unterschied macht das? Außer dass ein neuer Prozess aufgerufen wird.

MfG Oliver

 

[buehmann]

Keinen großen, je nach Bewertungsmaßstab: Durch einen eigenen Prozess hat man eine bessere Trennung (lokale Variablen, Funktionsdefinitionen etc. können sich nicht evtl. unbeabsichtigt auf den fremden Code auswirken).

 

[RalfFriedl]

Allgemein gesehen schon, aber im konkreten Fall sehe ich keinen Grund für eine Änderung.

 

[buehmann]

Ja, hier kann es so bleiben. War mir nur beim Blick in dir rc.S aufgefallen.

 

[hermann72pb]

Mein erster Versuch endete damit, dass ich mich wieder in die push-firmware-Thematik einarbeiten musste und die Interfaces von freetz-linux so verbiegen musste, dass sie statisch werden und man überhaupt die Möglichkeit bekommt in der Sprache von Adam und Eva mit der Box zu reden.
Aber das sei hier nur am Rande angemerkt. Die Stelle in rc.S (etwas um Zeile 90 herum, oder etwas tiefer) war offensichtlich falsch (zu früh), wo ich die beiden Zeilen von Ralf eingepflanzt hatte. Die Box hat es übel genommen und hat die Weiterbearbeitung von rc.S eingestellt. Mit allen daraus folgenden Konsequenzen (nichts geht).
Diesmal werde ich etwas vorsichtiger und pflanze es deutlich tiefer, da wo die ersten logs geschrieben werden. Bis dahin dürfte bei mir sowieso alles durchlaufen und es ist von daher für die Fehlersuche irrelevant.
Dennoch würde mich tierisch interessieren, an welcher Stelle von rc.S denn /var/log angelegt wird und ab dort bereits existiert? Weiß das jemand? Eine einfache Suche in der Datei nach "log" und nach "/var/log" brachte keine vernünftigen Treffer bei mir.

MfG

 

[RalfFriedl]

Du solltest auch nicht nach "log", sondern nach "var" suchen.

 

[hermann72pb]

Mit var ist es noch komplizierter. Ich hatte mich an inotify-tools-Eintrag orientiert gehabt:

# Load boot loader kernel_args API
. /usr/bin/kernel_args
# Backup kernel log ring buffer ASAP, so as not to lose its earliest entries
if ka_isActiveVariable SaveKernelRingBuffer; then
	ka_decreaseValue SaveKernelRingBuffer
	dmesg > /var/dmesg-rc.S.log
fi
# Initiate inotify-tools file access logging
if ka_isActiveVariable InotifyBootAnalysis; then
	ka_decreaseValue InotifyBootAnalysis
	/etc/init.d/rc.inotify_tools start 
fi

Und dachte mir, wenn es da schon /var angesprochen wird, dann existiert es eben. Wenn man allerdings rc.S weiter unten anschaut, wird man sehen, dass etwas tiefer var.tar entpackt wird. Ich vermute, dass dieses Entpacken womöglich dadurch verhindert wird, dass nach /var/log gelogt wird. Deswegen habe ich jetzt deine zwei Zeilen deutlich tiefer gelegt.
Ich werde gleich flashen und dann sehen wir weiter. Wenn ich länger nicht auftauche, dann bin ich wieder mit push_firmware am spielen, sonst erhoffe ich endlich erste Erkenntnisse zu liefern.

MfG

 

[RalfFriedl]

In der original Version sieht es so aus:

mount /var
...
##########################################################################################
## /var filesystem mit leben fuellen
##########################################################################################
tar xf var.tar

In Freetz wird "mount -a" statt "mount /var" verwendet. Das Verzeichnis /var ist dann direkt verfügbar. Mit dem Auspacken von var.tar werden dann noch verschiedenen Dateien und Verzeichnisse in /var angelegt.

 

[hermann72pb]

eben, genau das war meine Motivation, als ich es dorthin gepackt hatte. Es scheint aber die falsche Stelle zu sein (zu früh).

Und nun flashe ich endlich mit einer späteren Positionierung. Bis dann!


Edit:
Übeltäter gefunden!!!

/var/mod/root # tail -f /var/log/rc.log
+ let cnt=cnt+1
+ sleep 10
+ [ ! -f /var/media/ftp/uStor01/dtmfbox/boot.sh ]
+ [ 5 -eq 30 ]
+ let cnt=cnt+1
+ sleep 10
+ [ ! -f /var/media/ftp/uStor01/dtmfbox/boot.sh ]
+ [ 6 -eq 30 ]
+ let cnt=cnt+1
+ sleep 10
+ [ ! -f /var/media/ftp/uStor01/dtmfbox/boot.sh ]
+ [ 7 -eq 30 ]
+ let cnt=cnt+1
+ sleep 10
+ [ ! -f /var/media/ftp/uStor01/dtmfbox/boot.sh ]
+ [ 8 -eq 30 ]
+ let cnt=cnt+1
+ sleep 10
+ [ ! -f /var/media/ftp/uStor01/dtmfbox/boot.sh ]
+ [ 9 -eq 30 ]
+ let cnt=cnt+1
+ sleep 10

dtmfbox habe ich übrigens schon lange nicht mehr im Image. Das werden wohl Überreste sein...

Die Frage ist: Wie entferne ich sie und warum haben sie so eine Auswirkung, obwohl dtmfbox gar nicht im Image ist?

Edit2:
Der Wurm steckte in debug.cfg:

/var/mod/root # cat /var/flash/debug.cfg
########## -= dtmfbox settings - DO NOT EDIT - S =- ##########
(
 # USB-Mount (300 sec)
 let cnt=0;
 while [ ! -f "/var/media/ftp/uStor01/dtmfbox/boot.sh" ]; do
        if [ $cnt -eq 30 ]; then break; fi
        let cnt=cnt+1;
        sleep 10
 done;
)
sleep 30; sh "/var/media/ftp/uStor01/dtmfbox/boot.sh"
########## -= dtmfbox settings - DO NOT EDIT - E =- ##########

Da ich mir 100% sicher war meine debug.cfg vor ewigen Zeiten geleert zu haben, bin ich natürlich nicht auf die Idee gekommen, dass dtmfbox sich da verewigt hat, ohne mich darüber zu informieren. Es mag sein, dass ich mal mit der USB-Version von dtmfbox rumgespielt hatte, ich konnte aber nicht ahnen, dass es solche Auswirkungen hat.

MfG