[RFC PATCH] Possible use-after-free bug in mTLS connect

[Michael Nemanov <michael.nemanov@vastdata.com>]

The NFS-over-TLS implementation seems to have a use-after-free bug where
a raw unrefcounted pointer to an rpc_clnt is stored in xs_connect() and
accessed by a delayed workqueue item after the client has been freed.

The issue manifests when an NFS mount uses incorrect credentials (client
cert is valid but does not match the server's) during TLS setup,
leading to the client being freed while a delayed work item still
holds a pointer to it.

The patch contains several debug traces that hopefully illustrate the problem
and a key msleep(100) that helps (though not guarantees) reproduction.
I had to use pr_debug as the bug often involves a kernel crash and logs can
only be collected from vmcore-dmesg.
Used with kernel v7.0-rc5.

Traces from vmcore-dmesg.txt showing the lifecycle of the RPC
client from creation to use-after-free:
  [   38.611952] New mount #5
  [   38.630156] @ rpc_new_client: New: 00000000f636d223, parent: 0000000000000000	<< Client created
  [   38.630179] @ xs_connect: Queue connect work in 0 for clnt 00000000f636d223
  [   38.630209] @ xs_tcp_tls_setup_socket: Using clnt 00000000f636d223
  [   38.630258] @ rpc_new_client: New: 0000000004f8c0fe, parent: 0000000000000000
  [   38.630265] @ xs_connect: Queue connect work in 0 for clnt 0000000004f8c0fe
  [   38.752404] @ rpc_shutdown_client: 0000000004f8c0fe
  [   38.752474] @ rpc_free_client: put_cred 0000000004f8c0fe
  [   38.752489] @ xs_tcp_tls_setup_socket: Done with clnt 00000000f636d223. status=0
  [   38.752573] @ rpc_free_client_work: xprt_put done for 0000000004f8c0fe
  [   38.752955] @ xs_sock_process_cmsg: TLS alert -13, level 2
  [   38.753069] @ xs_tcp_state_change: sk_state=8
  [   38.857474] @ xs_reset_transport: Null transport->sock for xprt 0000000066fa6fda
  [   38.857558] @ xs_connect: Queue connect work in 0 for clnt 00000000f636d223	<< Client used
  [   38.857574] @ xs_tcp_tls_setup_socket: Using clnt 00000000f636d223
  [   38.857677] @ rpc_new_client: New: 00000000d1455d7f, parent: 0000000000000000
  [   38.857684] @ xs_connect: Queue connect work in 0 for clnt 00000000d1455d7f
  [   38.975657] @ rpc_shutdown_client: 00000000d1455d7f
  [   38.975728] @ rpc_free_client: put_cred 00000000d1455d7f
  [   38.975742] @ xs_tcp_tls_setup_socket: Done with clnt 00000000f636d223. status=0	<< Client used
  [   38.975836] @ rpc_free_client_work: xprt_put done for 00000000d1455d7f
  [   38.976220] @ xs_sock_process_cmsg: TLS alert -13, level 2
  [   38.976269] @ xs_tcp_state_change: sk_state=8
  [   38.976303] @ xs_connect: Queue connect work in 3000 for clnt 00000000f636d223	<< Client used
  [   39.065470] @ rpc_shutdown_client: 00000000f636d223
  [   39.065580] @ rpc_free_client: put_cred 00000000f636d223				<< Client being destroyed
  [   42.033267] @ xs_tcp_tls_setup_socket: Using clnt 00000000f636d223			<< Client used
  [   42.033481] @ rpc_new_client: New: 00000000762dc139, parent: 0000000000000000
  [   42.033505] @ xs_connect: Queue connect work in 0 for clnt 00000000762dc139
  [   42.153240] @ rpc_shutdown_client: 00000000762dc139
  [   42.153274] @ rpc_free_client: put_cred 00000000762dc139
  [   42.153283] @ xs_tcp_tls_setup_socket: Done with clnt 00000000f636d223. status=0
  [   42.153297] @ xs_reset_transport: Null transport->sock for xprt 0000000066fa6fda
  [   42.153355] @ rpc_free_client_work: xprt_put done for 00000000f636d223
  [   42.153373] @ rpc_free_client_work: xprt_put done for 00000000762dc139
  [   42.153419] @ xs_reset_transport: Null transport->sock for xprt 0000000093fd6749
  [   42.164197] ------------[ cut here ]------------
  [   42.165779] refcount_t: underflow; use-after-free.
  [   42.166596] WARNING: lib/refcount.c:28 at refcount_warn_saturate+0x5e/0x90, CPU#5: swapper/5/0

And for reference, a non-crashing attempt:
  [   16.756822] New mount #1
  [   17.122657] NFS: Registering the id_resolver key type
  [   17.123591] Key type id_resolver registered
  [   17.124329] Key type id_legacy registered
  [   17.131019] @ rpc_new_client: New: 0000000074283ee9, parent: 0000000000000000
  [   17.131035] @ xs_connect: Queue connect work in 0 for clnt 0000000074283ee9
  [   17.131042] @ xs_tcp_tls_setup_socket: Using clnt 0000000074283ee9
  [   17.131108] @ rpc_new_client: New: 00000000b25a12a5, parent: 0000000000000000
  [   17.131114] @ xs_connect: Queue connect work in 0 for clnt 00000000b25a12a5
  [   17.254743] @ xs_``tcp_state_change: sk_state=8
  [   17.262363] @ rpc_shutdown_client: 00000000b25a12a5
  [   17.262398] @ rpc_free_client: put_cred 00000000b25a12a5
  [   17.262404] @ xs_tcp_tls_setup_socket: Done with clnt 0000000074283ee9. status=0
  [   17.262448] @ rpc_free_client_work: xprt_put done for 00000000b25a12a5
  [   17.473543] @ xs_reset_transport: Null transport->sock for xprt 000000004c2083b6
  [   17.473597] @ xs_connect: Queue connect work in 0 for clnt 0000000074283ee9
  [   17.473606] @ xs_tcp_tls_setup_socket: Using clnt 0000000074283ee9
  [   17.473709] @ rpc_new_client: New: 00000000c549945c, parent: 0000000000000000
  [   17.473717] @ xs_connect: Queue connect work in 0 for clnt 00000000c549945c
  [   17.591937] @ rpc_shutdown_client: 00000000c549945c
  [   17.591977] @ rpc_free_client: put_cred 00000000c549945c
  [   17.591984] @ xs_tcp_tls_setup_socket: Done with clnt 0000000074283ee9. status=0
  [   17.592030] @ rpc_free_client_work: xprt_put done for 00000000c549945c
  [   17.592534] @ xs_sock_process_cmsg: TLS alert -13, level 2
  [   17.592564] @ xs_tcp_state_change: sk_state=8
  [   17.592569] @ rpc_shutdown_client: 0000000074283ee9
  [   17.592608] @ rpc_free_client: put_cred 0000000074283ee9
  [   17.593105] @ rpc_free_client_work: xprt_put done for 0000000074283ee9
  [   17.593148] @ xs_reset_transport: Null transport->sock for xprt 000000004c2083b6

Note that on some iterations, the queued work runs successfully
despite using a freed client. Not sure if this is of interest.

Reproduction script:

```bash
sudo echo 'file net/sunrpc/clnt.c +p' > /sys/kernel/debug/dynamic_debug/control
sudo echo 'file net/sunrpc/xprtsock.c +p' >> /sys/kernel/debug/dynamic_debug/control
sudo mkdir -p /mnt/export

for i in {1..1000}; do
        echo "Iteration $i"
        echo "New mount #$i" | sudo tee /dev/kmsg
        sudo mount -o vers=4.2,proto=tcp,xprtsec=mtls remote_addr:/opt/export /mnt/export
        sleep 5
done
```

What I understand:
The connecting task terminates, presumably due to the fatal TLS error as
expected. The upper client is being destroyed: `rpc_shutdown_client`
down to `rpc_free_client`, which *puts the creds* that would be used
by queued connect work.

Where I need help:
I don't understand if the use-after-free is the root cause and must be
fixed or a symptom of a problem elsewhere.
I am also not sure what causes the bug to manifest. It *might* be related
to the timing of server's FIN (sk_state=8 in the log) and the
flags it changes.
Any guidance or pointers on where to look next would be much appreciated.

Thank you for reading,
Michael.

Signed-off-by: Michael Nemanov <michael.nemanov@vastdata.com>
---
 net/sunrpc/clnt.c     | 4 ++++
 net/sunrpc/xprtsock.c | 8 ++++++++
 2 files changed, 12 insertions(+)

diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index bc8ca470718b..dbc7d51f073d 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -429,6 +429,7 @@ static struct rpc_clnt * rpc_new_client(const struct rpc_create_args *args,
 		refcount_inc(&parent->cl_count);
 
 	trace_rpc_clnt_new(clnt, xprt, args);
+	pr_debug("@ %s: New: %p, parent: %p\n", __func__, clnt, parent);
 	return clnt;
 
 out_no_path:
@@ -949,6 +950,7 @@ void rpc_shutdown_client(struct rpc_clnt *clnt)
 	might_sleep();
 
 	trace_rpc_clnt_shutdown(clnt);
+	pr_debug("@ %s: %p\n", __func__, clnt);
 
 	clnt->cl_shutdown = 1;
 	while (!list_empty(&clnt->cl_tasks)) {
@@ -983,6 +985,7 @@ static void rpc_free_client_work(struct work_struct *work)
 	rpc_free_clid(clnt);
 	rpc_clnt_remove_pipedir(clnt);
 	xprt_put(rcu_dereference_raw(clnt->cl_xprt));
+	pr_debug("@ %s: xprt_put done for %p\n", __func__, clnt);
 
 	kfree(clnt);
 	rpciod_down();
@@ -1000,6 +1003,7 @@ rpc_free_client(struct rpc_clnt *clnt)
 	clnt->cl_metrics = NULL;
 	xprt_iter_destroy(&clnt->cl_xpi);
 	put_cred(clnt->cl_cred);
+	pr_debug("@ %s: put_cred %p\n", __func__, clnt);
 
 	INIT_WORK(&clnt->cl_work, rpc_free_client_work);
 	schedule_work(&clnt->cl_work);
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
index 2e1fe6013361..cc4275e0b276 100644
--- a/net/sunrpc/xprtsock.c
+++ b/net/sunrpc/xprtsock.c
@@ -377,6 +377,7 @@ xs_sock_process_cmsg(struct socket *sock, struct msghdr *msg,
 		tls_alert_recv(sock->sk, msg, &level, &description);
 		ret = (level == TLS_ALERT_LEVEL_FATAL) ?
 			-EACCES : -EAGAIN;
+		pr_debug("@ %s: TLS alert %d, level %d\n", __func__, ret, level);
 		break;
 	default:
 		/* discard this record type */
@@ -1297,6 +1298,7 @@ static void xs_reset_transport(struct sock_xprt *transport)
 	transport->inet = NULL;
 	transport->sock = NULL;
 	transport->file = NULL;
+	pr_debug("@ %s: Null transport->sock for xprt %p\n", __func__, xprt);
 
 	sk->sk_user_data = NULL;
 	sk->sk_sndtimeo = 0;
@@ -1589,6 +1591,7 @@ static void xs_tcp_state_change(struct sock *sk)
 		 */
 		if (xprt->reestablish_timeout < XS_TCP_INIT_REEST_TO)
 			xprt->reestablish_timeout = XS_TCP_INIT_REEST_TO;
+		pr_debug("@ %s: sk_state=%d\n", __func__, sk->sk_state);
 		break;
 	case TCP_LAST_ACK:
 		set_bit(XPRT_CLOSING, &xprt->state);
@@ -2688,6 +2691,7 @@ static void xs_tcp_tls_setup_socket(struct work_struct *work)
 	struct sock_xprt *upper_transport =
 		container_of(work, struct sock_xprt, connect_worker.work);
 	struct rpc_clnt *upper_clnt = upper_transport->clnt;
+	pr_debug("@ %s: Using clnt %p\n", __func__, upper_clnt);
 	struct rpc_xprt *upper_xprt = &upper_transport->xprt;
 	struct rpc_create_args args = {
 		.net		= upper_xprt->xprt_net,
@@ -2759,6 +2763,7 @@ static void xs_tcp_tls_setup_socket(struct work_struct *work)
 	current_restore_flags(pflags, PF_MEMALLOC);
 	upper_transport->clnt = NULL;
 	xprt_unlock_connect(upper_xprt, upper_transport);
+	pr_debug("@ %s: Done with clnt %p. status=%d\n", __func__, upper_clnt, status);
 	return;
 
 out_close:
@@ -2806,6 +2811,7 @@ static void xs_connect(struct rpc_xprt *xprt, struct rpc_task *task)
 		dprintk("RPC:       xs_connect scheduled xprt %p\n", xprt);
 
 	transport->clnt = task->tk_client;
+	pr_debug("@ %s: Queue connect work in %lu for clnt %p\n", __func__, delay, transport->clnt);
 	queue_delayed_work(xprtiod_workqueue,
 			&transport->connect_worker,
 			delay);
@@ -2847,6 +2853,8 @@ static void xs_error_handle(struct work_struct *work)
 	struct sock_xprt *transport = container_of(work,
 			struct sock_xprt, error_worker);
 
+	msleep(100); // Improves reproducibility
+
 	xs_wake_disconnect(transport);
 	xs_wake_write(transport);
 	xs_wake_error(transport);

base-commit: c369299895a591d96745d6492d4888259b004a9e
-- 
2.43.7