Re: Immer wieder: kernelpanic von rsh (jetzt mit crashdump)

<ticso(at)cicely.de> aka Bernd Walter schrieb
mit Datum Mon, 21 Apr 2003 13:39:48 +0200 in m2n.de.fbsd.questions:

|On Mon, Apr 21, 2003 at 12:17:49AM +0000, Peter Much wrote:
|>
|> In letzter Zeit macht eine von meinen 4.7 Maschinen immer oefter
|> eine kernelpanic. Und zwar immer bei derselben Anwendung, naemlich
|> wenn ich mit rsh die filesystem-dumps vom System herunter schiebe,
|> nachdem schon eine gute Weile Daten geflossen sind.
|> Stacktrace sagt jedesmal, der Crash ist in m_copym() via tcp_output,
|> tcp_usr_send, sosend, soo_write, dofilewrite, write, syscall2.
|>
|> Solange kein Backup laeuft, ist das System voellig stabil. Es
|> arbeitet als Gateway fuer die Internet-Anbindung, es ist also
|> kaum denkbar, dass die Probleme aus genuinem Netzwerktraffic
|> herruehren.
|
|Routing ist was anderes als selber Daten zu verschicken.
|Außerdem passiert es in dem Fall gleichzeitig mit Plattenzugriffen,
|die beim routen als solche niemals vorkommen.

So, nun hab ich also einen wunderschoenen crashdump, und der
erzaehlt auch was. Das haengt unten an.

Dann bin ich die ganze Funktionskette von oben her abgelaufen,
und hab zu verstehen versucht, was da passiert. (Dementsprechend
raucht mit jetzt der Kopf, aber viel schlauer bin ich noch nicht.)
Derweil hab ich mal gem. dem Vorschlag von Peter Ross eine andere
Netzwerkkarte probiert - hat dasselbe Ergebnis. Wenn ich allerdings
den Datenstrom ueber eine ipfw-pipe abbremse, dann scheint ruhe zu
sein.

Der Crash passiert immer mitten im Datenstrom, wenn also Daten
fliessen sollten, so schnell die Physik sie durchlaesst. Von daher
gibt es also keinen Hinweis darauf, wo man hinschauen sollte, und
die ganzen Datenstrukturen sind mitten in ihrer dynamischen
Funktionsweise.

Oben kommt offenbar ein write() call fuer den fd=3 herein mit
einem buffer von 1024 Byte. In dem Buffer sehe ich auch irgendwo
was von meinen Nutzdaten.
Zwischen soo_write() und sosend() taucht dann irgendwo aus den
indirekten Funktionsaufrufen ein Parameter "top" (struct mbuf *)
auf, und da sind auch wieder meine Nutzdaten drin zu sehen.
Dieser mbuf * wird dann an tcp_usr_send() uebergeben und soll
wohl dort an den so_snd socketbuffer angehaengt werden.

Ungefaehr da komme ich dann massiv durcheinander mit diesen
gigantischen Verkettungen von Indirektionen, und der Fragestellung,
was von dem, was ich jetzt post-mortem sehe, eventuell von wo aus
wann veraendert wurde. Und dann weiss ich irgendwann nichtmal mehr,
was jetzt wo by-value und wo by-reference erscheint, bzw. was fuer
Uebergabe-Werte ich in den Funktionsaufrufen der Stack-Frames sehe:
offensichtlich ja nicht die, mit denen die Funktion tatsaechlich
aufgerufen wuerde, sondern so, wie sie bis zum Crash-Zeitpunkt ver-
aendert wurden.

Zum crashzeitpunkt jedenfalls steht in dem Socket in so_snd.sb_mb
eine 0; und da m_copym() diesen Wert als "struct mbuf *m =
so->so_snd.sb_mb", d.h. doch offensichtlich by-value uebergeben
gekriegt hat, kann die nicht von m_copym() erzeugt worden sein.
m_copym() wierderum prueft diesen uebergebenen Wert zuerst
erfolgreich(!) auf "m != NULL", hangelt sich dann durch die
mbuf-Kette mglw. bis ans Ende, prueft dann erfolgreich(!) auf
"m == 0", folgert daraus, dass es etwas kopieren soll, wo
nichts ist, und haelt das System an.

