FB 7170: Kernel Oops bei USB-Seriell-Wandler (speziell bei digitemp)

[Toadie]

Hi,

nachdem ich bereits seit einigen Jahren regelmäßigen Reboots meiner 7170 beim Betrieb mit digitemp erfolglos hinterherjage, habe ich jetzt doch einmal einen Oops einfangen können.
Es würde mich interessieren, ob andere Benutzer ein ähnliches Verhalten bei Verwendung von usb-seriell Wandlern beobachten konnten (Reboot der Box alle 5-20 Tage, kein Panic-Log-File).

Der unten angehängte Absturz entstand, weil usb-serial.c, Funktion serial_ioctl mit port = tty->driver_data = null aufgerufen wurde. Der erste Zugriff auf Port:

if (!port->open_count) {
		dbg ("%s - port not open", __FUNCTION__);
		goto exit;
	}

scheiterte dann mit einer Zugriffsverletzung.

Der Nullpointer läßt vermuten, dass sich da etwas "überholt", vermutlich serial_open, serial_close und serial_ioctl Aufrufe. Spätere Versionen von usb-serial.c (z.B. Kernel 2.6.27 statt dem Kernel 2.6.13 der 7170) haben die entsprechenden Funktionen mit Mutexen gesichert.

Auch ansonsten ist die 2.6.13 Version von usb-serial.c wohl etwas buggy. z.B. bringt ein

cat /dev/ttyUSB0

mit einem anschließenden CTRL+C die Referenzzählung durcheinander und das Modul läßt sich anschließend nicht mehr entfernen. Dafür treten danach aber auch kein Race-Conditions mehr auf

Falls eine Chance besteht, dass die Änderungen als Patch für den 2.6.13 Kernel in freetz aufgenommen werden, und noch jemand die Änderungen testen kann, würde ich ein entsprechendes Patch-File in einem Ticket auf freetz.org einstellen. Auf eine neuere Version des Kernels für die 7170 brauchen wir wahrscheinlich nicht mehr hoffen.

Zum Thema Kernel-Debuggen hätte ich noch eine Menge Fragen, aber das wäre wahrscheinlich ein eigener Thread (ich bin aber trotzdem frech genug, die hier zu stellen) :

• warum wird kein panic-File angelegt? bzw. kann man das irgendwie konfigurieren? bzw. könnte freetz ein eigenes Panic-File verwalten?
• warum wird der Kernel bei jeder Änderung komplett neu gebaut (z.B. bei make kernel-modules)? oder mache ich da etwas falsch?
• hat sich schon jemand mit Kernel-Debugger an die FritzBox getraut?
• wie kriege ich die Modul-Symbole in die dumps? kallsyms klappt bei der 7170 wahrscheinlich aus Speichermangel nicht.

Der Absturz läßt sich mit einiger Geduld auch reproduzieren:
Mit Digitemp in zwei Threads gleichzeitig auf ttyUSB0 zugreifen. Digitemp scheint ein guter Kandidat zu sein, da damit relativ häufig der serielle Port auf- und wieder zugemacht wird. Im normalen Betrieb (digitemp mit 5 Sensoren + Abfrage alle 60sek) warte ich jetzt bereits seit 9 Tagen, dass der Bug wieder auftritt. Wenn man drauf wartet geht's irgendwie immer länger.


Viele Grüße + Danke für die Geduld beim Lesen

Toadie

CPU 0 Unable to handle kernel paging request at virtual address 00000088, epc == c007c9f8, ra == 940c499c
Cpu 0
$ 0   : 00000000 1000ce00 00000000 00010003
$ 4   : c00801fc c008013c c007f9dc 7fff0f18
$ 8   : ffffffe7 80000010 0000540d fffffff8
$12   : 2aade634 000002ff 00000000 00000001
$16   : 00000000 ffffffed 0000540d 95670060
$20   : 7fff0f18 c0080000 00420000 00420000
$24   : 2aae4fb7 2aae9510
$28   : 954f8000 954fbd88 0040b520 940c499c
Hi    : 000003f7
Lo    : 00036cbd
epc   : c007c9f8     Tainted: P
Cause : 10800008
        0000540d 7fff0f18 948af000 95670060 940c499c 954fbec0 954fbdf0 959fe000
        00002003 00000000 00000000 954fbec0 950e0e60 c007c038 942a9200 95dadaf4
        954fbdf0 00000007 941e0000 c007c33c 941e0000 941e1bf0 95670060 0bc00000
        941e0000 ffffffed 95670060 0bc00000 940c5780 940c5750 954fbec0 94071e70
Call Trace: [<940735b4>]  [<940723a0>]  [<94045ad0>]  [<940c499c>]  [<c007c038>]  [<c007c33c>]  [<940c5780>]  [<940c5750>]  [<94071e70>]  [<9406d92c>]  [<9406d8ac>]  [<94063f9c>]  [<94061f0c>]  [<94077cc4>]  [<9407800c>]  [<9407807c>]  [<94062448>]  [<9406242c>]  [<9400dc80>]  [<9400dc80>]
Code: 8c42c248  0040f809  afb20010 <8e020088> 1440000f  02002021  8ea20f04  3c04c008  3c05c008


>>RA;  940c499c <tty_ioctl+d3c/dc4>
>>$31; 940c499c <tty_ioctl+d3c/dc4>

