Lock Order Reversal on 7.0-STABLE with pf and ipfw / dummynet (traces)

[Max Laier]

Hi Alex,

so it's basically back to square one.  We only have LORs between the pfil 
R/W lock (read instance) and mutexes that don't have any lock order with 
the pfil R/W lock (write instance) at all.  This means the deadlock can't 
be explained by the LORs that are reported (unless there is something I'm 
missing).  Unless somebody who is seeing these kind of deadlocks can 
actually break into a debugger to identify the locks at play, everything 
else is just speculation.

I will fix the fastroute LOR with the patch you have been testing, 
eventhough it didn't fix your problem.  For the remaining issue, we need 
more IPFW or lock primitives knowledge (extending CC-list).

Note that the first LOR features a recursive pickup of the pfil R/W lock.  
I remember that Attilio committed a patch to forbid this for CURRENT.  
Could this be the cause of a deadlock?  Would it make sense to MFC 
rm_locks and try if they hold up under this scenario?

On Tuesday 25 March 2008 20:21:15 Alex Popa wrote:
[...]
> Hello.
>
> I have tested the patch, booted with a WITNESS kernel including that
> patch, and it has locked up (solid again, no numlock or console
> changing, no control-alt-esc to debugger) after about 41 minutes
> (timestamps in /var/log/all.log go from 19:12:57 to 19:53:40).
>
> I did get two LOR reports in dmesg, they are attached.

> lock order reversal:
> 1st 0xffffffff8096ebc8 PFil hook read/write mutex (PFil hook read/write
> mutex) @ /usr/src/sys/net/pfil.c:73 
> 2nd 0xffffffff8096f8e8 udp (udp) @ /usr/src/sys/netinet/udp_usrreq.c:385 

This one could be avoided if dummynet_send where to use a queue instead of 
direct dispatch - with all associated problems.

> KDB: stack backtrace: 
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> witness_checkorder() at witness_checkorder+0x539
> _mtx_lock_flags() at _mtx_lock_flags+0x1f
> udp_input() at udp_input+0x1f7
> ip_input() at ip_input+0xa7

>>> QUEUE here <<<

> dummynet_send() at dummynet_send+0xde
> dummynet_io() at dummynet_io+0x587
> ipfw_check_in() at ipfw_check_in+0x241
> pfil_run_hooks() at pfil_run_hooks+0xac
> ip_input() at ip_input+0x292
> ether_demux() at ether_demux+0x1ac
> ether_input() at ether_input+0x1bf
> em_handle_rxtx() at em_handle_rxtx+0x1d2
> taskqueue_run() at taskqueue_run+0x95
> taskqueue_thread_loop() at taskqueue_thread_loop+0x53
> fork_exit() at fork_exit+0x112
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffffffa057ad30, rbp = 0 ---
>
> lock order reversal:
> 1st 0xffffff00018ff690 inp (rawinp) @ /usr/src/sys/netinet/raw_ip.c:281 
> 2nd 0xffffffff8096ebc8 PFil hook read/write mutex (PFil hook read/write 
> mutex) @ /usr/src/sys/net/pfil.c:73

I'm still a bit suspicious of this one due to the interaction of exclusive 
IPFW locks with raw sockets, but I still can't find the code path for the 
original order, which makes it a bit hard to follow.

Alex, can you get a "show witness" after this LOR has been displayed?

> KDB: stack backtrace: 
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> witness_checkorder() at witness_checkorder+0x539
> _rw_rlock() at _rw_rlock+0x25
> pfil_run_hooks() at pfil_run_hooks+0x44
> ip_output() at ip_output+0x35a
> rip_output() at rip_output+0x1eb
> sosend_generic() at sosend_generic+0x289
> kern_sendit() at kern_sendit+0x122
> sendit() at sendit+0xc6
> sendto() at sendto+0x4d
> syscall() at syscall+0x1b5
> Xfast_syscall() at Xfast_syscall+0xab
> --- syscall (133, FreeBSD ELF64, sendto), rip = 0x80091132c, rsp =
> 0x7ffffffee6e8, rbp = 0x40 ---

Any input greatly appreciated!

-- 
/"\  Best regards,                      | mlaier at freebsd.org
\ /  Max Laier                          | ICQ #67774661
 X   http://pf4freebsd.love2party.net/  | mlaier at EFnet
/ \  ASCII Ribbon Campaign              | Against HTML Mail and News