On Fri, May 22, 2020 at 07:57:13AM +1000, David Gwynne wrote:
> On Wed, May 20, 2020 at 05:42:35PM +0300, Vitaliy Makkoveev wrote:
> > I got splassert with pppx(4) and net/ifq.c rev 1.38 raised by
> > NET_ASSERT_LOCKED() in netinet/ip_output.c:113 and underlaying routines.
> >
> > net/ifq.c rev 1.38 is not in snapshot yet so you need to checkout and
> > build kernel to reproduce.
> >
> > ---- dmesg begin ----
> >
> > splassert: ip_output: want 2 have 0
> > Starting stack trace...
> > ip_output(fffffd801f8c8800,0,0,0,0,0) at ip_output+0x8f
> > pipex_l2tp_output(fffffd801f8c8800,ffff80000e787808) at
> > pipex_l2tp_output+0x21d
> > pipex_ppp_output(fffffd801f8c8800,ffff80000e787808,21) at
> > pipex_ppp_output+0xda
> > pppx_if_start(ffff80000e787268) at pppx_if_start+0x83
> > if_qstart_compat(ffff80000e7874e0) at if_qstart_compat+0x2e
> > ifq_serialize(ffff80000e7874e0,ffff80000e7875b0) at ifq_serialize+0x103
> > taskq_thread(ffffffff81f3df30) at taskq_thread+0x4d
> > end trace frame: 0x0, count: 250
> > End of stack trace.
> > splassert: ipsp_spd_lookup: want 2 have 0
> > Starting stack trace...
> > ipsp_spd_lookup(fffffd801f8c8800,2,14,ffff80000e726c9c,2,0) at
> > ipsp_spd_lookup+0x80
> > ip_output_ipsec_lookup(fffffd801f8c8800,14,ffff80000e726c9c,0,1) at
> > ip_output_ipsec_lookup+0x4d
> > ip_output(fffffd801f8c8800,0,0,0,0,0) at ip_output+0x4fa
> > pipex_l2tp_output(fffffd801f8c8800,ffff80000e787808) at
> > pipex_l2tp_output+0x21d
> > pipex_ppp_output(fffffd801f8c8800,ffff80000e787808,21) at
> > pipex_ppp_output+0xda
> > pppx_if_start(ffff80000e787268) at pppx_if_start+0x83
> > if_qstart_compat(ffff80000e7874e0) at if_qstart_compat+0x2e
> > ifq_serialize(ffff80000e7874e0,ffff80000e7875b0) at ifq_serialize+0x103
> > taskq_thread(ffffffff81f3df30) at taskq_thread+0x4d
> > end trace frame: 0x0, count: 248
> > End of stack trace.
> > splassert: spd_table_get: want 2 have 0
> >
> > ---- dmesg end ----
> >
> > 1. `pxi_if' owned by struct pppx_if has IFXF_MPSAFE flag unset
> > 1.1 pppx(4) sets IFQ_SET_MAXLEN(&ifp->if_snd, 1) at net/if_pppx.c:866
> > 2. pppx_if_output() is called under NET_LOCK()
> > 3. pppx_if_output() calls if_enqueue() at net/if_pppx.c:1123
> > 4. pppx(4) doesn't set `ifp->if_enqueue' so if_enqueue() calls
> > if_enqueue_ifq() at net/if.c:709 (which is set in net/if.c:639)
> > 5. if_enqueue_ifq() calls ifq_start() at net/if.c:734
> > 6. ifq_start() we a still under NET_LOCK() here
> >
> > 6.a. in net/ifq.c rev 1.37 ifq_start() checks "ifq_len(ifq) >=
> > min(ifp->if_txmit, ifq->ifq_maxlen)" and this was always true because
> > (1.1) so we always call ifq_run_start() which calls ifq_serialize().
> >
> > ifq_serialize() will call if_qstart_compat() which calls
> > pppx_if_start() which calls pipex_ppp_output() etc while we still
> > holding NET_LOCK() so the assertions I reported above are not raised.
> >
> > 6.b. net/ifq.c rev 1.38 introduce checks of IFXF_MPSAFE flag. so we are
> > always going to net/ifq.c:132 where we adding out task to `systq'
> > referenced by `ifq_softnet' (ifq_softnet set to `systq' at
> > net/ifq.c:199).
> >
> > taskq_thread() doesn't grab NET_LOCK() so after net/ifq.c rev 1.38
> > ifq_serialize() and underlaying pppx_if_start() call without NET_LOCK()
> > and corresponding asserts raised.
> >
> > The problem I pointed is not in net/ifq.c rev 1.38 but in pppx(4).
> > `if_start' routines should grab NET_LOCK() by themself if it is required
> > but pppx_if_start() and pppac_start() did't do that. pppac_start() has
> > no underlaying NET_ASSERT_LOCKED() so the pppx(4) is the only case were
> > the problem is shown.
> >
> > Since NET_LOCK() is required by pipex(4), diff below adds it to
> > pppx_if_start() and pppac_start().
> >
> > After net/ifq.c rev 1.38 pppx_if_start() will newer be called from
> > pppx_if_output() but from `systq' only so I don't add lock/unlock
> > dances around if_enqueue() at net/if_pppx.c:1123.
> >
> > Diff tested for both pppx(4) and pppac(4) cases.
>
> thanks for the detailed analysis. i wondered how the ifq change
> triggered this exactly, and your mail makes it clear.
>
> however, pppx/pppac/pipex are not the first or only drivers in the tree
> that encapsulate a packet in IP from their if_start routine and send it
> out with the network stack. the way this has been solved in every other
> driver has been to call ip{,6}_send to transmit the packet instead
> of ip{,6}_output.
>
> can you try the following diff?
>
I tested this diff and it works for me. But the problem I pointed is
about pipex(4) locking.
pipex(4) requires NET_LOCK() be grabbed not only for underlaying
ip{,6}_output() but for itself too. But since pppac_start() has
unpredictable behavior I suggested to make it predictable [1].
With net/ifq.c rev 1.37 and rev 1.39 pppx_if_start() routine will be
allways called under NET_LOCK(), but pppac_start() will not. It depends
on packet count stored in `if_snd' (look at net/ifq.c:125).
With net/ifq.c rev 1.38 pppx_if_start() and pppac_start() have fully
identical behavior and we can simply add NET_LOCK() [2] required by
pipex(4).
Also I can write my own handler for `ifp->if_enqueue' to be sure about
`ifp->if_start' locking state, but I still have misunderstanding why
pppx(4) does "IFQ_SET_MAXLEN(&ifp->if_snd, 1)". Just to make locking
state of pppx_if_start() predictable or for avoid hidden bug triggering?
Also this time I'am not shure about KERNEL_LOCK() locking while pipex(4)
is accessed from the stack so I can't say is NET_LOCK() really required
for the whole pipex(4).
1. https://marc.info/?l=openbsd-tech&m=159006455720473&w=2
2. https://marc.info/?l=openbsd-tech&m=158998597126002&w=2
