Re: [PATCH net-next] net/iucv: serialize HiperSockets receive with the socket lock

[Hidayath Khan]

On 14/10/26 4:42 am, Hidayath Khan wrote:
> Hi Bryam,
>
> Below are the test results for this stage 1 patch on z/VM.
>
> Setup: one z/VM guest, two HiperSockets hsuids, two CPUs, af_iucv as a
> module, and an AF_IUCV socket-locking reproducer. Both kernels have 
> the same
> config - CONFIG_KASAN=y, CONFIG_PROVE_LOCKING=y and
> CONFIG_DEBUG_ATOMIC_SLEEP=y - so the only variable is the patch.
>
>   scenario     net-next,               patch
>   sk_shutdown  fail, 271-299 misses    pass, 0 in 9058 cycles
>   shut_rd      fail, fail, pass        pass, 0 in 29 cycles
>   recvrecv     fail, 3658-4139 back.   pass, 0 out-of-order in 4194304 
> words
>   backlog      pass                    pass
>   rxclose      fail, 16-17 of 35-38    fail, 14 of 57
>   spin         fail, 2020-2190 ms CPU  fail, 2070 ms CPU
>
> No KASAN, lockdep or DEBUG_ATOMIC_SLEEP report on either kernel, in 
> dmesg or
> the journal - so nothing reports here either way, and the patch 
> introduces
> nothing. Since this patch adds local_bh_disable() around the backlog 
> replay,
> moves __iucv_sock_close() into recvmsg() under lock_sock() and holds 
> the socket
> lock across copy_to_user(), that was the result I was most interested in.
>
> backlog passed on both - it is a guard rather than a reproducer, and 0
> frames lost over roughly 1.1 million ownership windows on net-next 
> confirms
> it has no discriminating power here, so it says nothing either way.
>
> shut_rd is too flaky to lean on: on net-next it failed with 2 misses 
> in 43
> cycles and 3 in 35, then passed with 0 in 45. So its single pass with the
> patch is not evidence. Its window is now narrow enough that 30 s under 
> KASAN
> is not enough cycles; I will re-run it much longer.
>
> sk_shutdown and recvrecv are the solid ones. recvrecv is what I would 
> point
> at: two readers interleaving inside an unlocked iucv_sock_recvmsg() went
> backwards 3658, 3896 and 4139 times across the three net-next runs and 
> not
> once with your patch.
>
> rxclose fails on both, on the -ENOTCONN that Sashiko flags as Low: 17 
> of 37,
> 17 of 38 and 16 of 35 on net-next against 14 of 57 with your patch. Lower
> with the patch, but that is one patched run against three, so I would not
> read much into the difference. 0 lost tails in every run - though the
> lost-tail check only runs on cycles that reached EOF, so the failing 
> cycles
> are not data-checked. The test counts any errno other than EINTR and 
> EAGAIN
> as a wrong termination, which is why -ENOTCONN shows as a failure.
>
> The asymmetry is that recvmsg()'s shortcut gives EOF on IUCV_DISCONN with
> the queues empty, while iucv_sock_recv_skb() gives -ENOTCONN on
> sk_state != IUCV_CONNECTED. Either the loop returns EOF for IUCV_DISCONN
> with nothing queued, or afiucv_hs_callback_fin() sets RCV_SHUTDOWN as 
> well -
> that one is a single line but also changes what callback_rx() drops 
> and what
> iucv_sock_poll() reports. I have tried neither. Which behaviour do you 
> want?
>
> spin fails on both, and by the same margin: 2020, 2150 and 2190 ms of CPU
> while blocked about 3000 ms on net-next, 2070 ms with your patch.
> __iucv_sock_wait() still calls prepare_to_wait() once, outside its 
> loop, so
> after the first schedule_timeout() the task is TASK_RUNNING. Outside your
> diff, and a different bug from the missed wakeup you fix at the same call
> site. One-liner; I will send it separately.
>
> On KASAN specifically, so an empty result is not read as a gap: there 
> will
> be no KASAN report from these scenarios even on a KASAN kernel. The
> reproducer does scan /dev/kmsg for KASAN and KCSAN reports and fails a
> scenario on any hit, but stage 1's defects are missing locks - they 
> surface
> as lost data, a lost sk_shutdown bit, a wrong errno or a leaked 
> socket, none
> of which touch freed or out-of-bounds memory. KASAN is a clean-run 
> control
> here. KCSAN is what can witness the accesses still left unlocked; note 
> that
> it generally does not flag volatile accesses, so it may not show sk_state
> races either. A KCSAN run is next.
>
> Sashiko's three budget findings look to me like instances of one 
> thing, and
> it says so itself on the SO_MSGLIMIT case: stream data is "lost 
> without any
> error". A frame that does not fit is dropped with nothing but
> sk_drops_inc() and kfree_skb_reason(). Resizing a budget per instance 
> leaves
> the next one open.
>
> Sashiko's three budget findings look like one thing: a frame that does 
> not fit
> is dropped with only sk_drops_inc() and kfree_skb_reason(), so resizing a
> budget per instance leaves the next one open. Would you take a patch 
> on top
> that makes the loss visible instead - the softirq sets a bit in 
> iucv_sock, and
> iucv_sock_release_cb() turns it into sk_err = ECONNRESET plus 
> IUCV_DISCONN once
> the owner lets go? Separately: would it be simpler not to defer
> a pure WIN at all? afiucv_hs_callback_win() is only an atomic_sub() and
> iucv_sock_wake_msglim().
>
> Thanks,
> Hidayath

