debug process hanging when stat a disconnected nfs server

這篇記錄的預期會有點像流水帳，希望能完整重現我的 debug 過程和遇到的困難

根據我同事的 debug 的結果是當對著 disconnected 的 nfs mount server 下指令 stat 會直接卡住，而 enine 的實作剛好是會用 stat 去訪問該路徑，所以卡住也是合情合理，但我的困惑點是我從手冊上看不出 stat 會是 block function ，手冊中提到 block 字眼都是在描述資料大小的 block 而不是卡住的 block ，所以對這個結果產生疑惑，所以想一探究竟

debug 完後再搜尋其實有發現不少人問過對著一個 disconnected 的 nfs mount point 下指令會卡住的問題，例如：An NFS client hangs on various operations, including "df". Hard vs Soft NFS mounts.

因為 stat 基本上就是用 syscall 去拿該 directory 的資訊，所以進行 kernel debug 是必須的，我的預想是開兩台機器，一台是 nfs-server 另一台當 client ，當兩邊建立好連線資料夾都 mount 上去後關掉 server ，然後對著 mounted directory 下指令 stat ，觀察其流程

或許其他 tool 說不定也可以，但不太熟 XD

環境架設

我原定計畫是用一台 vm a 裡面開 qemu 的 vm aa 當作 client ，另一台跟 vm a 一樣開在 vmware 的 vm b ，但是技術太差兩邊連不到，我也懶得想於是放棄

從現況來看我應該要有兩台 vm ，要嘛都是在 vmware 上，要嘛都是在同一台 vm 但是分別用兩個 qemu 去執行，都在 vmware 上的話我必須要在 windows 上跑 gdb 去 debug kernel ，這我沒試過(理論上應該可行 ?)，所以用一台 vm 起兩個 qemu vm 去 debug

原本想說兩個只要拿來跑 nfs client, server 的話我應該不需要太多功能，所以弄個類似打 ctf 的簡易環境應該就可以，但後來發現架設 nfs 的教學文章都是基於各個發行版，如果我要拿到一台幾乎全空的機器安裝教學提到的軟體我必須對每個會用到的 binary 進行重編譯然後塞進去，想一想好像超級麻煩，我還不如直接裝兩台 ubuntu vm ，這樣就有現成的 apt 可以下載我要的軟體，缺點是 vm 會比較肥，不過容量問題我覺得比較好解決

qemu + ubuntu 然後 kernel debug 的操作我之前有實驗過，除了安裝過程步驟較繁瑣和需要比較多空間之外，其實沒啥難度，唯一的問題是我要額外把 qemu vm 設定網路，讓他們用 virtual bridge 去連接，這部分之前沒研究過，所幸找到一篇簡單的教學文讓我可以快速上手，細節就先略過，之後再補

網路問題弄好，兩個 vm 都裝好，剩下來就是設定 nfs 的問題，這個也好辦，現成的工具基本上都幫你弄好好的，我按照這篇沒問到什麼問題，也順利的弄好 nfs 連接

debug

為了知道 stat 一個資料夾後會呼叫哪個 syscall ，我先用 strace 去監控 stat 的行為，發現他最後會呼叫 lstat 這個 syscall

接著從 elixir 這個 linux kernel source code 網站去找 lstat 具體的 symbol name 是啥：

/* ... */
SYSCALL_DEFINE2(lstat, const char __user *, filename,
		struct __old_kernel_stat __user *, statbuf)
{
	struct kstat stat;
	int error;

	error = vfs_lstat(filename, &stat);
	if (error)
		return error;

	return cp_old_stat(&stat, statbuf);
}
/* ... */
SYSCALL_DEFINE2(newlstat, const char __user *, filename,
		struct stat __user *, statbuf)
{
	struct kstat stat;
	int error;

	error = vfs_lstat(filename, &stat);
	if (error)
		return error;

	return cp_new_stat(&stat, statbuf);
}
/* ... */
SYSCALL_DEFINE2(lstat64, const char __user *, filename,
		struct stat64 __user *, statbuf)
{
	struct kstat stat;
	int error = vfs_lstat(filename, &stat);

	if (!error)
		error = cp_new_stat64(&stat, statbuf);

	return error;
}

/* ... */
COMPAT_SYSCALL_DEFINE2(newlstat, const char __user *, filename,
		       struct compat_stat __user *, statbuf)
{
	struct kstat stat;
	int error;

	error = vfs_lstat(filename, &stat);
	if (error)
		return error;
	return cp_compat_stat(&stat, statbuf);
}

發現有一堆 lstat 相關的 syscall ，但我發現他們都會呼叫 vfs_lstat ，所以乾脆直接下斷點在 vfs_lstat

