Re: Report in unix_stream_read_generic()

Matthew Wilcox
2022-02-16T04:34:08Z

On Wed, Feb 16, 2022 at 01:17:03PM +0900, Byungchul Park wrote:
> [ 7.013330] ===================================================
> [ 7.013331] DEPT: Circular dependency has been detected.
> [ 7.013332] 5.17.0-rc1-00014-gcf3441bb2012 #2 Tainted: G W
> [ 7.013333] ---------------------------------------------------
> [ 7.013334] summary
> [ 7.013334] ---------------------------------------------------
> [ 7.013335] *** DEADLOCK ***
> [ 7.013335]
> [ 7.013335] context A
> [ 7.013336] [S] (unknown)(&(&ei->socket.wq.wait)->dmap:0)
> [ 7.013337] [W] __mutex_lock_common(&u->iolock:0)
> [ 7.013338] [E] event(&(&ei->socket.wq.wait)->dmap:0)
> [ 7.013340]
> [ 7.013340] context B
> [ 7.013341] [S] __raw_spin_lock(&u->lock:0)
> [ 7.013342] [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> [ 7.013343] [E] spin_unlock(&u->lock:0)

This seems unlikely to be real. We're surely not actually waiting
while holding a spinlock; existing debug checks would catch it.

> [ 7.013407] ---------------------------------------------------
> [ 7.013407] context B's detail
> [ 7.013408] ---------------------------------------------------
> [ 7.013408] context B
> [ 7.013409] [S] __raw_spin_lock(&u->lock:0)
> [ 7.013410] [W] wait(&(&ei->socket.wq.wait)->dmap:0)
> [ 7.013411] [E] spin_unlock(&u->lock:0)
> [ 7.013412]
> [ 7.013412] [S] __raw_spin_lock(&u->lock:0):
> [ 7.013413] [<ffffffff81aa451f>] unix_stream_read_generic+0x6bf/0xb60
> [ 7.013416] stacktrace:
> [ 7.013416] _raw_spin_lock+0x6e/0x90
> [ 7.013418] unix_stream_read_generic+0x6bf/0xb60

It would be helpful if you'd run this through scripts/decode_stacktrace.sh
so we could see line numbers instead of hex offsets (which arene't much
use without the binary kernel).

> [ 7.013420] unix_stream_recvmsg+0x40/0x50
> [ 7.013422] sock_read_iter+0x85/0xd0
> [ 7.013424] new_sync_read+0x162/0x180
> [ 7.013426] vfs_read+0xf3/0x190
> [ 7.013428] ksys_read+0xa6/0xc0
> [ 7.013429] do_syscall_64+0x3a/0x90
> [ 7.013431] entry_SYSCALL_64_after_hwframe+0x44/0xae
> [ 7.013433]
> [ 7.013434] [W] wait(&(&ei->socket.wq.wait)->dmap:0):
> [ 7.013434] [<ffffffff810bb017>] prepare_to_wait+0x47/0xd0

... this may be the source of confusion. Just because we prepare to
wait doesn't mean we end up actually waiting. For example, look at
unix_wait_for_peer():

prepare_to_wait_exclusive(&u->peer_wait, &wait, TASK_INTERRUPTIBLE);

sched = !sock_flag(other, SOCK_DEAD) &&
!(other->sk_shutdown & RCV_SHUTDOWN) &&
unix_recvq_full(other);

unix_state_unlock(other);

if (sched)
timeo = schedule_timeout(timeo);

finish_wait(&u->peer_wait, &wait);

We *prepare* to wait, *then* drop the lock, then actually schedule.