Und das gibt so keinen Sinn:
 * Wenn zum Zeitpunkt des Aufrufs von m_copym() in so_snd.sb_mb
   noch ein Pointer stand (nur so ist doch zu erklaeren, warum
   der erste Test auf "m != NULL" gelingt), warum ist der zum
   Crash-Zeitpunkt ploetzlich weg und durch eine 0 ersetzt?
 * Wenn das m = 0 in m_copym() zum Crashzeitpunkt dadurch
   entstanden ist, dass m_copym() sich die Kette entlanggehangelt
   hat und ans Ende gelangt ist, und obwohl da nix mehr ist,
   nun noch restliche len=920 kopieren soll, dann ist offenbar
   ein fehlerhafter Aufruf an m_copym() erfolgt - warum? Und
   warum tritt das nur in diesen seltenen Faellen auf?
Und nebenbei, aber damit mach ich mich jetzt wahrsch. als Ko-
   rinthenkacker unbeliebt: Wenn m als "struct mbuf *" deklariert
   ist, warum wird er dann einmal auf "m != NULL" getestet und das
   naechste mal auf "m == 0"? Oder warum schaffen wir die NULL
   dann nicht gleich ganz ab?

Anders gefragt: besteht die Moeglichkeit, dass "jemand anderes"
an dem socketbuffer herumarbeitet, *waehrend* tcp_output() ihn
sendefertig machen will? Und die Daten dem m_copym() gewisser-
massen unterm Arsch weggezogen werden?

Frage in die Runde: ist dieses Ding einen bugreport wert? Nach
meinem Dafuerhalten koennte es eventuell eine race-Condition sein;
nach einem Hardwarefehler sieht es mir nicht aus, und auch eine
schlechte Netzwerkkarte sollte, soweit ich die Zusammenhaenge
jetzt zu verstehen meine, nicht an dieser Stelle und auf diese
Weise zum Crash fuehren.

Gruss
PMc

-----------------------------------------------------------------
IdlePTD at phsyical address 0x0054f000
initial pcb at physical address 0x003b7b20
panicstr: m_copym, length > size of mbuf chain
panic messages:

---
panic: m_copym, length > size of mbuf chain
syncing disks... 4 
done
Uptime: 3d17h17m38s
dumping to dev #da/1, offset 480
dump 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28
27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2
1 
---
#0  dumpsys () at ../../kern/kern_shutdown.c:487
487             if (dumping++) {
(kgdb) bt full
#0  dumpsys () at ../../kern/kern_shutdown.c:487
        error = 0
#1  0xc01a56a7 in boot (howto=256) at ../../kern/kern_shutdown.c:316
        howto = 256
#2  0xc01a5ae9 in panic (fmt=0xc032f6a0 "m_copym, length > size of mbuf chain")
    at ../../kern/kern_shutdown.c:595
        fmt = 0xc032f6a0 "m_copym, length > size of mbuf chain"
        bootopt = 256
        buf = "m_copym, length > size of mbuf chain", '\000' <repeats 219 times>
#3  0xc01c1b1d in m_copym (m=0x0, off0=1448, len=920, wait=1)
    at ../../kern/uipc_mbuf.c:806
        n = (struct mbuf *) 0xc06a8c00
        np = (struct mbuf **) 0xc06a8c00
        off = 0
        top = (struct mbuf *) 0xc06a8c00
        copyhdr = 0
#4  0xc0221cd5 in tcp_output (tp=0xc471ee40) at ../../netinet/tcp_output.c:612
        tp = (struct tcpcb *) 0xc471ee40
        so = (struct socket *) 0xc46d0cc0
        len = 1448
        win = 57920
        off = 1448
        flags = 16
        error = 0
        m = (struct mbuf *) 0xc06ec400
        ip = (struct ip *) 0x0
        ip6 = (struct ip6_hdr *) 0x0
        th = (struct tcphdr *) 0x5a8
        opt = "\001\001\b\n\001éå\004\0026JS\000\000\000\000äýÍÄGd\034À0\rmÄ\000+lÀ\000UnÀ\020þÍÄ"
        ipoptlen = 1448
        optlen = 12
        hdrlen = 52
        idle = 0
        sendalot = 1
        taop = (struct rmxp_tao *) 0x5a8
        tao_noncached = {tao_cc = 1, tao_ccsent = 0, tao_mssopt = 32}
        isipv6 = 0
#5  0xc0226445 in tcp_usr_send (so=0xc46d0cc0, flags=0, m=0xc06c2b00, nam=0x0, 
    control=0x0, p=0xc4c4f100) at ../../netinet/tcp_usrreq.c:578
        m = (struct mbuf *) 0xc06c2b00
        control = (struct mbuf *) 0x0
        s = 6422528
        error = 0
        inp = (struct inpcb *) 0x0
        tp = (struct tcpcb *) 0xc471ee40
        isipv6 = 0
        ostate = 4
