Hi.
It seems I catched some bug in kernel. I use some ugly program which
connects to COM-port and tries to do some activity.
You can see it's source here http://pastebin.com/kHLy26GD
I start it and try to kill it
# ./ct
writing bytes 36 [ 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
0 0 ff 0 0 0 ff 0 0 0 2 e0 41 df ]
read 0 bytes [ 0 0 0 0 0 0 0 0 0 0 0 0 0 ]
writing bytes 13 [ 1 80 0 0 4 0 2 17 f0 0 0 0 0 ]
read 0 bytes [ 0 0 0 0 0 0 0 0 0 0 0 0 0 ]
writing bytes 13 [ 1 80 0 0 4 0 2 17 f0 0 0 0 0 ]
read 0 bytes [ 0 0 0 0 0 0 0 0 0 0 0 0 0 ]
writing bytes 13 [ 1 80 0 0 4 0 2 17 f0 0 0 0 0 ]
read 0 bytes [ 0 0 0 0 0 0 0 0 0 0 0 0 0 ]
writing bytes 13 [ 1 80 0 0 4 0 2 17 f0 0 0 0 0 ]
^C
...and here I can't even kill -KILL it.
I drop into ddb and gather some information. Then I tried to do "boot
sync" and seen panic.
I'm a little confused about root of the bug - is it COM-port related
issue or "idle" related issue.
login: Stopped at Debugger+0x4: popl %ebp
ddb> trace
Debugger(0,3f8,0,d073c119,b0) at Debugger+0x4
comintr(d155f000) at comintr+0x287
Xrecurse_legacy4() at Xrecurse_legacy4+0xb3
--- interrupt ---
apm_cpu_idle(d03d9015,d0a2ee34,d0ae9220,d989b000,d5d3b13c) at apm_cpu_idle+0x8a
cpu_idle_cycle(d0ae9220) at cpu_idle_cycle+0xc
Bad frame pointer: 0xd0ba0e48
ddb> ps
PID PPID PGRP UID S FLAGS WAIT COMMAND
28942 12726 28942 0 3 0x6080 ttyout ct
12726 4622 12726 0 3 0x4080 pause ksh
7904 1 7904 0 3 0x4080 ttyin getty
9697 1 9697 0 3 0x4080 ttyin getty
11903 1 11903 0 3 0x4080 ttyin getty
7081 1 7081 0 3 0x4080 ttyin getty
2033 1 2033 0 3 0x4080 ttyin getty
24882 1 24882 0 3 0x4080 ttyin getty
11773 1 11773 0 3 0x80 select cron
4622 2038 4622 0 3 0x4080 select sshd
11364 1 11364 77 3 0x180 poll dhclient
7987 1 7987 0 3 0x40180 select sendmail
21377 1 10736 0 3 0x80 poll dhclient
12123 31014 10736 0 3 0x80 netio tcpdump
31014 1 10736 76 3 0x4180 bpf tcpdump
18935 1 18935 0 3 0x180 select inetd
2038 1 2038 0 3 0x80 select sshd
2509 12112 12112 74 3 0x180 bpf pflogd
12112 1 12112 0 3 0x80 netio pflogd
25827 10246 10246 73 3 0x180 poll syslogd
10246 1 10246 0 3 0x88 netio syslogd
9966 1 9966 0 3 0x80 mfsidl mount_mfs
14 0 0 0 3 0x100200 aiodoned aiodoned
13 0 0 0 3 0x100200 syncer update
12 0 0 0 3 0x100200 cleaner cleaner
11 0 0 0 3 0x100200 reaper reaper
10 0 0 0 3 0x100200 pgdaemon pagedaemon
9 0 0 0 3 0x100200 bored crypto
8 0 0 0 3 0x100200 pftm pfpurge
7 0 0 0 3 0x100200 usbtsk usbtask
6 0 0 0 3 0x100200 usbatsk usbatsk
5 0 0 0 3 0x100200 apmev apm0
4 0 0 0 3 0x100200 bored syswq
* 3 0 0 0 7 0x40100200 idle0
2 0 0 0 3 0x100200 kmalloc kmthread
1 0 1 0 3 0x4080 wait init
0 -1 0 0 3 0x80200 scheduler swapper
ddb> show registers
ds 0x10
es 0xd0200010 kernel_text+0x10
fs 0x120058
gs 0xd9890010 end+0x8da418c
edi 0xd1535a60 end+0xa49bdc
esi 0xd155f0ac end+0xa73228
ebp 0xd989ce90 end+0x8db100c
ebx 0xf9
edx 0x3f8
ecx 0xd155f000 end+0xa7317c
eax 0x1
eip 0xd056bf44 Debugger+0x4
cs 0xd0200050 kernel_text+0x50
eflags 0x202
esp 0xd989ce90 end+0x8db100c
ss 0xd9890010 end+0x8da418c
Debugger+0x4: popl %ebp
ddb> show panic
the kernel did not panic
ddb> show extents
extent `swap0x0000' (0x0 - 0xff45), flags=0
0x0 - 0x0
extent `swapmap' (0x1 - 0x7fffffff), flags=0
0x1 - 0xff46
extent `pcimem' (0x0 - 0xffffffff), flags=0
0x1000 - 0x1fffffff
0xf8000000 - 0xfbffffff
0xfebd9000 - 0xfebdafff
0xfebdb400 - 0xfebdb4ff
0xfebdb800 - 0xfebdb8ff
0xfebdbc00 - 0xfebdbcff
0xfebdc000 - 0xfebfffff
0xff000000 - 0xffffffff
extent `pciio' (0x0 - 0xffffffff), flags=0
0x5800 - 0x5817
0xde00 - 0xdeff
0xdf80 - 0xdfff
0xef00 - 0xef0f
0x10000 - 0xffffffff
extent `PCI I/O port space' (0x0 - 0xffff), flags=0
0x5800 - 0x5817
0xde00 - 0xdeff
0xdf80 - 0xdfff
0xef00 - 0xef0f
extent `PCI I/O memory space' (0x0 - 0xffffffff), flags=0
0xf8000000 - 0xfbffffff
0xfebd9000 - 0xfebdafff
0xfebdb400 - 0xfebdb4ff
0xfebdb800 - 0xfebdb8ff
0xfebdbc00 - 0xfebdbcff
0xfebdc000 - 0xfecfffff
0xfee00000 - 0xfeefffff
0xfffe0000 - 0xffffffff
extent `iomem' (0x0 - 0xffffffff), flags=3<NOCOALESCE,FIXED>
0x400 - 0xfff
0x2000 - 0x214b
0x8000 - 0x9efff
0xa0000 - 0xbffff
0xc0000 - 0xc7fff
0xe9400 - 0xe95ff
0xf0000 - 0xfffff
0x100000 - 0x1fffffff
0xfebd9000 - 0xfebd9fff
0xfebda000 - 0xfebdafff
0xfebdb400 - 0xfebdb4ff
0xfebdb800 - 0xfebdb8ff
0xfebdbc00 - 0xfebdbcff
extent `ioport' (0x0 - 0xffff), flags=3<NOCOALESCE,FIXED>
0x0 - 0xb
0x40 - 0x43
0x60 - 0x60
0x61 - 0x61
0x64 - 0x64
0x80 - 0x8e
0xc0 - 0xd7
0x1f0 - 0x1f7
0x3c0 - 0x3cf
0x3d0 - 0x3df
0x3e8 - 0x3ef
0x3f6 - 0x3f6
0x3f8 - 0x3ff
0xef00 - 0xef0f
ddb> show malloc
Type InUse MemUse HighUse Limit Requests Type Lim Kern Lim
devbuf 581 399K 399K 39321K 920 0 0
pcb 28 5K 5K 39321K 60 0 0
routetbl 71 4K 4K 39321K 131 0 0
ifaddr 40 11K 11K 39321K 41 0 0
sysctl 2 0K 0K 39321K 2 0 0
ioctlops 0 0K 4K 39321K 1449 0 0
mount 9 4K 4K 39321K 9 0 0
vnodes 1448 90K 90K 39321K 1452 0 0
UFS quota 1 16K 16K 39321K 1 0 0
UFS mount 17 33K 33K 39321K 17 0 0
shm 2 0K 0K 39321K 2 0 0
VM map 2 0K 0K 39321K 2 0 0
sem 2 0K 0K 39321K 2 0 0
dirhash 24 4K 4K 39321K 24 0 0
proc 9 4K 4K 39321K 9 0 0
MFS node 1 0K 0K 39321K 1 0 0
NFS srvsock 1 0K 0K 39321K 1 0 0
NFS daemon 1 0K 0K 39321K 1 0 0
in_multi 24 0K 0K 39321K 25 0 0
ether_multi 4 0K 0K 39321K 5 0 0
ISOFS mount 1 16K 16K 39321K 1 0 0
MSDOSFS mount 1 8K 8K 39321K 1 0 0
ttys 420 308K 308K 39321K 420 0 0
exec 0 0K 1K 39321K 166 0 0
pfkey data 1 0K 0K 39321K 2 0 0
pagedep 1 4K 4K 39321K 1 0 0
inodedep 1 16K 16K 39321K 1 0 0
newblk 1 0K 0K 39321K 1 0 0
VM swap 7 22K 22K 39321K 7 0 0
UVM amap 668 71K 71K 39321K 6269 0 0
UVM aobj 2 1K 1K 39321K 2 0 0
USB 61 13K 13K 39321K 61 0 0
USB device 14 0K 0K 39321K 14 0 0
crypto data 1 1K 1K 39321K 1 0 0
packet tags 0 0K 0K 39321K 1 0 0
NDP 6 0K 0K 39321K 7 0 0
temp 42 5K 12K 39321K 1071 0 0
NTFS hash 1 16K 16K 39321K 1 0 0
ddb> show buf
vp 0x4489c0b7 lblkno 0x4c8910fbc1082444 blkno 0x66ffe80b4de80424 dev 0xc7cc24
04
proc 0x53e58955 error -1947185919 flags 1711166203<AGE,NEEDCOMMIT,DELWRI,EINT
R,ERROR,INVAL,NOCACHE,PHYS,WRITEINPROG,XXX,DEFERRED,SCANNED>
bufsize 0xd231f04d bcount 0x89f45d8b resid 0xc70c2454 sync 0x0
data 0xb70fd08d saveaddr 0xd9ac0fc1 dep 0xb70fc800 iodone 0xfc0000f
dirty {off 0x4c70424 end 0x8dc7f624} valid {off 0xb36e8d0 end 0xf66ffe8}
ddb> show proc
PROC (idle0) pid=3 stat=onproc flags=40100200<SYSTEM,NOZOMBIE,CPUPEG>
pri=0, usrpri=86, nice=20
forw=0xffffffff, list=0xd5d3b13c,0xd5d3b3bc
process=0xd5d3a080 user=0xd989b000, vmspace=0xd0a2c8c0
estcpu=36, cpticks=9381, pctcpu=0.36, swtime=141
user=0, sys=0, intr=27
ddb> show uvmexp
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
126390 VM pages: 2248 active, 1016 inactive, 0 wired, 117288 free
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
pages 0 anon, 0 vnode, 0 vtext
freemin=4213, free-target=5617, inactive-target=0, wired-max=42130
faults=23841, traps=25320, intrs=34260, ctxswitch=7918 fpuswitch=37
softint=16982, syscalls=86837, swapins=0, swapouts=0, kmapent=15
fault counts:
noram=0, noanon=0, pgwait=0, pgrele=0
ok relocks(total)=1948(1948), anget(retries)=13583(0), amapcopy=8121
neighbor anon/obj pg=1207/13403, gets(lock/unlock)=6292/1948
cases: anon=11116, anoncow=2467, obj=5792, prcopy=500, przero=3966
daemon and swap counts:
woke=0, revs=0, scans=0, obscans=0, anscans=0
busy=0, freed=0, reactivate=0, deactivate=0
pageouts=0, pending=0, nswget=0
nswapdev=1, nanon=0, nanonneeded=0 nfreeanon=0
swpages=65349, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xd0a0af00
ddb> show all callout
ticks now: 14179
ticks wheel arg func
1 0/100 0 m_cltick
2 0/101 d09e62a4 pffasttimo
4 0/103 d1538000 vte_tick
21 0/120 d09e634c if_slowtimo
21 0/120 d0a23160 pckbc_poll
21 0/120 0 nd6_timer
21 0/120 d09e7db0 rt_timer_timer
21 0/120 d09e5ff0 schedcpu
22 0/121 d09e628c pfslowtimo
29 0/128 d5b53008 endtsleep
30 0/129 d5d319e4 endtsleep
31 0/130 d5d319e4 realitexpire
66 0/165 d5d3b8a4 endtsleep
421 1/313 d5b534f8 endtsleep
752 1/314 d5d313b8 realitexpire
2764 1/322 d5b53770 endtsleep
16604 1/376 d09e7dd8 arptimer
45821 1/490 0 arc4_reinit
172304 2/514 d5b534f8 realitexpire
345821 2/517 0 nd6_slowtimo
713864 2/523 d5b3d4cc tcp_timer_keep
8632426 2/643 d5d31c5c endtsleep
and here is the panic
ddb> boot sync
syncing disks... splassert: assertwaitok: want -1 have 1
splassert: assertwaitok: want -1 have 1
panic: cpu_switch1 0xd5d3b278
Stopped at Debugger+0x4: popl %ebp
RUN AT LEAST 'trace' AND 'ps' AND INCLUDE OUTPUT WHEN REPORTING THIS PANIC!
DO NOT EVEN BOTHER REPORTING THIS WITHOUT INCLUDING THAT INFORMATION!
ddb> trace
Debugger(d08dcd42,d98c8db0,d0200877,d98c8db0,7fffffff) at Debugger+0x4
panic(d0200877,d5d3b278,d5d22000,d5d313b8,7fffffff) at panic+0x5d
switch_error1(c0,d08b9e99,d5c447e8,d98c8e34,d98c8e34) at switch_error1+0xb
sleep_finish(d98c8e34,1,11,d08d20be,50) at sleep_finish+0x99
tsleep(d5c412fc,11,d08d20be,0,d5c42f0c) at tsleep+0x9d
vwaitforio(d5c41290,0,d08d20be,0,d5c41290) at vwaitforio+0x5a
ffs_fsync(d98c8ec8,20042,d5d313b8,0,0) at ffs_fsync+0x17f
VOP_FSYNC(d5c41290,d5d45000,1,d5d313b8,6) at VOP_FSYNC+0x30
sys_fsync(d5d313b8,d98c8f64,d98c8f84,d98c8fa8,d5d313b8) at sys_fsync+0x7a
syscall() at syscall+0x2f0
--- syscall (number 3) ---
0x2:
ddb> ps
PID PPID PGRP UID S FLAGS WAIT COMMAND
28942 12726 28942 0 3 0x6080 ttyout ct
12726 4622 12726 0 3 0x4080 pause ksh
7904 1 7904 0 3 0x4080 ttyin getty
9697 1 9697 0 3 0x4080 ttyin getty
11903 1 11903 0 3 0x4080 ttyin getty
7081 1 7081 0 3 0x4080 ttyin getty
2033 1 2033 0 3 0x4080 ttyin getty
24882 1 24882 0 3 0x4080 ttyin getty
11773 1 11773 0 3 0x80 select cron
4622 2038 4622 0 3 0x4080 select sshd
11364 1 11364 77 3 0x180 poll dhclient
7987 1 7987 0 3 0x40180 select sendmail
21377 1 10736 0 3 0x80 poll dhclient
21377 1 10736 0 3 0x80 poll dhclient
31014 1 10736 76 3 0x4180 bpf tcpdump
18935 1 18935 0 3 0x180 select inetd
2038 1 2038 0 3 0x80 select sshd
2509 12112 12112 74 3 0x180 bpf pflogd
12112 1 12112 0 3 0x80 netio pflogd
*25827 10246 10246 73 3 0x100 ffs_fsync syslogd
10246 1 10246 0 3 0x88 netio syslogd
9966 1 9966 0 3 0x80 mfsidl mount_mfs
14 0 0 0 3 0x100200 aiodoned aiodoned
13 0 0 0 3 0x100200 syncer update
12 0 0 0 3 0x100200 cleaner cleaner
11 0 0 0 3 0x100200 reaper reaper
10 0 0 0 3 0x100200 pgdaemon pagedaemon
9 0 0 0 3 0x100200 bored crypto
8 0 0 0 3 0x100200 pftm pfpurge
7 0 0 0 3 0x100200 usbtsk usbtask
6 0 0 0 3 0x100200 usbatsk usbatsk
5 0 0 0 3 0x100200 apmev apm0
4 0 0 0 3 0x100200 bored syswq
3 0 0 0 2 0x40100200 getblk idle0
2 0 0 0 3 0x100200 kmalloc kmthread
1 0 1 0 3 0x4080 wait init
0 -1 0 0 3 0x80200 scheduler swapper
ddb> show registers
ds 0x10
es 0xd0200010 kernel_text+0x10
fs 0xd98c0058 end+0x8dd41d4
gs 0xd98c0010 end+0x8dd418c
edi 0xd0200877 switch_error1+0xb
esi 0x100
ebp 0xd98c8d64 end+0x8ddcee0
ebx 0xd98c8db0 end+0x8ddcf2c
edx 0x1
ecx 0xd09c0480 kprintf_mutex
eax 0x1
eip 0xd056bf44 Debugger+0x4
cs 0xd98c0008 end+0x8dd4184
eflags 0x212
esp 0xd98c8d64 end+0x8ddcee0
ss 0xd98c0010 end+0x8dd418c
Debugger+0x4: popl %ebp
ddb> show uvmexp
Current UVM status:
pagesize=4096 (0x1000), pagemask=0xfff, pageshift=12
126390 VM pages: 2250 active, 1016 inactive, 0 wired, 117221 free
min 10% (25) anon, 10% (25) vnode, 5% (12) vtext
pages 0 anon, 0 vnode, 0 vtext
freemin=4213, free-target=5617, inactive-target=0, wired-max=42130
faults=23843, traps=25323, intrs=34272, ctxswitch=7920 fpuswitch=38
softint=16987, syscalls=86842, swapins=0, swapouts=0, kmapent=15
fault counts:
noram=0, noanon=0, pgwait=0, pgrele=0
ok relocks(total)=1948(1948), anget(retries)=13583(0), amapcopy=8121
neighbor anon/obj pg=1207/13403, gets(lock/unlock)=6292/1948
cases: anon=11116, anoncow=2467, obj=5792, prcopy=500, przero=3968
daemon and swap counts:
woke=0, revs=0, scans=0, obscans=0, anscans=0
busy=0, freed=0, reactivate=0, deactivate=0
pageouts=0, pending=0, nswget=0
nswapdev=1, nanon=0, nanonneeded=0 nfreeanon=0
swpages=65349, swpginuse=0, swpgonly=0 paging=0
kernel pointers:
objs(kern)=0xd0a0af00
ddb> show all callout
ticks now: 14185
ticks wheel arg func
1 0/106 0 m_cltick
15 0/120 d09e634c if_slowtimo
15 0/120 d0a23160 pckbc_poll
15 0/120 0 nd6_timer
15 0/120 d09e7db0 rt_timer_timer
15 0/120 d09e5ff0 schedcpu
16 0/121 d09e628c pfslowtimo
16 0/121 d09e62a4 pffasttimo
23 0/128 d5b53008 endtsleep
24 0/129 d5d319e4 endtsleep
25 0/130 d5d319e4 realitexpire
60 0/165 d5d3b8a4 endtsleep
98 0/203 d1538000 vte_tick
415 1/313 d5b534f8 endtsleep
746 1/314 d5d313b8 realitexpire
998 1/315 d15420e4 wdctimeout
2758 1/322 d5b53770 endtsleep
16598 1/376 d09e7dd8 arptimer
45815 1/490 0 arc4_reinit
172298 2/514 d5b534f8 realitexpire
345815 2/517 0 nd6_slowtimo
713858 2/523 d5b3d4cc tcp_timer_keep
8632420 2/643 d5d31c5c endtsleep
ddb> show proc
PROC (syslogd) pid=25827 stat=sleep flags=100<SUGID>
pri=17, usrpri=50, nice=20
forw=0x0, list=0xd5d314f4,0xd5d318b0
process=0xd5d3a3c0 user=0xd98c7000, vmspace=0xd5d37168
estcpu=0, cpticks=1, pctcpu=0.0, swtime=127
user=2, sys=1, intr=0
--
antonvm
