On Mon, 2025-03-24 at 22:49 +0000, Trond Myklebust wrote: > On Mon, 2025-03-24 at 17:52 -0400, Jeff Layton wrote: > > Hi Trond, > > > > We hit a new failure mode with the containerized NFS client teardown > > patches. > > > > The symptoms are that we see the state recovery thread stuck, and > > then > > we see a flusher thread stuck like this: > > > > #0 context_switch (kernel/sched/core.c:5434:2) > > #1 __schedule (kernel/sched/core.c:6799:8) > > #2 __schedule_loop (kernel/sched/core.c:6874:3) > > #3 schedule (kernel/sched/core.c:6889:2) > > #4 nfs_wait_bit_killable (fs/nfs/inode.c:77:2) > > #5 __wait_on_bit (kernel/sched/wait_bit.c:49:10) > > #6 out_of_line_wait_on_bit (kernel/sched/wait_bit.c:64:9) > > #7 wait_on_bit_action (./include/linux/wait_bit.h:156:9) > > #8 nfs4_wait_clnt_recover (fs/nfs/nfs4state.c:1329:8) > > #9 nfs4_client_recover_expired_lease (fs/nfs/nfs4state.c:1347:9) > > #10 pnfs_update_layout (fs/nfs/pnfs.c:2133:17) > > #11 ff_layout_pg_get_mirror_count_write > > (fs/nfs/flexfilelayout/flexfilelayout.c:949:4) > > #12 nfs_pageio_setup_mirroring (fs/nfs/pagelist.c:1114:18) > > #13 nfs_pageio_add_request (fs/nfs/pagelist.c:1406:2) > > #14 nfs_page_async_flush (fs/nfs/write.c:631:7) > > #15 nfs_do_writepage (fs/nfs/write.c:657:9) > > #16 nfs_writepages_callback (fs/nfs/write.c:684:8) > > #17 write_cache_pages (mm/page-writeback.c:2569:11) > > #18 nfs_writepages (fs/nfs/write.c:723:9) > > #19 do_writepages (mm/page-writeback.c:2612:10) > > #20 __writeback_single_inode (fs/fs-writeback.c:1650:8) > > #21 writeback_sb_inodes (fs/fs-writeback.c:1942:3) > > #22 __writeback_inodes_wb (fs/fs-writeback.c:2013:12) > > #23 wb_writeback (fs/fs-writeback.c:2120:15) > > #24 wb_check_old_data_flush (fs/fs-writeback.c:2224:10) > > #25 wb_do_writeback (fs/fs-writeback.c:2277:11) > > #26 wb_workfn (fs/fs-writeback.c:2305:20) > > #27 process_one_work (kernel/workqueue.c:3267:2) > > #28 process_scheduled_works (kernel/workqueue.c:3348:3) > > #29 worker_thread (kernel/workqueue.c:3429:4) > > #30 kthread (kernel/kthread.c:388:9) > > #31 ret_from_fork (arch/x86/kernel/process.c:147:3) > > #32 ret_from_fork_asm+0x11/0x16 (arch/x86/entry/entry_64.S:244) > > > > Turning up some tracepoints, I see this: > > > > kworker/u1028:1-997456 [159] ..... 9027.330396: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE status=0 action=call_reserve [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330397: xprt_reserve: > > task:0000174b@00000000 xid=0x6bfc099c > > kworker/u1028:1-997456 [159] ..... 9027.330397: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEO > > UT|NORTO runstate=RUNNING|ACTIVE status=0 action=call_reserveresult > > [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330397: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEO > > UT|NORTO runstate=RUNNING|ACTIVE status=0 action=call_refresh > > [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330399: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEO > > UT|NORTO runstate=RUNNING|ACTIVE status=0 action=call_refreshresult > > [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330399: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEO > > UT|NORTO runstate=RUNNING|ACTIVE status=0 action=call_allocate > > [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330400: rpc_buf_alloc: > > task:0000174b@00000000 callsize=368 recvsize=80 status=0 > > kworker/u1028:1-997456 [159] ..... 9027.330400: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE status=0 action=call_encode [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330402: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=0 > > action=call_connect [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330403: xprt_reserve_xprt: > > task:0000174b@00000000 snd_task:0000174b > > kworker/u1028:1-997456 [159] ..... 9027.330404: xprt_connect: > > peer=[2a03:83e4:4002:0:12a::2a]:20492 state=LOCKED|BOUND > > kworker/u1028:1-997456 [159] ..... 9027.330405: rpc_task_sleep: > > task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=0 timeout=0 > > queue=xprt_pending > > kworker/u1028:1-997456 [159] ..... 9027.330442: > > rpc_socket_connect: error=-22 socket:[15084763] srcaddr=[::]:993 > > dstaddr=[2a03:83e4:4002:0:12a::2a]:0 state=1 (UNCONNECTED) sk_state=7 > > (CLOSE) > > kworker/u1028:1-997456 [159] ..... 9027.330443: rpc_task_wakeup: > > task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=QUEUED|ACTIVE|NEED_XMIT|NEED_RECV status=-22 timeout=60000 > > queue=xprt_pending > > kworker/u1028:1-997456 [159] ..... 9027.330444: > > xprt_disconnect_force: peer=[2a03:83e4:4002:0:12a::2a]:20492 > > state=LOCKED|CONNECTING|BOUND|SND_IS_COOKIE > > kworker/u1028:1-997456 [159] ..... 9027.330444: xprt_release_xprt: > > task:ffffffff@ffffffff snd_task:ffffffff > > kworker/u1028:1-997456 [159] ..... 9027.330445: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=-22 > > action=call_connect_status [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330446: > > rpc_connect_status: task:0000174b@00000000 status=-22 > > kworker/u1028:1-997456 [159] ..... 9027.330446: rpc_call_rpcerror: > > task:0000174b@00000000 tk_status=-22 rpc_status=-22 > > kworker/u1028:1-997456 [159] ..... 9027.330446: > > rpc_task_run_action: task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEO > > UT|NORTO runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=-22 > > action=rpc_exit_task [sunrpc] > > kworker/u1028:1-997456 [159] ..... 9027.330447: rpc_task_end: > > task:0000174b@00000000 > > flags=ASYNC|MOVEABLE|NETUNREACH_FATAL|DYNAMIC|SOFT|TIMEOUT|NORTO > > runstate=RUNNING|ACTIVE|NEED_XMIT|NEED_RECV status=-22 > > action=rpc_exit_task [sunrpc] > > > > There is no traffic on the wire. So, the problem seems to be in this > > situation that we're calling call_connect, and getting back -EINVAL > > from the network layer, which doesn't trigger the -ENETUNREACH > > handling. > > > > Is this a bug from the network layer, or do we also need to handle - > > EINVAL in call_connect_status? > > > > ...or do we need a different fix? > > > > Thoughts? > > We need a way to pass down to the client calling > nfs4_client_recover_expired_lease() that the client is terminally gone > away, and that it should stop looping. > I'm thinking that we probably need to mark the client as errored out by > using a call to nfs_mark_client_ready() to set clp->cl_cons_state in > error. > > However I do find it odd that we're seeing an EINVAL error instead of > ENETUNREACH. > Same. > It looks from your traces above as if that is coming from > the call to xs_tcp_finish_connecting(), which almost has to mean that > it is being returned by kernel_connect(). > Hmm. Maybe it is this: "dstaddr=[2a03:83e4:4002:0:12a::2a]:0"? A zero > port value might explain it... That sounds entirely plausible. Here is the whole trace buffer. It sort of looks like the port isn't 0, in xprt_disconnect_auto/_force(), but in rpc_socket_connect() it definitely is. I see no calls to call_bind() in here too, which is also odd if the port is really 0. -- Jeff Layton <jlayton@xxxxxxxxxx>
Attachment:
nfs-port0.txt.gz
Description: application/gzip