最後從 backtrace 去看，應該是呼叫 newlstat

停住後一路追下去發現到 vfs_getattr_nosec 裡面的:

int vfs_getattr_nosec(const struct path *path, struct kstat *stat,
		      u32 request_mask, unsigned int query_flags) {
    /* ... */
    if (inode->i_op->getattr)
	    return inode->i_op->getattr(mnt_userns, path, stat,
					    request_mask, query_flags);
}

i_op->getattr 之後的 code 沒有 symbol ，這邊卡滿久的，我一直以為這邊的 code 就是沒 symbol ，所以想慢慢看 asm ，不過沒有 symbol 輔助根本看不懂 XD

後來翻了下 inode 的 i_op 到底是啥鬼後發現：

struct inode {
	/* ... */

	const struct inode_operations	*i_op;
    /* ... */
};

知道 i_op 的 type 後再去看該 type 在 nfs 相關的哪個檔案有用到，找到 fs/nfs/proc.c 裡面有對 inode_operations 的 table assign:

static const struct inode_operations nfs_dir_inode_operations = {
	.create		= nfs_create,
	.lookup		= nfs_lookup,
	.link		= nfs_link,
	.unlink		= nfs_unlink,
	.symlink	= nfs_symlink,
	.mkdir		= nfs_mkdir,
	.rmdir		= nfs_rmdir,
	.mknod		= nfs_mknod,
	.rename		= nfs_rename,
	.permission	= nfs_permission,
	.getattr	= nfs_getattr,
	.setattr	= nfs_setattr,
};

發現他其實是呼叫 nfs_getattr

那為什麼 gdb 裡面沒有 symbol 呢？後來我在一次手誤後輸入 /proc/mounts ，突然想到會不會其實 nfs 相關 symbol 根本不在 vmlinux 裡面而是作為 symbol 存放在 module 內，結果真的找到兩個 nfs 相關的 symbol: nfs.ko 和 nfsv4.ko

要注意兩個 kernel module 的 symbol 都要載入，因為 nfsv4 的 symbol 會去 link 到 nfs 的 symbol ，所以如果要有完整的 symbol 兩者都必須載入，載入 symbol 的方式在之前的 note 有提到，我就不多提

一路追下去會發現最後卡在 net/sunrpc/sched.c 裡面的 __rpc_execute:

static void __rpc_execute(struct rpc_task *task)
{
	struct rpc_wait_queue *queue;
	int task_is_async = RPC_IS_ASYNC(task);
	int status = 0;

	WARN_ON_ONCE(RPC_IS_QUEUED(task));
	if (RPC_IS_QUEUED(task))
		return;

	for (;;) {
		void (*do_action)(struct rpc_task *);

		/*
		 * Perform the next FSM step or a pending callback.
		 *
		 * tk_action may be NULL if the task has been killed.
		 * In particular, note that rpc_killall_tasks may
		 * do this at any time, so beware when dereferencing.
		 */
		do_action = task->tk_action;
		if (task->tk_callback) {
			do_action = task->tk_callback;
			task->tk_callback = NULL;
		}
		if (!do_action)
			break;
		trace_rpc_task_run_action(task, do_action);
		do_action(task);

		/*
		 * Lockless check for whether task is sleeping or not.
		 */
		if (!RPC_IS_QUEUED(task))
			continue;

		/*
		 * Signalled tasks should exit rather than sleep.
		 */
		if (RPC_SIGNALLED(task)) {
			task->tk_rpc_status = -ERESTARTSYS;
			rpc_exit(task, -ERESTARTSYS);
		}

		/*
		 * The queue->lock protects against races with
		 * rpc_make_runnable().
		 *
		 * Note that once we clear RPC_TASK_RUNNING on an asynchronous
		 * rpc_task, rpc_make_runnable() can assign it to a
		 * different workqueue. We therefore cannot assume that the
		 * rpc_task pointer may still be dereferenced.
		 */
		queue = task->tk_waitqueue;
		spin_lock(&queue->lock);
		if (!RPC_IS_QUEUED(task)) {
			spin_unlock(&queue->lock);
			continue;
		}
		rpc_clear_running(task);
		spin_unlock(&queue->lock);
		if (task_is_async)
			return;

		/* sync task: sleep here */
		trace_rpc_task_sync_sleep(task, task->tk_action);
		status = out_of_line_wait_on_bit(&task->tk_runstate,
				RPC_TASK_QUEUED, rpc_wait_bit_killable,
				TASK_KILLABLE);
		if (status < 0) {
			/*
			 * When a sync task receives a signal, it exits with
			 * -ERESTARTSYS. In order to catch any callbacks that
			 * clean up after sleeping on some queue, we don't
			 * break the loop here, but go around once more.
			 */
			trace_rpc_task_signalled(task, task->tk_action);
			set_bit(RPC_TASK_SIGNALLED, &task->tk_runstate);
			task->tk_rpc_status = -ERESTARTSYS;
			rpc_exit(task, -ERESTARTSYS);
		}
		trace_rpc_task_sync_wake(task, task->tk_action);
	}

	/* Release all resources associated with the task */
	rpc_release_task(task);
}