>>PC;  c007c9f8 <END_OF_CODE+2be2ea14/????>   <===== serial_ioctl

Trace; 940735b4 <__link_path_walk+e64/100c>
Trace; 940723a0 <do_lookup+70/278>
Trace; 94045ad0 <filemap_nopage+1a0/440>
Trace; 940c499c <tty_ioctl+d3c/dc4>
Trace; c007c038 <END_OF_CODE+2be2e054/????>  <=== usb_serial_get_by_index
Trace; c007c33c <END_OF_CODE+2be2e358/????>  <=== serial_open
Trace; 940c5780 <tty_open+290/404>
Trace; 940c5750 <tty_open+260/404>
Trace; 94071e70 <permission+90/a4>
Trace; 9406d92c <chrdev_open+148/17c>
Trace; 9406d8ac <chrdev_open+c8/17c>
Trace; 94063f9c <get_empty_filp+5c/108>
Trace; 94061f0c <dentry_open+10c/268>
Trace; 94077cc4 <do_ioctl+64/78>
Trace; 9407800c <vfs_ioctl+334/354>
Trace; 9407807c <sys_ioctl+50/94>
Trace; 94062448 <sys_open+e8/10c>
Trace; 9406242c <sys_open+cc/10c>
Trace; 9400dc80 <stack_done+20/3c>
Trace; 9400dc80 <stack_done+20/3c>

 

[RalfFriedl]

Wenn Du schon weißt, dass tty->driver_data == NULL ist, dann kannst Du diesen Fall ja abfangen, so dass es nicht mehr zu einen Fehler führt. Sinnvoller wäre es, die Mutex-Änderungen zu übernehmen, aber auch mehr Arbeit. Oder die einfache Lösung, den Port offen halten, damit das Problem nicht auftreten kann.

 

[Toadie]

Abfragen von tty->driver_data auf Null in serial_ioctl verhindert zwar den Kernel-Oops, aber anschließend ist der Port nicht mehr brauchbar. Die Funktion dürfte eigentlich auch nie mit einem driver_data == null aufgerufen werden. Ich versuche immer noch, den Fehler mit einem instrumentierten usb-serial.c (Traces bei serial_open und serial_close, Test auf NullPointer in serial_ioctl) im normalen Betrieb (kein Zugriff von mehren Prozessen/Threads) nachzustellen, bisher allerdings ohne Erfolg. Vielleicht führen alleine die printks dazu, dass der Fehler nicht mehr auftritt?

Die Mutexe von 2.6.27 (oder wann immer die auch reingekommen sind) werde ich bei mir mal nachziehen und dann einen Dauertest starten. Bisher hat meine Box mit aktiviertem digitemp nie länger als 14 Tage bis zum Crash gebraucht.

 

[RalfFriedl]

Es kann durchaus sein, dass die Verzögerung durch printk bewirkt, dass der Fehler nicht mehr auftritt.

Zum Dauertest kannst Du ja ein Programm erstellen, das den Port laufend öffnet und schließt, dann kannst Du den Fehler schneller provozieren und weißt umgekehrt auch schneller, ob er behoben ist.

 

[olistudent]

Deine Beschreibung passt sehr gut auf einige Fixes die direkt nach 2.6.13 gemacht wurden:
http://git.kernel.org/?p=linux/kern...ff;h=487f9c6710e7dff338e59820f6cfaeaaa87cb532
http://git.kernel.org/?p=linux/kern...ff;h=8a4613f01f5bb850cab34e3db572d97251d997b3
http://git.kernel.org/?p=linux/kern...ff;h=91c0bce29e4050a59ee5fdc1192b60bbf8693a6d
http://git.kernel.org/?p=linux/kern...ff;h=704936a25bda9bb12e35bb222d5e3f26186dc279
http://git.kernel.org/?p=linux/kern...ff;h=71a84163ca6b4e36744978385e94150af32f9d75

Die ersten 2 Changesets sollten den Panic beheben. Die anderen könnten bei dem falschen Zähler helfen...

Gruß
Oliver

 

[Toadie]

Da haben die Kernel-Jungs aber einige Anläufe gebraucht, bis sie einen stabilen Stand hatten

Mit dem von Ralf vorgeschlagenen Programm, das den Port immer auf und wieder zumacht, läßt sich der Fehler sofort reproduzieren. Allerdings bisher nur, wenn mehrere Prozesse bzw. Threads beteiligt sind. Man sieht dann wirklich, wie der eine Thread in serial_open port setzt und der 2.te Thread ihn rechts überholt und port in serial_close zurücksetzt (obwohl noch ein FileDescriptor dranhängt). Wie das bei rrdstats und digitemp passiert ist, ist mir immer noch ein Rätsel. Da müssten die serial_open und seriel_close immer schön nacheinander angekommen sein. Aus dem Grund habe ich immer noch den Dauertest mit rrdstats und digitemp laufen (inzwischen seit 12 Tagen ohne Vorkommnisse)

Egal was beim Dauertest rauskommt: Die Mutexe (was ist eigentlich die Mehrzahl von Mutex?) machen auf jeden Fall Sinn und ich werde den Patch als Ticket an freetz.org schicken, für den Fall, dass es noch weitere Nutzer einer 7170 mit usb-seriell Wandler gibt.