On 16.11.2021. 0:08, Hrvoje Popovski wrote:
> On 15.11.2021. 16:44, Hrvoje Popovski wrote:
>> On 15.11.2021. 15:04, Vitaliy Makkoveev wrote:
>>> On Mon, Nov 15, 2021 at 02:51:16PM +0100, Hrvoje Popovski wrote:
>>>
>>> And you don'n see "--------> tdb_free() killing ourself" in dmesg
>>> output?
>>
>>
>> I couldn't find that message anywhere ....
>>
>>
>
> with new panic i see this message ... this time i have mvs@ + "IPsec tdb
> ddb print" diff ...
>
> r620-1# --------> tdb_free() killing ourself
> panic: kernel diagnostic assertion "refcnt != ~0" failed: file
> "/sys/kern/kern_synch.c", line 824
> Stopped at db_enter+0x10: popq %rbp
> TID PID UID PRFLAGS PFLAGS CPU COMMAND
> 142769 73130 68 0x10 0 1 sasyncd
> *407867 7095 0 0x14000 0x40000200 0K softclock
> db_enter() at db_enter+0x10
> panic(ffffffff81e456ab) at panic+0xbf
> __assert(ffffffff81eb4ec9,ffffffff81e1c0b3,338,ffffffff81e4cbf5) at
> __assert+0x25
> refcnt_rele(ffff8000013f3478) at refcnt_rele+0x6f
> tdb_free(ffff8000013f3450) at tdb_free+0x14f
> tdb_timeout(ffff8000013f3450) at tdb_timeout+0x39
> softclock_thread(ffff8000ffffefc0) at softclock_thread+0x16e
> end trace frame: 0x0, count: 8
> https://www.openbsd.org/ddb.html describes the minimum info required in
> bug reports. Insufficient info makes it difficult to find and fix bugs.
> ddb{0}>
>
panic with show tdb feature in ddb and witness
r620-2# panic: kernel diagnostic assertion "refcnt != ~0" failed: file
"/sys/kern/kern_
synch.c", line 824
Stopped at db_enter+0x10: popq %rbp
TID PID UID PRFLAGS PFLAGS CPU COMMAND
219343 43291 68 0x10 0 2 sasyncd
*321579 50760 68 0x10 0 4 isakmpd
187492 98224 0 0x14000 0x200 3 smr
166953 9856 0 0x14000 0x200 1 systq
33216 41335 0 0x14000 0x40000200 0 softclock
db_enter() at db_enter+0x10
panic(ffffffff81e4f74f) at panic+0xbf
__assert(ffffffff81ebf7a0,ffffffff81e233bf,338,ffffffff81e54f8e) at
__assert+0x25
refcnt_rele(ffff8000014829a8) at refcnt_rele+0x6f
tdb_unref(ffff800001482980) at tdb_unref+0x26
pfkeyv2_send(fffffd83b0ddd968,ffff800001439d00,50) at pfkeyv2_send+0x662
pfkeyv2_output(fffffd80a4b0c200,fffffd83b0ddd968,0,0) at pfkeyv2_output+0x8a
pfkeyv2_usrreq(fffffd83b0ddd968,9,fffffd80a4b0c200,0,0,ffff800022cd5510)
at pfkeyv2_usrreq+0x1b0
sosend(fffffd83b0ddd968,0,ffff800022dc9000,0,0,0) at sosend+0x3a9
dofilewritev(ffff800022cd5510,7,ffff800022dc9000,0,ffff800022dc9100) at
dofilew
ritev+0x14d
sys_writev(ffff800022cd5510,ffff800022dc90a0,ffff800022dc9100) at
sys_writev+0xd2
syscall(ffff800022dc9170) at syscall+0x3a9
Xsyscall() at Xsyscall+0x128
end of kernel
end trace frame: 0x7f7ffffe90a0, count: 2
https://www.openbsd.org/ddb.html describes the minimum info required in
bug reports. Insufficient info makes it difficult to find and fix bugs.
ddb{4}>
ddb{4}> show tdb
0xffffffff8188e110: 24030000 (unknown address family)->(unknown address
family)
:128 02c08348
ddb{4}> show all tdb
0xffff800001481880: 38a3d1b0 192.168.42.100->192.168.42.112:50 000d1082
0xffff800001482540: dc955248 192.168.42.113->192.168.42.100:50 00001002
0xffff800001482980: 344ab07c 192.168.42.100->192.168.42.113:50 00091000
0xffff800001483a80: 06e97cf1 192.168.42.112->192.168.42.100:50 00001082
0xffff800001483ec0: 064e7b16 192.168.42.100->192.168.42.113:50 000d1082
0xffff800001484b80: d213635f 192.168.42.113->192.168.42.100:50 00001082
ddb{4}>
ddb{4}> show locks
exclusive rwlock netlock r = 0 (0xffffffff8216c5e0)
#0 witness_lock+0x333
#1 rw_enter+0x27f
#2 pfkeyv2_send+0x659
#3 pfkeyv2_output+0x8a
#4 pfkeyv2_usrreq+0x1b0
#5 sosend+0x3a9
#6 dofilewritev+0x14d
#7 sys_writev+0xd2
#8 syscall+0x3a9
#9 Xsyscall+0x128
ddb{4}>
ddb{4}> show all locks
CPU 3:
exclusive mutex /sys/kern/kern_malloc.c:105 r = 0 (0xffffffff82180d60)
#0 witness_lock+0x333
#1 mtx_enter_try+0x95
#2 mtx_enter+0x48
#3 free+0x74
#4 aesni_free+0x3c
#5 smr_thread+0x21e
#6 proc_trampoline+0x1c
Process 43291 (sasyncd) thread 0xffff800022cd4550 (219343)
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff82255630)
#0 witness_lock+0x333
#1 __mp_acquire_count+0x38
#2 mi_switch+0x299
#3 sleep_finish+0x11c
#4 rw_enter+0x223
#5 solock+0x4b
#6 filt_soreadmodify+0x32
#7 kqueue_register+0x6f1
#8 pselregister+0x1f1
#9 dopselect+0x300
#10 sys_pselect+0xdb
#11 syscall+0x3a9
#12 Xsyscall+0x128
Process 50760 (isakmpd) thread 0xffff800022cd5510 (321579)
exclusive rwlock netlock r = 0 (0xffffffff8216c5e0)
#0 witness_lock+0x333
#1 rw_enter+0x27f
#2 pfkeyv2_send+0x659
#3 pfkeyv2_output+0x8a
#4 pfkeyv2_usrreq+0x1b0
#5 sosend+0x3a9
#6 dofilewritev+0x14d
#7 sys_writev+0xd2
#8 syscall+0x3a9
#9 Xsyscall+0x128
Process 98224 (smr) thread 0xffff800022c91508 (187492)
shared rwlock smr r = 0 (0xffffffff82192348)
#0 witness_lock+0x333
#1 smr_thread+0x1f8
#2 proc_trampoline+0x1c
Process 9856 (systq) thread 0xffff8000ffffed20 (166953)
shared rwlock systq r = 0 (0xffffffff82194200)
#0 witness_lock+0x333
#1 taskq_thread+0x92
#2 proc_trampoline+0x1c
Process 41335 (softclock) thread 0xffff8000fffff260 (33216)
shared rwlock timeout r = 0 (0xffffffff82196238)
#0 witness_lock+0x333
#1 timeout_run+0x88
#2 softclock_thread+0x11d
#3 proc_trampoline+0x1c
ddb{4}>
ddb{4}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
43291 219343 22789 68 7 0x10 sasyncd
22789 24626 1 0 3 0x80 kqread sasyncd
*50760 321579 28327 68 7 0x10 isakmpd
28327 250973 1 0 3 0x80 netio isakmpd
99457 41892 1 0 3 0x100083 ttyin ksh
50944 201916 1 0 3 0x100098 kqread cron
30237 50523 96061 95 3 0x100092 kqread smtpd
54148 391339 96061 103 3 0x100092 kqread smtpd
27005 192457 96061 95 3 0x100092 kqread smtpd
89533 222241 96061 95 3 0x100092 kqread smtpd
62954 127681 96061 95 3 0x100092 kqread smtpd
62192 82201 96061 95 3 0x100092 kqread smtpd
96061 156722 1 0 3 0x100080 kqread smtpd
73222 394828 1 0 3 0x88 kqread sshd
57422 521449 1 0 3 0x100080 kqread ntpd
95525 503268 39813 83 3 0x100092 kqread ntpd
39813 245219 1 83 3 0x100092 kqread ntpd
55743 44427 51174 74 3 0x100092 bpf pflogd
51174 359190 1 0 3 0x80 netio pflogd
41706 115469 78742 73 3 0x100090 kqread syslogd
78742 60752 1 0 3 0x100082 netio syslogd
98224 187492 0 0 7 0x14200 smr
75900 438972 0 0 3 0x14200 pgzero zerothread
31693 342045 0 0 3 0x14200 aiodoned aiodoned
71461 36274 0 0 3 0x14200 syncer update
88518 306760 0 0 3 0x14200 cleaner cleaner
59985 161942 0 0 3 0x14200 reaper reaper
19061 436366 0 0 3 0x14200 pgdaemon pagedaemon
52103 509506 0 0 3 0x14200 usbtsk usbtask
38318 159243 0 0 3 0x14200 usbatsk usbatsk
9043 179173 0 0 3 0x40014200 acpi0 acpi0
55033 387628 0 0 7 0x40014200 idle5
66420 339209 0 0 3 0x40014200 idle4
80545 328914 0 0 3 0x40014200 idle3
86253 444937 0 0 3 0x40014200 idle2
45764 248236 0 0 3 0x40014200 idle1
78670 286927 0 0 3 0x14200 bored sensors
30919 244739 0 0 2 0x14200 softnet
84482 447312 0 0 3 0x14200 bored systqmp
9856 166953 0 0 7 0x14200 systq
41335 33216 0 0 7 0x40014200 softclock
54918 203967 0 0 3 0x40014200 idle0
1 322976 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{4}>
ddb{4}> trace /t 0t321579
ffff800022dc9170(
after this trace command, box locks up ..
