How to analyze system panic

nimysun

A Case Study on debugging a system panic due to memory corruption.
System panics due to kernel heap corruption
    The system panicked multiple times.  This crash dump was taken after setting kmem_flags.
SolarisCAT(vmcore.4):10> stat
core file:      /cores/63804466/vmcore.4
user:           Cores User (cores:911)
release:        5.8 (64-bit)
version:        Generic_108528-24
machine:        sun4u
node name:      ltdu2
hw_provider:    Sun_Microsystems
system type:    SUNW,Ultra-60
hostid:         80bb0d02
kmem_flags:     0x3f (AUDIT|DEADBEEF|REDZONE|CONTENTS|STICKY|NOMAGAZINE)
time of crash:  Mon Nov  3 08:22:03 MST 2003
age of system:  3 minutes 27.63 seconds
panic cpu:      2
panic string:   kernel heap corruption detected
    This system is running Solaris 8 system with KU-24.  The kmem_flags is set to 0x3f
    kmem_flags should be set on a case by case basis.  In this case 0xf would have been sufficient.  See the following infodocs for more info about kmem_flags:
    73364 How to use Solaris[TM] kmem_flags
    20548 How To: Tracking kernel memory problems
    MDB guide to set kmem_flags:
   
http://docs.sun.com/db/doc/806-5194/6je7ktflt?a=view
    "Magazines and Vmem" by Jeff Bonwick is also a good read.
   
http://www.usenix.org/event/usenix01/full_papers/bonwick/bonwick_html/index.html
    The panic string is "kernel heap corruption detected".  The message buffer should have more information on what kind of corruption was detected by kernel memory subsystem
SolarisCAT(vmcore.4)> msgbuf
SunOS Release 5.8 Version Generic_108528-24 64-bit
Copyright 1983-2003 Sun Microsystems, Inc.  All rights reserved.
Ethernet address = 8:0:20:bb:d:2
mem = 1048576K (0x40000000)
avail mem = 978812928
.
.
nkqt Driver v3.5
Copyright (c) BLT Softix, Inc.
PCI-device: pci1214,370a@4, nkqt0
nkqt0 is /pci@1f,4000/pci1214,370a@4
nkqt[0] PCI37xPQ @0x30004b42000[0x80000]:0x30004b40000[0x80]
kernel memory allocator: buffer modified after being freed
modification occurred at offset 0x10 (0xdeadbeef replaced by 0x0)
buffer=30002dd10e0  bufctl=30003ee30a0  cache: streams_dblk_8
previous transaction on buffer 30002dd10e0:
thread=2a10015dd20  time=T-10.786029541  slab=30002ea4600  cache:
streams_dblk_8
kmem_cache_free+28
tcp_rput_data+2c5c
putnext+1cc
ip_rput_local+998
ip_rput+12c4
putnext+1cc
hmeread+33c
hmeintr+374
pci_intr_wrapper+80
panic[cpu2]/thread=3000481f7c0: kernel heap corruption detected
.
.
    Note the following line above:
    "kernel memory allocator: buffer modified after being freed"
    When a buffer is freed, it's filled with a pattern "0xdeadbeef".  And when it's allocated, it's filled with a pattern "0xbaddcafe".  Note that this is done only if kmem_flags are enabled.
    While allocating a buffer, it's checked if the buffer still has the freed pattern.  If not, then that means the buffer was modified after it was freed.  When this kind of corruption is detected, the system panics.
    The message buffer also shows that the thread that attempted to allocate the buffer is 0x3000481f7c0 and the address of the buffer that it tried to allocate is 0x30002dd10e0.
    Before proceeding on nailing the culprit, it's always better to double check what's reported is indeed correct.  Looking at the thread 0x3000481f7c0 to double-check if it's allocating a buffer:
SolarisCAT(vmcore.4)> thread 0x3000481f7c0
==== panic user thread: 0x3000481f7c0  pid: 428  on cpu: 2 ====
cmd: /nblm/mgr/bin/PLLKP_mgr
t_stk: 0x2a100537af0  sp: 0x10423341  t_stkbase: 0x2a100534000
t_pri: 55(TS)  pctcpu: 0.088029  t_lwp: 0x300048311b8  machpcb: 0x2a100537af0
t_procp: 0x300049b5558  p_as: 0x30002c5a140  hat: 0x3000290ea08  cnum: 0xc7
  size: 5742592  rss: 1933312
last cpuid: 2
idle: 1 ticks (0.01 seconds)
start: Mon Nov  3 20:51:58 2003
age: 5 seconds (5 seconds)
stime: 20662 (1.01 seconds earlier)
syscall: write (0x3, 0x0, 0x440a4)
tstate: TS_ONPROC - thread is being run on a processor
tflg:   T_PANIC - thread initiated a system panic
tpflg:  TP_TWAIT - wait to be freed by lwp_wait
tsched: TS_LOAD - thread is in memory
        TS_DONT_SWAP - thread/LWP should not be swapped
pflag:  SLOAD - in core
        SULOAD - u-block in core
pc: 0x10046e8c  unix:panicsys+0x44:     call    unix:setjmp
   0x10423b40 unix:panicsys+0x44 (0x10423d10, 0x2a100537438, 0x10143fe0,0x78002000, 0x2000, 0x0)
   0x10423c60 unix:vpanic+0xcc (0x10143fe0, 0x2a100537438, 0x80,
0x2a100537398, 0x10242938, 0x30002e987f8)
0x2a100537300 unix:panic+0x1c (0x10143fe0, 0x30002dd10e0, 0x10438790,
0x30003ee30a0, 0x9, 0x0)
0x2a1005373b0 genunix:kmem_error+0x448 (0x1042f400, 0x30000032c00,
0x30002dd1160, 0x0, 0x30000032c00, 0x30002dd10e0)
0x2a100537460 genunix:kmem_cache_alloc_debug+0xf8 (0xdeadbeef,
0x300f700c44e, 0x1, 0x30002dd1160, 0x30002dd10e0, 0x30000032c00)
              genunix:kmem_cache_alloc - frame recycled
0x2a100537510 genunix:allocb+0x7c (0x0, 0x2, 0x3, 0xffbef618, 0x311ad8, 0xff00)
0x2a1005375c0 genunix:strmakedata+0xd0 (0x3, 0x300048088d8, 0x300048088d8,
0x0, 0x0, 0x1)
0x2a100537680 genunix:strput+0x15c (0x0, 0x2a100537a00, 0x300049afdf8, 0x0,
0x0, 0x0)
0x2a100537870 genunix:strwrite+0x200 (0x850, 0x2a100537930, 0x300035a3340,
0x1000000, 0x300049b1da8, 0x2a100537a00)
              specfs:spec_write - frame recycled
0x2a100537940 genunix:write+0x204 (0x12, 0x3, 0x83, 0x30004589e70, 0x2, 0x3)
0x2a100537a40 genunix:write32+0x30 (0x2, 0xff1bfbac, 0x3, 0xff3e7760,
0x2d634, 0xff3c09e8)
0x2a100537af0 unix:syscall_trap32+0xa8 (0x2, 0xff1bfbac, 0x3, 0xff3e7760,
0x2d634, 0xff3c09e8)
-- switch to user thread's user stack --
    The stack shows kmem_cache_alloc().  This means that this thread was trying to allocate a buffer.  Looking at the buffer itself to check if it's indeed corrupt:
SolarisCAT(vmcore.4)> rd32 30002dd10e0 10
0x30002dd10e0 = 0xdeadbeef
0x30002dd10e4 = 0xdeadbeef
0x30002dd10e8 = 0xdeadbeef
0x30002dd10ec = 0xdeadbeef
0x30002dd10f0 = 0x0            rd64 30002dd10e0 5
0x30002dd10e0 = 0xdeadbeefdeadbeef
0x30002dd10e8 = 0xdeadbeefdeadbeef
0x30002dd10f0 = 0x3fa6729b   
    A free buffer should show only "0xdeadbeef" pattern.  But this buffer shows some hex values.  This means that this buffer is corrupt.  16 bytes from 0x30002dd10f0 to 0x30002dd10ff are corrupted. Incidentally, the value at 0x30002dd10f0 shows "time".