基本上它的行為就是一直嘗試去連接 server 但是一直 timeout ，然後永遠不結束(除非收到 signal)，這就是為什麼在端點上對著一個 disconnected 的 directory stat 會卡住的原因

詳細的 backtrace:

#3  0xffffffffc036285a in __rpc_execute (task=task@entry=0xffff8d50cbd23d00) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/net/sunrpc/sched.c:893
#4  0xffffffffc03657da in rpc_execute (task=task@entry=0xffff8d50cbd23d00) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/net/sunrpc/sched.c:970
#5  0xffffffffc034ac4c in rpc_run_task (task_setup_data=task_setup_data@entry=0xffffba0900dcfb60) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/net/sunrpc/clnt.c:1157
#6  0xffffffffc09d9220 in nfs4_call_sync_custom (task_setup=task_setup@entry=0xffffba0900dcfb60) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/nfs/nfs4proc.c:1135
#7  0xffffffffc09d92ba in nfs4_do_call_sync (clnt=<optimized out>, server=server@entry=0xffff8d50cd88b800, msg=msg@entry=0xffffba0900dcfbe0, args=args@entry=0xffffba0900dcfbc0, res=res@entry=0xffffba0900dcfc00, task_flags=task_flags@entry=0x4) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/nfs/nfs4proc.c:1165
#8  0xffffffffc09dbf6a in _nfs4_proc_getattr (server=server@entry=0xffff8d50cd88b800, fhandle=fhandle@entry=0xffff8d50ca859520, fattr=fattr@entry=0xffff8d50ca03da00, label=label@entry=0x0 <fixed_percpu_data>, inode=inode@entry=0xffff8d50ca8596c8) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/nfs/nfs4proc.c:4295
#9  0xffffffffc09e3a54 in nfs4_proc_getattr (server=0xffff8d50cd88b800, fhandle=0xffff8d50ca859520, fattr=0xffff8d50ca03da00, label=0x0 <fixed_percpu_data>, inode=0xffff8d50ca8596c8) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/nfs/nfs4proc.c:4308
#10 0xffffffffc0960ce8 in __nfs_revalidate_inode (server=0xffff8d50cd88b800, inode=0xffff8d50ca8596c8) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/include/linux/nfs_fs.h:314
#11 0xffffffffc0961224 in nfs_getattr (mnt_userns=<optimized out>, path=<optimized out>, stat=0xffffba0900dcfe10, request_mask=0x7ff, query_flags=<optimized out>) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/nfs/inode.c:909
#12 0xffffffff91b9245d in vfs_getattr_nosec (path=path@entry=0xffffba0900dcfdc0, stat=stat@entry=0xffffba0900dcfe10, request_mask=request_mask@entry=0x7ff, query_flags=0x0, query_flags@entry=0x900) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/stat.c:123
#13 0xffffffff91b924b7 in vfs_getattr (path=path@entry=0xffffba0900dcfdc0, stat=stat@entry=0xffffba0900dcfe10, request_mask=request_mask@entry=0x7ff, query_flags=query_flags@entry=0x900) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/stat.c:160
#14 0xffffffff91b92559 in vfs_statx (dfd=dfd@entry=0xffffff9c, filename=0x7fffffffe411 "./general", flags=flags@entry=0x900, stat=stat@entry=0xffffba0900dcfe10, request_mask=request_mask@entry=0x7ff) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/stat.c:225
#15 0xffffffff91b92bae in vfs_fstatat (flags=0x100, stat=0xffffba0900dcfe10, filename=<optimized out>, dfd=0xffffff9c) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/stat.c:243
#16 vfs_lstat (stat=0xffffba0900dcfe10, name=<optimized out>) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/include/linux/fs.h:3324
#17 __do_sys_newlstat (filename=<optimized out>, statbuf=0x7fffffffdf10) at /build/linux-hwe-5.15-sbzV1t/linux-hwe-5.15-5.15.0/fs/stat.c:397

話說其實根據其他的文章所述，可以從 dmesg 看到

nfs: server [ip] not responding, timed out

代表他一直有嘗試想跟 server 聯繫上但是聯繫不到所以卡著

reference

• linux-5.19.94
• Ubuntu + qemu + gdb
• How To Set Up an NFS Mount on Ubuntu 20.04
• Really Simple network briding with qemu