Hi Bryam,

Follow-up to the earlier KASAN + PROVE_LOCKING + DEBUG_ATOMIC_SLEEP results.

I ran the same reproducer on the same z/VM guest with a KCSAN build of your
patch, interrupt watcher on. KCSAN found two af_iucv data races. Both
appeared during the sk_shutdown scenario. The second also appeared once in
rxclose scenario. I have the full KCSAN reports from /dev/kmsg now, so
the fields below are from them rather than from reading the code.

1) sk->sk_shutdown, 1 byte, same address on both sides.

A marked read in afiucv_hs_callback_rx(), inlined into afiucv_hs_dispatch():

    if (READ_ONCE(sk->sk_shutdown) & RCV_SHUTDOWN)

by interrupt on one CPU, against the plain read-modify-write in
iucv_sock_shutdown():

    sk->sk_shutdown |= how;

by task on the other CPU. The report gives the contexts as interrupt and 
task;
that the writer holds lock_sock() is from the source - iucv_sock_shutdown()
takes it on entry and that line is on every path to it.

The receive side must have come through the !afiucv_hs_defer() bypass rather
than the !sock_owned_by_user() arm. The writer holds lock_sock(), so
sk_lock.owned is set and slock is free; the reader runs inside 
bh_lock_sock(),
which is slock. For the two to overlap, the task must have finished
lock_sock() before the softirq took slock - so sock_owned_by_user() was 
true
when the softirq checked it. On the other arm the softirq holds slock while
nobody owns the socket, and a task entering lock_sock() blocks on slock 
until
the callback returns, so it cannot reach the write.

That is the window I asked you about in the previous comment, where a frame
can also be queued after shutdown(SHUT_RD)'s skb_queue_purge(), and which I
could not get to fire functionally. It has a KCSAN report behind it now.

Making the write a WRITE_ONCE() would silence KCSAN and fix nothing. The
frame-after-purge behaviour looks like an ordering problem.

2) iucv->hs_dev, 8 bytes, same address on both sides.

A plain read in afiucv_hs_rcv()'s socket-lookup loop:

    if (iucv_sk(sk)->hs_dev != dev)

by interrupt, with only read_lock(&iucv_sk_list.lock) held, against the 
plain
write in __iucv_sock_close():

    iucv->hs_dev = NULL;

by task, from an ordinary close() - the stack is iucv_sock_release ->
sock_close -> __fput -> sys_close, so the socket lock is held there.

The read is the ingress check added by Alexandra's 80230a18c164 and the
write was already there, so neither line is from your patches.
I do not think it needs locking: the lookup is inherently racy with close,
since the socket can be closed between the match and the dispatch however
well hs_dev is synchronised. I think both outcomes are harmless - observing
NULL early drops a frame that was about to be dropped anyway, and 
observing a
stale pointer gets the frame as far as the callbacks, which drop it on
sk_state. So I think the right treatment is READ_ONCE()/WRITE_ONCE() on the
two accesses with a comment saying the lookup read is deliberately
unsynchronised, rather than anything structural. Tell me if you see it
differently.

One more thing in the same function. __iucv_sock_close() does

    dev_put(iucv->hs_dev);
    iucv->hs_dev = NULL;

so between those two statements hs_dev names a device this socket no longer
holds a reference to, and the lookup loop can match on it. Clearing before
the put removes that window - via a local, since swapping the lines as they
stand would dev_put(NULL) and leak the reference:

    struct net_device *dev = iucv->hs_dev;

    if (dev) {
        iucv->hs_dev = NULL;
        sk->sk_bound_dev_if = 0;
        dev_put(dev);
    }

The test run also has 500+ KCSAN reports with skb_copy_bits / 
__might_fault.
All of them have
afiucv_hs_rcv() -> pskb_may_pull() -> __pskb_pull_tail() in the stack.
The conflict is on current->pagefault_disabled not skb data, so I don't 
think
either of your patches is involved.

Functionally the KCSAN kernel showed nothing new - the same rxclose and spin
failures as previous comment, everything else is clean.

Thanks,
Hidayath