SolarisCAT(vmcore.4)> rd64 time
0x1046cb78 genunix(bss):time+0x0 = 0x3fa6729b
    With kmem_flags enabled, a finite history of the users of the buffer is saved.  This history shows the user thread id, what operation they did (allocate/free) and even the stack.
    At this time we should check the history of the buffer to see which thread was using this buffer before it was freed and what that thread is doing now.  The stack will enable us to locate the line where this buffer was freed.  Then look at the source code to see if there are any references to the memory after it's freed.
    From past experience it's possible that corruption can be caused by third party modules.  However do not immediately discount Sun kernel code.  It's always worth checking and eliminating the suspicion on third party modules before looking into our source code.  From the output of modinfo command, manually select the third party modules.
SolarisCAT(vmcore.4):14> modinfo
id flags        modctl      textaddr     size cnt name
.
.
120 LI    0x30004559750    0x102c5b34  0x50015   1 tpx (BLT Softix TPX Mux Driver v3.5)
121 LI    0x30004559588    0x102d1c95  0x1d217   1 nkqt (nkqt Driver v3.5)
122 LI    0x30004558ad8    0x1030fcba   0x2681   1 blmod (BLT Softix BLMOD Module v3.5)
.
.   
tpx
    Three third party modules/drivers:  tpx, nkqt & blmod
    The stack of the thread also shows the functions strwrite(), strput(), strmakedata() and allocb().  These are STREAMS functions.  allocb(9F) allocates a streams message block. If the modules listed above are STREAMS modules, then the suspicion remains.
SolarisCAT(vmcore.4):15> stream -s | egrep "tpx|nkqt|blmod"
0x300049ade08 W strwhead tpx
              R tpx strrhead
0x300048083f8 W strwhead tpx
              R tpx strrhead
0x300048088d8 W strwhead tpx
              R tpx strrhead
0x30004808598 W tpx blmod nkqt
              R nkqt blmod tpx
0x30004808a78 W strwhead tpx
              R tpx strrhead
    We see these modules on the output.  This means that these modules are indeed STREAMS modules.
    On a side note, the 'tpx' module appear as the last module on the write side on some streams and as the first module on the write side on some streams.  That means that its a multiplexor.  'nkqt' appears only as the list module on the write side.  This has to be a driver. 'blmod' appears only in between.  Hence it's a module.
    As the suspicion of third party modules has not been eliminated, we'll look at the buffers history to check if any of these modules had used this buffer before.
SolarisCAT(vmcore.4)> kma log 0x30002dd10e0 | egrep "tpx|nkqt|blmod"
SolarisCAT(vmcore.4)>
    No third party modules were involved in handling this buffer.  Maybe we should look at who used the buffer last and dig into our source.
    But, before that let proceed on a vague idea.  We had noticed earlier that the bytes written to the freed memory was the value of 'time'.  We'll search for the value of time in other buffers in the memory.  If we do find similar pattern then we can check if they were handled by these third party modules.
SolarisCAT(vmcore.4):552> findval -32 0x3fa6729b > /tmp/fval
    1. Edit the /tmp/fval file.  Change the lines from:
       0x30004c97404 = 0x3fa6729b
       0x30004c974c4 = 0x3fa6729b
       0x30004c97584 = 0x3fa6729b
       .
       .
       To:
       kma audit 0x30004c97404
       kma audit 0x30004c974c4
       kma audit 0x30004c97584
       .
       .
       This can be done in vi by pattern substitution.
    2. Give execute permission to this file
    3. Execute the file.
       This would give the audit data for all addresses which have the value of 'time' in it.
SolarisCAT(vmcore.4)> /tmp/fval >/tmp/fval.out
    4. Filter the output to search for freed buffers.
       If the buffer is allocated, then any corruption will not be easily visible.  But it's easy to spot corruption in a freed buffer.