#6  0xc01c4403 in sosend (so=0xc46d0cc0, addr=0x0, uio=0xc4cdfed4, 
    top=0xc06c2b00, control=0x0, flags=0, p=0xc4c4f100)
    at ../../kern/uipc_socket.c:609
        mp = (struct mbuf **) 0xc06c2b00
        m = (struct mbuf *) 0xc06c2b00
        space = 29880
        len = 0
        resid = 0
        clen = -1066652928
        error = -999486272
        s = 0
        dontroute = 0
        mlen = 2048
        atomic = 0
#7  0xc01b7a70 in soo_write (fp=0xc0c4cbc0, uio=0xc4cdfed4, cred=0xc0b87780, 
    flags=0, p=0xc4c4f100) at ../../kern/sys_socket.c:81
        fp = (struct file *) 0x0
        uio = (struct uio *) 0x0
        so = (struct socket *) 0x0
#8  0xc01b4701 in dofilewrite (p=0xc4c4f100, fp=0xc0c4cbc0, fd=3, 
    buf=0xbfbff5bc, nbyte=1024, offset=-1, flags=0) at ../../sys/file.h:162
        error = -993726208
        fp = (struct file *) 0xc0c4cbc0
        cred = (struct ucred *) 0x0
        p = (struct proc *) 0xc4c4f100
        fp = (struct file *) 0xc0c4cbc0
        offset = 0
        auio = {uio_iov = 0xc4cdfeac, uio_iovcnt = 1, uio_offset = 1023, 
  uio_resid = 0, uio_segflg = UIO_USERSPACE, uio_rw = UIO_WRITE, 
  uio_procp = 0xc4c4f100}
        aiov = {iov_base = 0xbfbff9bc "\b", iov_len = 0}
        cnt = 1024
        error = -993726208
        ktriov = {iov_base = 0xc4cdfed8 "\001", iov_len = 3224186978}
        ktruio = {uio_iov = 0x0, uio_iovcnt = 1, 
  uio_offset = -4268021561307097088, uio_resid = 0, uio_segflg = 3217029564, 
  uio_rw = UIO_READ, uio_procp = 0xc0951800}
        didktr = 0
#9  0xc01b45ba in write (p=0xc4c4f100, uap=0xc4cdff80)
    at ../../kern/sys_generic.c:329
        p = (struct proc *) 0xc4c4f100
        uap = (struct write_args *) 0xc4cdff80
        fp = (struct file *) 0xc0c4cbc0
        error = -993132672
#10 0xc02eaa99 in syscall2 (frame={tf_fs = -1078001617, tf_es = -993198033, 
      tf_ds = -1078001617, tf_edi = -1077938756, tf_esi = 1024, 
      tf_ebp = -1077937348, tf_isp = -993132588, tf_ebx = -1077937732, 
      tf_edx = 3, tf_ecx = 3, tf_eax = 4, tf_trapno = 7, tf_err = 2, 
      tf_eip = 672005944, tf_cs = 31, tf_eflags = 663, tf_esp = -1077938816, 
      tf_ss = 47}) at ../../i386/i386/trap.c:1175
        params = 0xbfbff584 "\003"
        i = 0
        callp = (struct sysent *) 0xc038d7a0
        p = (struct proc *) 0xc4c4f100
        orig_tf_eflags = 663
        sticks = 60359
        error = 0
        narg = 3
        args = {3, -1077938756, 1024, 0, 0, 0, 0, 0}
        have_mplock = 1
        code = 4
#11 0xc02de205 in Xint0x80_syscall ()
No symbol table info available.
#12 0x8048f84 in ?? ()
No symbol table info available.
#13 0x8048ae9 in ?? ()
No symbol table info available.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
To Unsubscribe: send mail to majordomo(at)de.FreeBSD.org
with "unsubscribe de-bsd-questions" in the body of the message