いろいろやっちゃってカーネルをよく落としているので、デバッグ方法のメモです。
# etherswitchcfg
etherswitch0: VLAN mode: DOT1Q
port0:
pvid: 2
flags=0<>
media: Ethernet autoselect (Trap cause = 2 (TLB miss (load or instr. fet
ch) - kernel mode)
[ thread pid 58 tid 100052 ]
Stopped at mii_attach_proxy+0x1714: lw a0,300(s0)
db>
こんなバグがあった時にとりあえずカーネルを逆アセンブラします。
mips.mipsのクロスのビルドなのでクロス用のobjdumpで逆アセンブラします。ZRouterのビルドではkernelがあるディレクトリのtmpの下にあります。
microserver % `find tmp/mips.mips -name objdump -type f | head -1` -d Buffalo_WZ
R-HP-G301NH_kernel | more
mii_attach_proxyを探します。
mii_attach_proxyはあくまでオフセットのスタートポジションで、この関数が原因ではありません。
8008eb3c <mii_attach_proxy>:
8008eb3c: 27bdffd0 addiu sp,sp,-48
8008eb40: afb30024 sw s3,36(sp)
8008eb44: 00809821 move s3,a0
8008eb48: afbf002c sw ra,44(sp)
8008eb4c: afb00018 sw s0,24(sp)
8008eb50: afb40028 sw s4,40(sp)
8008eb54: afb20020 sw s2,32(sp)
8008eb58: 0c062d23 jal 8018b48c <device_get_name>
0x8008eb3c+0x1714=0x80090250を探します。余談ですがMac OS Xの計算機アプリケーションは16進も計算できて便利です。
800901fc <rtl_getvgroup>:
800901fc: 27bdffd0 addiu sp,sp,-48
80090200: afb30024 sw s3,36(sp)
80090204: afb20020 sw s2,32(sp)
80090208: afb1001c sw s1,28(sp)
8009020c: afb00018 sw s0,24(sp)
80090210: 00809821 move s3,a0
80090214: 00a09021 move s2,a1
80090218: 27b10010 addiu s1,sp,16
8009021c: 00008021 move s0,zero
80090220: 08024094 j 80090250 <rtl_getvgroup+0x54>
80090224: afbf0028 sw ra,40(sp)
80090228: 8e420000 lw v0,0(s2)
8009022c: 26030020 addiu v1,s0,32
80090230: 24050003 li a1,3
80090234: 70452002 mul a0,v0,a1
80090238: 26100001 addiu s0,s0,1
8009023c: 00832821 addu a1,a0,v1
80090240: 0c024074 jal 800901d0 <rtl_readreg>
80090244: 02602021 move a0,s3
80090248: a6220000 sh v0,0(s1)
8009024c: 26310002 addiu s1,s1,2
80090250: 8e04012c lw a0,300(s0)
80090254: 24030002 li v1,2
80090258: 24020003 li v0,3
rtl_getvgroup()での変数の初期忘れでした。
グローバルで確保した変数をsoftcにいれた方が良いってレビューがあり、修正したところ関数内でsoftcを初期化する前にその値を使ってしまっていました。。。
落ちないどけ調べたい事がある場合は、シリアルコンソールからのブレークを送る方法やkdb_break(),panic()をカーネル内に放り込む方法があります。kdb_break()を放り込むには以下が必要です。
#include <sys/kdb.h>
またユーザランドから落とす場合は以下でできます。
sysctl debug.kdb.enter=1
or
sysctl debug.kdb.panic=1
vm_fault(0xc12868e8, 30000, 2, 0) -> 1
Fatal kernel mode data abort: 'Translation Fault (P)'
trapframe: 0xc289cd30
FSR=00000017, FAR=00030000, spsr=20000013
r0 =00030000, r1 =c1669010, r2 =000007e0, r3 =736e6f63
r4 =09656c6f, r5 =00000800, r6 =00000000, r7 =00005bc0
r8 =00000000, r9 =c164b7e0, r10=c164e940, r11=00000040
r12=73752f22, ssp=c289cd84, slr=696c2f72, pc =c11d8650
[ thread pid 12 tid 100007 ]
Stopped at memcpy+0x80: stmia r0!, {r3-r4, r12, r14}
db>
こんな感じで落ちた時は以下のように確認する。
db> show proc 12
Process 12 (geom) at 0xc150ec80:
state: NORMAL
uid: 0 gids: 0
parent: pid 0 at 0xc12862b8
ABI: null
threads: 3
100008 D - 0xc1285e50 [g_down]
100007 Run CPU 0 [g_up]
100006 D - 0xc1285e44 [g_event]
db> show thread 100007
Thread 100007 at 0xc1511330:
proc (pid 12): 0xc150ec80
name: g_up
stack: 0xc289b000-0xc289cfff
flags: 0x4010004 pflags: 0x200000
state: RUNNING (CPU 0)
priority: 92
container lock: sched lock 0 (0xc1296300)
その弐
arm/cavium/cns11xxをいじって放置してあった物をまた試してみました。
STR9100>tftpboot 0x00800000 Planex_MZK-W04G_kernel.kbin.gz.uboot
orn_drv_open
first read orn_drv_open: phy0_id:0 phy1_id:0
auto polling gsw_mac_0_phy_addr: 0
auto polling gsw_mac_1_phy_addr: 1
orn_drv_open: phy0_id:FFFF phy1_id:FFFF
orn_configure_vitesse_vsc7385()
ARP broadcast 1
eth addr: 00:00:00:00:00:00
TFTP from server 10.10.10.3
; our IP address is 10.10.10.190
Filename 'Planex_MZK-W04G_kernel.kbin.gz.uboot'.
Load address: 0x800000
Loading: #######################################################################
################################################################################
################################################################################
####################################################################
done
Bytes transferred = 1528652 (17534c hex)
STR9100>bootm
## Booting image at 00800000 ...
Image Name: FreeBSD Kernel Image
Image Type: ARM Linux Kernel Image (gzip compressed)
Data Size: 1528588 Bytes = 1492 kB = 1 MB
Load Address: 00050100
Entry Point: 00050100
Verifying Checksum ... OK
Uncompressing Kernel Image ... OK
Starting kernel ...
data abort
pc : [<00000134>] lr : [<c00a6970>]
sp : c037c630 ip : 0000ff00 fp : c037c6e8
r10: 00800040 r9 : c037c738 r8 : c037c720
r7 : 600000d3 r6 : c03c4000 r5 : c037c71c r4 : 00000000
r3 : c03548fc r2 : c00b17a4 r1 : c02dd66e r0 : c037f064
Flags: nZCv IRQs off FIQs off Mode UND_32
Resetting CPU ...
### ERROR ### Please RESET the board ###
カーネルが起動直後にdata abort割り込みを発生して、Bootが拾ってくれています。これは以前調べたarmv4t以降でしか使えないbx命令をarmv4で実行している物と思われます。
でlrが戻りアドレスなのでここで呼び出している、関数をobjdumpで確認します。
c00a696c: eb003006 bl c00b298c <OF_finddevice>
c00a6970: e1a04000 mov r4, r0
OF_finddeviceの調べてみます。
c00b298c <OF_finddevice>:
c00b298c: e92d4c70 push {r4, r5, r6, sl, fp, lr}
c00b2990: e28db010 add fp, sp, #16 ; 0x10
c00b2994: e1a06000 mov r6, r0
c00b2998: e59f0058 ldr r0, [pc, #88] ; c00b29f8 <_end+0xffcee
9f8>
c00b299c: e5900000 ldr r0, [r0]
c00b29a0: e3500000 cmp r0, #0 ; 0x0
c00b29a4: 03e00000 mvneq r0, #0 ; 0x0
c00b29a8: 08bd4c70 popeq {r4, r5, r6, sl, fp, lr}
c00b29ac: 01a0f00e moveq pc, lr
c00b29b0: e59f1048 ldr r1, [pc, #72] ; c00b2a00 <_end+0xffcee
a00>
c00b29b4: e59f3040 ldr r3, [pc, #64] ; c00b29fc <_end+0xffcee
9fc>
c00b29b8: e5915000 ldr r5, [r1]
c00b29bc: e5d30000 ldrb r0, [r3]
c00b29c0: e5952000 ldr r2, [r5]
c00b29c4: e1a01002 mov r1, r2
c00b29c8: e7b10100 ldr r0, [r1, r0, lsl #2]!
c00b29cc: e5904000 ldr r4, [r0]
c00b29d0: e1540003 cmp r4, r3
c00b29d4: 0a000002 beq c00b29e4 <OF_finddevice+0x58>
c00b29d8: e5920400 ldr r0, [r2, #1024]
c00b29dc: e59f2018 ldr r2, [pc, #24] ; c00b29fc <_end+0xffcee
9fc>
c00b29e0: eb03c6e6 bl c01a4580 <kobj_lookup_method>
c00b29e4: e5902004 ldr r2, [r0, #4]
c00b29e8: e1a00005 mov r0, r5
c00b29ec: e1a01006 mov r1, r6
c00b29f0: e8bd4c70 pop {r4, r5, r6, sl, fp, lr}
c00b29f4: e12fff12 bx r2
c00b29f8: c037f060 .word 0xc037f060
c00b29fc: c03548fc .word 0xc03548fc
c00b2a00: c037f180 .word 0xc037f180
思った通りbx命令使ってますね。clangはarmv4のコードはけるようですが、オプションが設定されていない可能性が調べてみる必要がありそうです。調べてみたらclangはarmv4なコードは対応していないようなのでgccでビルドすることにしました。
調査中
以前はちゃんと起動していたAR5312なルーターが起動しなくなってしなくなってしまいました。同じソースで同じSOCの別のルーターは何故かちゃんと起動しています。
uart0: <16550 or compatible> on apb0
Trap cause = 10 (reserved instruction - kernel mode)
[ thread pid 0 tid 100000 ]
Stopped at 0
db> where
Tracing pid 0 tid 100000 td 0x80340e20
ns8250_bus_flush+0xc (?,?,?,?) ra 800802f0 sp 80376ce0 sz 0
ns8250_bus_attach+0x160 (?,?,?,?) ra 8007b5c4 sp 80376ce0 sz 48
uart_bus_attach+0x200 (?,?,?,?) ra 0 sp 80376d10 sz 0
db> show reg
at 0
v0 0x2 _DYNAMIC_LINKING+0x1
v1 0x3 _DYNAMIC_LINKING+0x2
a0 0x8040a000
a1 0x3 _DYNAMIC_LINKING+0x2
a2 0
a3 0
t0 0x2 _DYNAMIC_LINKING+0x1
t1 0
t2 0x4 _DYNAMIC_LINKING+0x3
t3 0xcccccccc
t4 0x1 _DYNAMIC_LINKING
t5 0
t6 0
t7 0
s0 0
s1 0x80376cf8
s2 0x8040a000
s3 0x8042dc80
s4 0x8042dcd0
s5 0x802c4cd8
s6 0x802bd1f0
s7 0x802c4abc
t8 0x1 _DYNAMIC_LINKING
t9 0x80280cd0 minidumpsys+0xcf4
k0 0
k1 0x1c000022
gp 0x8033f000 _gp
sp 0x80376ce0
s8 0x80000300
ra 0x800802f0 ns8250_bus_attach+0x160
sr 0x2000c002
lo 0
hi 0
bad 0xc1f9fff0
cs 0x30008828
pc 0x8008003c ns8250_bus_flush+0xc
0
db>
objdumpでkernelを逆アセンブルしてみると
80080030 <ns8250_bus_flush>:
80080030: 27bdffd8 addiu sp,sp,-40
80080034: 3c028035 lui v0,0x8035
80080038: 8c422640 lw v0,9792(v0)
8008003c: afb20020 sw s2,32(sp)
80080040: afb1001c sw s1,28(sp)
80080044: afb00018 sw s0,24(sp)
80080048: afbf0024 sw ra,36(sp)
スタックにs2を積んでいるところで落ちている。とくにスタックも異常値ではないようなきもするのだが。
kobjの不整合
ドライバを追加したときなど、ドライバの依存に不整合がある場合には起動直後に落ちます。
KDB: debugger backends: ddb
KDB: current backend: ddb
Copyright (c) 1992-2017 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 12.0-CURRENT #69 db91580(zrouter)-dirty: Mon May 15 10:26:25 JST 2017
hiroki@microserver:/storage/home/hiroki/obj/storage/home/hiroki/zrouter/tmp/
mips.mips/storage/home/hiroki/freebsd/sys/Buffalo_WZR-HP-G300NH mips
gcc version 4.2.1 20070831 patched [FreeBSD]
Preloaded elf kernel "kernel" at 0x80384a60.
real memory = 67108864 (65536K bytes)
Physical memory chunk(s):
0x00417000 - 0x03eb6fff, 61472768 bytes (15008 pages)
avail memory = 60817408 (58MB)
arc4random: no preloaded entropy cache
random: entropy device external interface
mem: <memory>
null: <full device, null device, zero device>
Trap cause = 2 (TLB miss (load or instr. fetch) - kernel mode)
[ thread pid 0 tid 100000 ]
Stopped at 0
db> w
Nothing written.
KDB: reentering
KDB: stack backtrace:
db_trace_self+0x14 (?,?,?,?) ra 8004b334 sp 8039c788 sz 8
db_fetch_ksymtab+0x2a4 (?,?,?,?) ra 8016ce20 sp 8039c790 sz 416
kdb_reenter+0x44 (?,?,?,?) ra 0 sp 8039c930 sz 0
db> show reg
at 0
v0 0x8fbf0038
v1 0x350000
a0 0x8032c858 rtl8366rbmdio_driver
a1 0x8056a000
a2 0x802ad958 asc_table_size+0x36ac
a3 0x45 _DYNAMIC_LINKING+0x44
t0 0
t1 0x2c _DYNAMIC_LINKING+0x2b
t2 0x80505eb0
t3 0
t4 0
t5 0x16000
t6 0
t7 0
s0 0x8056a000
s1 0x8032c858 rtl8366rbmdio_driver
s2 0x8032c858 rtl8366rbmdio_driver
s3 0x80515a00
s4 0x80363ba0 miiproxy_devclass+0x10
s5 0x83ff0000
s6 0
s7 0x83f80015
t8 0
t9 0
k0 0x7 _DYNAMIC_LINKING+0x6
k1 0x83ffcea0
gp 0x80367880 _gp
sp 0x8039cdf0
s8 0x83ff0000
ra 0x8016d4e8 kobj_class_compile+0x94
sr 0x2 _DYNAMIC_LINKING+0x1
lo 0xfffab8c0
hi 0x13 _DYNAMIC_LINKING+0x12
bad 0x350000
cs 0x40008008
pc 0x8016d124 kobj_error_method+0x34
0
db> w
Nothing written.
KDB: reentering
KDB: stack backtrace:
db_trace_self+0x14 (?,?,?,?) ra 8004b334 sp 8039c788 sz 8
db_fetch_ksymtab+0x2a4 (?,?,?,?) ra 8016ce20 sp 8039c790 sz 416
kdb_reenter+0x44 (?,?,?,?) ra 0 sp 8039c930 sz 0
rtl8366rbmdio_driverを追加したんですが、なにかおかしいみたいです。
bhnd_pmu0: WARNING: Using untested PWRCTL support
Trap cause = 13 (trap - kernel mode)
[ thread pid 0 tid 100000 ]
Stopped at 0
db> where
Tracing pid 0 tid 100000 td 0x802eede0
bhnd_pwrctl_setclk+0x83c (?,?,?,?) ra 80029370 sp 80323c78 sz 0
bhnd_pwrctl_setclk+0x888 (?,?,?,?) ra 0 sp 80323c78 sz 0
該当箇所は
800292fc: 0083001b divu zero,a0,v1
80029300: 006001f4 teq v1,zero,0x7
で0除算でした。
```
reroot失敗
reboot -rでrerootという機能が使えるのだが時々下記のエラーがでて失敗していた。
Jan 1 09:01:04 init: cannot mount tmpfs on /dev/reroot: No space left on device
Jan 1 09:01:04 init: reroot failed; going to single user mode
initのコードを読んでみるとnmountに失敗しているようだ。"No space left on device"をsysの下でgrepしてみたが、関係のありそうなところがない。"No space left on device"はENOSPCでsys/kernには返しているところはない。sys/fs/tmpfsを調べてみると何カ所かある。とりあえずデバッグライトを入れて確認したら、tmpfs_vfsops.cのTMPFS_PAGES_MINRESERVEDのチェックに引っかかってしまっていた。
ブレークは効くけど黙り
db> show thread
Thread 100018 at 0xc07313c0:
proc (pid 0): 0xc03d2ee8
name: rt28600 net80211 ta
stack: 0xc0678000-0xc0679fff
flags: 0x5010004 pflags: 0x200000
state: RUNNING (CPU 0)
priority: 8
container lock: sched lock (0xc03c2344)
last voluntary switch: 3103280 ms ago
最後のlast voluntary switchが怪しいですね。なんでswitchしないのかな？
AR5312
何故かビルドすると不安定な事があります。普通に上がる事もあります。
db> where
Tracing pid 15 tid 100035 td 0x8054b780
kdb_enter+0x48 (?,?,?,?) ra 800c2140 sp c33cbb58 sz 24
vpanic+0x124 (?,?,?,?) ra 800c21d0 sp c33cbb70 sz 32
shutdown_nice (?,0,0,0) ra 80234294 sp c33cbb90 sz 32
trap+0x2c0 (?,?,?,?) ra 80222bf0 sp c33cbbb0 sz 216
MipsKernGenException+0x134 (?,?,?,?) ra 0 sp c33cbc88 sz 0
--- exception, cause ffffffff8041e58c badvaddr 76e71b50 ---
fdcopy_remapped+0x22c (?,?,?,?) ra 80080204 sp c33cbd50 sz 40
kern_close+0xa4 (?,?,?,?) ra 80234818 sp c33cbd78 sz 48
trap+0x844 (?,?,?,?) ra 0 sp c33cbda8 sz 0
Comcerto 1000
ずっとほっておいたのですが、ちょっと見てみました。
cd9660: RockRidge Extension
Warning: no time-of-day clock registered, system time will not be set accurately
start_init: trying /sbin/init
Fatal kernel mode data abort: 'Translation Fault (L1)' on read
trapframe: 0xca4e2cb0
FSR=00000005, FAR=b8ee511c, spsr=60000113
r0 =c0d5b5ff, r1 =0000001f, r2 =fe06adaf, r3 =ca4e2d34
r4 =c0d28000, r5 =c0d280bc, r6 =b8ee46bc, r7 =c0d39000
r8 =c0d5b600, r9 =c0d2c000, r10=c0d39ab8, r11=ca4e2d60
r12=00000000, ssp=ca4e2d40, slr=c0d2c000, pc =c010f120
panic: Fatal abort
time = 2
KDB: enter: panic
[ thread pid 1 tid 100001 ]
Stopped at kdb_enter+0x48: ldrb r15, [r15, r15, ror r15]!
db> show pmap
省略
0xFBF00000: Section 0x2001041A, s:1 g:1
0xFC000000: Section 0x2011041A, s:1 g:1
0xFC100000: Section 0x2021041A, s:1 g:1
0xFC200000: Section 0x2031041A, s:1 g:1
0xFC300000: Section 0x2041041A, s:1 g:1
0xFC400000: Section 0x2051041A, s:1 g:1
0xFC500000: Section 0x2061041A, s:1 g:1
0xFC600000: Section 0x2071041A, s:1 g:1
0xFC700000: Section 0x2081041A, s:1 g:1
0xFC800000: Section 0x2091041A, s:1 g:1
0xFC900000: Section 0x20A1041A, s:1 g:1
0xFCA00000: Section 0x20B1041A, s:1 g:1
0xFCB00000: Section 0x20C1041A, s:1 g:1
0xFCC00000: Section 0x20D1041A, s:1 g:1
0xFCD00000: Section 0x20E1041A, s:1 g:1
0xFCE00000: Section 0x20F1041A, s:1 g:1
0xFCF00000: Section 0x2101041A, s:1 g:1
0xFD000000: Section 0x2111041A, s:1 g:1
0xFD100000: Section 0x2121041A, s:1 g:1
0xFD200000: Section 0x2131041A, s:1 g:1
0xFD300000: Section 0x2141041A, s:1 g:1
0xFD400000: Section 0x2151041A, s:1 g:1
0xFD500000: Section 0x2161041A, s:1 g:1
0xFD600000: Section 0x2171041A, s:1 g:1
0xFD700000: Section 0x2181041A, s:1 g:1
0xFD800000: Section 0x2191041A, s:1 g:1
0xFD900000: Section 0x21A1041A, s:1 g:1
0xFDA00000: Section 0x21B1041A, s:1 g:1
0xFDB00000: Section 0x21C1041A, s:1 g:1
0xFDC00000: Section 0x21D1041A, s:1 g:1
0xFDD00000: Section 0x21E1041A, s:1 g:1
0xFDE00000: Section 0x21F1041A, s:1 g:1
0xFDF00000: Section 0x1001041A, s:1 g:1
0xFE000000: Section 0x1011041A, s:1 g:1
0xFE100000: Section 0x1021041A, s:1 g:1
0xFE200000: Section 0x1031041A, s:1 g:1
0xFE300000: Section 0x1041041A, s:1 g:1
0xFE400000: Section 0x1051041A, s:1 g:1
0xFE500000: Section 0x1061041A, s:1 g:1
0xFE600000: Section 0x1071041A, s:1 g:1
0xFE700000: Section 0x1081041A, s:1 g:1
0xFE800000: Section 0x1091041A, s:1 g:1
0xFE900000: Section 0x10A1041A, s:1 g:1
0xFEA00000: Section 0x10B1041A, s:1 g:1
0xFEB00000: Section 0x10C1041A, s:1 g:1
0xFEC00000: Section 0x10D1041A, s:1 g:1
0xFED00000: Section 0x10E1041A, s:1 g:1
0xFEE00000: Section 0x10F1041A, s:1 g:1
0xFEF00000: Section 0x1101041A, s:1 g:1
0xFF000000: Section 0x1111041A, s:1 g:1
0xFF100000: Section 0x1121041A, s:1 g:1
0xFF200000: Section 0x1131041A, s:1 g:1
0xFF300000: Section 0x1141041A, s:1 g:1
0xFF400000: Section 0x1151041A, s:1 g:1
0xFF500000: Section 0x1161041A, s:1 g:1
0xFF600000: Section 0x1171041A, s:1 g:1
0xFF700000: Section 0x1181041A, s:1 g:1
0xFF800000: Section 0x1191041A, s:1 g:1
0xFF900000: Section 0x11A1041A, s:1 g:1
0xFFA00000: Section 0x11B1041A, s:1 g:1
0xFFB00000: Section 0x11C1041A, s:1 g:1
0xFFC00000: Section 0x11D1041A, s:1 g:1
0xFFD00000: Section 0x11E1041A, s:1 g:1
0xFFE00000: Section 0x11F1041A, s:1 g:1
0xFFF00000: Link 0x80426C01, pt2tab: 0x80426412 m: 0
0xFFFF0000: 0x80425412, TEX0, s:1, g:1, m:0
db>
Flashが0x20000000から32Mあり、その部分のテーブルはあるようですが、ちゃんと読めないケースがあるような気がします。
kernelとユーザランドの不整合のためです。
シリアルコンソール
i386やamd64のマシンでpoweroffの処理をデバッグするのにビデオコンソールだとデバッグメッセージが表示されてすぐにコンソールが落ちてしまうので、確認できません。この場合はシリアルコンソールが有効です。
シリアルコンソールを有効にしてpoweroffを実行したところ、以下の行が最後に出力されてました。
acpi0: Powering system off
いろいろ
ある期間のcommitで問題が出た場合にはgitで作業している場合は以下でログを確認する。
% git log <ok id>..<ng id>
--name-statusオプションを付けるとファイル名も表示される。
armなどの場合llvmのビルドに時間がかかるので、llvmの入れ替えのタイミングを考慮して調べるのが良いです。
メインラインのカーネルの不具合のパターンは、修正における考慮漏れ副作用などがある。考慮漏れはコンパイラー(gcc,clang)やプラットフォーム(arm,mipsなど)やエンディアン(Big,Little)などが考えられる。
落ちずにハングアップして、ブレークも効かないのが一番厄介です。。。
参考資料
FreeBSD Developers' Handbook Kernel Debugging
Introduction to Debugging the FreeBSD Kernel
Debugging Kernel Problems