SolarisCAT(vmcore.4):602>  egrep "bufctl:|bxstat|addr:" /tmp/fval.out
.
.
bufctl:     0x30003ee0180
bxstat:     0x300f700f56e (FREE)
addr:       0x30002dd01e0
bufctl:     0x30003ee2320
bxstat:     0x300f700d7ce (FREE)
addr:       0x30002dd0b40
bufctl:     0x30003ee30a0
bxstat:     0x300a2fef84d (ALLOC)
addr:       0x30002dd10e0            
    There are three buffers which are free and one is in the process of being allocated.  The buffer which caused the panic is marked ALLOC but contains the pattern "0xdeadbeef" as process of allocation is in progress.
    First verify if these buffers contains the pattern we are looking for:
SolarisCAT(vmcore.4)> rd64 0x30002dd01e0 5
0x30002dd01e0 = 0xdeadbeefdeadbeef
0x30002dd01e8 = 0xdeadbeefdeadbeef
0x30002dd01f0 = 0x3fa6729b
0x30002dd01f8 = 0x511a
0x30002dd0200 = 0xdeadbeefdeadbeef
SolarisCAT(vmcore.4)> rd64 0x30002dd0b40 5
0x30002dd0b40 = 0xdeadbeefdeadbeef
0x30002dd0b48 = 0xdeadbeefdeadbeef
0x30002dd0b50 = 0x3fa6729b
0x30002dd0b58 = 0x511a
0x30002dd0b60 = 0xdeadbeefdeadbeef
SolarisCAT(vmcore.4)> rd64 0x30002dd10e0 5
0x30002dd10e0 = 0xdeadbeefdeadbeef
0x30002dd10e8 = 0xdeadbeefdeadbeef
0x30002dd10f0 = 0x3fa6729b
0x30002dd10f8 = 0x511a
0x30002dd1100 = 0xdeadbeefdeadbeef
SolarisCAT(vmcore.4)> rd64 0x30002dd1220 5
0x30002dd1220 = 0xdeadbeefdeadbeef
0x30002dd1228 = 0xdeadbeefdeadbeef
0x30002dd1230 = 0x3fa6729b
0x30002dd1238 = 0x511a
0x30002dd1240 = 0xdeadbeefdeadbeef
    The three buffers contain the same pattern as the one which caused the panic. So, these buffers were corrupted by the same source as the one which caused the panic.
    Remember that we still haven't discarded the idea of third party modules being the culprit.  Lets check if these buffers were handled by the third party modules.
SolarisCAT(vmcore.4)> kma log 0x30002dd01e0 | egrep "tpx|nkqt|blmod"
SolarisCAT(vmcore.4)> kma log 0x30002dd0b40 | egrep "tpx|nkqt|blmod"
SolarisCAT(vmcore.4)> kma log 0x30002dd1220 | egrep "tpx|nkqt|blmod"
SolarisCAT(vmcore.4)>
    Although all the four known buffers were corrupted with the same pattern, none of them were handled by the third party modules. Audit log of each of the four buffers does not show any common pattern either.
    However, lets look at the buffers located just *before* these four buffers.  To find the previous buffer, subtract 4 bytes from the current buffer and run 'kma audit' on it.  This would give the address of the new buffer.
SolarisCAT(vmcore.4)> kma audit 0x30002dd01e0-4 | grep "^addr"
addr:       0x30002dd0140
SolarisCAT(vmcore.4)> kma audit 0x30002dd0b40-4 | grep "^addr"
addr:       0x30002dd0aa0
SolarisCAT(vmcore.4)> kma audit 0x30002dd10e0-4 | grep "^addr"
addr:       0x30002dd1040
SolarisCAT(vmcore.4)> kma audit 0x30002dd1220-4 | grep "^addr"
addr:       0x30002dd1180
    Running audit on these four buffers shows the exactly same stack:
SolarisCAT(vmcore.4)> kma audit 0x30002dd1180
0x30002dd1180 found in:
cache:      0x30000027000 (kmem_va_8192) size 8192 (quantum cache)
slab:       0x300027daec0
buf:        0x30002dd0000 (addr not at start of buf, offset 0x1180)
  buf found in hash bucket 744 @ 0x300048c7740 entry 0, bufctl @ 0x30002d09c20
  buf not found in its slab's freelist or live magazine (buf is ALLOC)
0x30002dd1180 found in:
cache:      0x30000032c00 (streams_dblk_8) size 128
slab:       0x30002ea4600
buf:        0x30002dd1180
  buf found on slab freelist (bufctl @ 0x30003ee2fe0) (buf is FREE)
kmem_buftag @ 0x30002dd1200
redzone:    0xfeedfacefeedface
bufctl:     0x30003ee2fe0
bxstat:     0x300f700db0e (FREE)
kmem_bufctl_audit @ 0x30003ee2fe0
next:       0x30003ee2920
addr:       0x30002dd1180
slab:       0x30002ea4600
cache:      0x30000032c00 (streams_dblk_8) size 128
timestamp:  0x3f23401c2e (1 minutes 3.544343726 seconds later)
thread:     0x3000481f7c0
lastlog:    0x30000799ba0
contents:   0x300014d6ea0
  genunix:kmem_cache_free+0x28
  genunix:freemsg+0x9c
  tpx:cmn_alarm_sanity_check+0xe8tpx
  tpx:tpx_send2alarm+0xc
  tpx:tpx_route_ss7msg+0x8c
  tpx:tpxuwsrv+0x5c
  genunix:runservice+0x3c
  genunix:queuerun+0x160
  genunix:strput+0x26c
  genunix:strwrite+0x200
  genunix:write+0x204
  genunix:write32+0x30
    From this we can easily conclude that the 3rd party modules were
    corrupting the buffers.
    This is what happened here:
     - tpx module freed the buffers it was using and then it chose a wrong
       offset and wrote at that location.
                                OR
       tpx module wrote to a wrong offset and then freed the buffer
     - This wrong offset was large enough to make it point into the
       adjacent buffer and not its own.
     - Incidentally this adjacent buffer was freed when this happened.
     - An attempt to allocate that adjacent buffer resulted in a panic.
    If the adjacent buffer was allocated, the result would have been
    corruption of another thread's active buffer causing unpredictable
    behavior.
    Also of interest is what 'tpx' appears to have written in each buffer
    in the last second. This could help the 3rd party find the issue.
SolarisCAT(vmcore.4)> findval 0x511a
.
.
0x1041d360 unix(data):panic_cpu+0xc0 = 0x511a
    'panic_cpu' is a structure of type 'cpu_t'
SolarisCAT(vmcore.4)> stype cpu_t | grep 0xc0
   typedef clock_t = long/long long cpu_last_swtch; (offset 0xc0 bytes,
size 0x8 bytes)
    That is the time in ticks since the last time the CPU exchanged
    threads.
SolarisCAT(vmcore.4)> findval -32 0x3fa6729b
.
.
0x1046cb7c genunix(bss):time+0x4 = 0x3fa6729b
    This is the time in seconds since 1970 which is kept for compatibility
    purpose only.
Summary:
This case study shows that users of a buffer catching a memory corruption  may not be actually involved in the corruption.
Memory corruptions can be extremely difficult to find the root cause even with kmem_flags set.  A culprit can not only corrupt its own buffers, but its adjacent buffers too as shown by this case study.  Well, theoretically, a kernel module can corrupt any part of the kernel and even kmem_flags may not be able to nail the culprit!
Setting kmem_flags helps in
  - confirming that there is indeed a memory corruption and not any other bug.
  - identifying the culprit.  Although this may not be possible depending on th e complexity of the corruption.


At the end, I could only tell myself I can not master this tech for ever


本文来自ChinaUnix博客，如果查看原文请点：http://blog.chinaunix.net/u/43/showart_96839.html