diff mbox series

cifs_mount_get_tcon() is broken?

Message ID 3749392.1712238821@warthog.procyon.org.uk (mailing list archive)
State New, archived
Headers show
Series cifs_mount_get_tcon() is broken? | expand

Commit Message

David Howells April 4, 2024, 1:53 p.m. UTC
Hi Steve, Shyam, Paulo,

I've been looking into the duplicate fscache volume cookie message I see when
running the generic/013 xfstest on cifs with a "-o fsc" mount option.  It
turns out that in this particular case, cifs_mount_get_tcon() finds a tcon it
can reuse... and then partially reinitialises it - whilst it is still in use
by another mount.

This is probably a bad idea because it's resetting/changing various values on
the tcon without any locking - whilst it may be being accessed by other
filesystem operations.

Probably the function should more or less drop straight out if the tcon is
already set up - as cifs_get_tcon() (which it calls to get a tcon) does.  That
said, there is the possibility that the second mount wants different
parameters - but I'm not sure how that affects things.

I added a tracepoint (see attached patch) that allows the evolution of the
tcon refcount to be followed.  With:

	echo 1 > /sys/kernel/debug/tracing/events/fscache/fscache_volume/enable
	echo 1 > /sys/kernel/debug/tracing/events/cifs/smb3_tcon_ref/enable
	mount //carina/test /xfstest.test -o user=shares,pass=xxx,fsc
	mount //carina/test /mnt -o user=shares,pass=xxx,fsc
	umount /xfstest.test 
	umount /mnt

I see:

    mount.cifs-5744 ...    50.282306: smb3_tcon_ref: TC=00000001 NEW       r=1
    mount.cifs-5744 ...    50.283215: smb3_tcon_ref: TC=00000002 NEW       r=1
    mount.cifs-5744 ...    50.286871: fscache_volume: V=00000001 NEW acq   u=1
    mount.cifs-5744 ...    50.286872: smb3_tcon_ref: TC=00000002 SEE_F_Ok  r=1
    mount.cifs-5744 ...    50.288346: fscache_volume: V=00000001 GET cook  u=2
    mount.cifs-5810 ...   344.536761: smb3_tcon_ref: TC=00000002 GET_Find  r=2
    mount.cifs-5810 ...   344.538981: fscache_volume: V=00000002 NEW acq   u=1
    mount.cifs-5810 ...   344.538982: fscache_volume: V=00000001 *COLLIDE* u=2
    mount.cifs-5810 ...   344.538982: fscache_volume: V=00000002 PUT hcoll u=0
    mount.cifs-5810 ...   344.538983: fscache_volume: V=00000002 FREE      u=0
    mount.cifs-5810 ...   344.544859: smb3_tcon_ref: TC=00000002 SEE_F_CO! r=2
    mount.cifs-5810 ...   344.546497: smb3_tcon_ref: TC=00000002 PUT_Tlink r=1
        umount-6054 ...  1609.705106: fscache_volume: V=00000001 PUT cook  u=1
        umount-6054 ...  1609.705237: smb3_tcon_ref: TC=00000002 PUT_Tlink r=0
        umount-6054 ...  1609.706098: smb3_tcon_ref: TC=00000002 SEE_F_Rlq r=0
        umount-6054 ...  1609.706099: smb3_tcon_ref: TC=00000002 FREE      r=0
        umount-6054 ...  1609.706101: smb3_tcon_ref: TC=00000001 FREE      r=1

in the tracebuffer.  tcons get labelled with integer debugging IDs as they are
created, which you can see in TC=nnnnnnnn.  fscache volume cookies similarly
get labelled as V=nnnnnnnn.

The "GET_Find" line corresponds to the refcount increment in cifs_find_tcon()
where it finds an already live tcon and reuses it.

This is then followed by fscache attempting to create a second volume cookie
because that's driven from cifs_mount_get_tcon() - and cifs reports this as
the "SEE_F_CO!" line.

Both tcons that were created are freed, but TC=00000001 does not get a final
put, but is rather freed directly with a ref still attached - presumably by
design.

The simplest fix I can make is to take a mutex around the acquisition of the
volume cookie, and check to see if I've tried to get one before.  That said,
it looks like cifs_mount_get_tcon() may have other problems too and a more
general solution may be required.

David
---
commit 072e0337280fb1f1dcca883ca1e6340eb9be265c
Author: David Howells <dhowells@redhat.com>
Date:   Thu Apr 4 13:51:36 2024 +0100

    cifs: Add tracing for the tcon struct refcounting
diff mbox series

Patch

diff --git a/fs/smb/client/cifsfs.c b/fs/smb/client/cifsfs.c
index 5ce2f54cb086..abbfb5138ee2 100644
--- a/fs/smb/client/cifsfs.c
+++ b/fs/smb/client/cifsfs.c
@@ -742,6 +742,8 @@  static void cifs_umount_begin(struct super_block *sb)
 
 	spin_lock(&cifs_tcp_ses_lock);
 	spin_lock(&tcon->tc_lock);
+	trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+			    netfs_trace_tcon_ref_see_umount);
 	if ((tcon->tc_count > 1) || (tcon->status == TID_EXITING)) {
 		/* we have other mounts to same share or we have
 		   already tried to umount this and woken up
diff --git a/fs/smb/client/cifsglob.h b/fs/smb/client/cifsglob.h
index 94885bf86ff2..22325fec7eb1 100644
--- a/fs/smb/client/cifsglob.h
+++ b/fs/smb/client/cifsglob.h
@@ -1188,6 +1188,7 @@  struct cifs_fattr {
  */
 struct cifs_tcon {
 	struct list_head tcon_list;
+	int debug_id;		/* Debugging for tracing */
 	int tc_count;
 	struct list_head rlist; /* reconnect list */
 	spinlock_t tc_lock;  /* protect anything here that is not protected */
diff --git a/fs/smb/client/cifsproto.h b/fs/smb/client/cifsproto.h
index 57ec67cdc31e..f49a63aed4dd 100644
--- a/fs/smb/client/cifsproto.h
+++ b/fs/smb/client/cifsproto.h
@@ -305,7 +305,7 @@  cifs_get_tcp_session(struct smb3_fs_context *ctx,
 		     struct TCP_Server_Info *primary_server);
 extern void cifs_put_tcp_session(struct TCP_Server_Info *server,
 				 int from_reconnect);
-extern void cifs_put_tcon(struct cifs_tcon *tcon);
+extern void cifs_put_tcon(struct cifs_tcon *tcon, enum smb3_tcon_ref_trace trace);
 
 extern void cifs_release_automount_timer(void);
 
@@ -719,8 +719,6 @@  static inline int cifs_create_options(struct cifs_sb_info *cifs_sb, int options)
 		return options;
 }
 
-struct super_block *cifs_get_tcon_super(struct cifs_tcon *tcon);
-void cifs_put_tcon_super(struct super_block *sb);
 int cifs_wait_for_server_reconnect(struct TCP_Server_Info *server, bool retry);
 
 /* Put references of @ses and @ses->dfs_root_ses */
diff --git a/fs/smb/client/connect.c b/fs/smb/client/connect.c
index 9b85b5341822..7502792a9c89 100644
--- a/fs/smb/client/connect.c
+++ b/fs/smb/client/connect.c
@@ -2434,6 +2434,8 @@  cifs_find_tcon(struct cifs_ses *ses, struct smb3_fs_context *ctx)
 			continue;
 		}
 		++tcon->tc_count;
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_get_find);
 		spin_unlock(&tcon->tc_lock);
 		spin_unlock(&cifs_tcp_ses_lock);
 		return tcon;
@@ -2443,7 +2445,7 @@  cifs_find_tcon(struct cifs_ses *ses, struct smb3_fs_context *ctx)
 }
 
 void
-cifs_put_tcon(struct cifs_tcon *tcon)
+cifs_put_tcon(struct cifs_tcon *tcon, enum smb3_tcon_ref_trace trace)
 {
 	unsigned int xid;
 	struct cifs_ses *ses;
@@ -2459,6 +2461,7 @@  cifs_put_tcon(struct cifs_tcon *tcon)
 	cifs_dbg(FYI, "%s: tc_count=%d\n", __func__, tcon->tc_count);
 	spin_lock(&cifs_tcp_ses_lock);
 	spin_lock(&tcon->tc_lock);
+	trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count - 1, trace);
 	if (--tcon->tc_count > 0) {
 		spin_unlock(&tcon->tc_lock);
 		spin_unlock(&cifs_tcp_ses_lock);
@@ -2756,7 +2759,7 @@  cifs_put_tlink(struct tcon_link *tlink)
 	}
 
 	if (!IS_ERR(tlink_tcon(tlink)))
-		cifs_put_tcon(tlink_tcon(tlink));
+		cifs_put_tcon(tlink_tcon(tlink), netfs_trace_tcon_ref_put_tlink);
 	kfree(tlink);
 }
 
@@ -3321,7 +3324,7 @@  void cifs_mount_put_conns(struct cifs_mount_ctx *mnt_ctx)
 	int rc = 0;
 
 	if (mnt_ctx->tcon)
-		cifs_put_tcon(mnt_ctx->tcon);
+		cifs_put_tcon(mnt_ctx->tcon, netfs_trace_tcon_ref_put_mnt_ctx);
 	else if (mnt_ctx->ses)
 		cifs_put_smb_ses(mnt_ctx->ses);
 	else if (mnt_ctx->server)
diff --git a/fs/smb/client/fscache.c b/fs/smb/client/fscache.c
index 147e8cd38fe1..9bf8a4fb06bd 100644
--- a/fs/smb/client/fscache.c
+++ b/fs/smb/client/fscache.c
@@ -82,6 +82,11 @@  int cifs_fscache_get_super_cookie(struct cifs_tcon *tcon)
 		}
 		pr_err("Cache volume key already in use (%s)\n", key);
 		vcookie = NULL;
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_see_fscache_collision);
+	} else {
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_see_fscache_okay);
 	}
 
 	tcon->fscache = vcookie;
@@ -102,6 +107,8 @@  void cifs_fscache_release_super_cookie(struct cifs_tcon *tcon)
 	cifs_fscache_fill_volume_coherency(tcon, &cd);
 	fscache_relinquish_volume(tcon->fscache, &cd, false);
 	tcon->fscache = NULL;
+	trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+			    netfs_trace_tcon_ref_see_fscache_relinq);
 }
 
 void cifs_fscache_get_inode_cookie(struct inode *inode)
diff --git a/fs/smb/client/misc.c b/fs/smb/client/misc.c
index c3771fc81328..746f127e080d 100644
--- a/fs/smb/client/misc.c
+++ b/fs/smb/client/misc.c
@@ -113,6 +113,7 @@  struct cifs_tcon *
 tcon_info_alloc(bool dir_leases_enabled)
 {
 	struct cifs_tcon *ret_buf;
+	static atomic_t tcon_debug_id;
 
 	ret_buf = kzalloc(sizeof(*ret_buf), GFP_KERNEL);
 	if (!ret_buf)
@@ -129,7 +130,8 @@  tcon_info_alloc(bool dir_leases_enabled)
 
 	atomic_inc(&tconInfoAllocCount);
 	ret_buf->status = TID_NEW;
-	++ret_buf->tc_count;
+	ret_buf->debug_id = atomic_inc_return(&tcon_debug_id);
+	ret_buf->tc_count = 1;
 	spin_lock_init(&ret_buf->tc_lock);
 	INIT_LIST_HEAD(&ret_buf->openFileList);
 	INIT_LIST_HEAD(&ret_buf->tcon_list);
@@ -141,6 +143,8 @@  tcon_info_alloc(bool dir_leases_enabled)
 #ifdef CONFIG_CIFS_DFS_UPCALL
 	INIT_LIST_HEAD(&ret_buf->dfs_ses_list);
 #endif
+	trace_smb3_tcon_ref(ret_buf->debug_id, ret_buf->tc_count,
+			    netfs_trace_tcon_ref_new);
 
 	return ret_buf;
 }
@@ -152,6 +156,8 @@  tconInfoFree(struct cifs_tcon *tcon)
 		cifs_dbg(FYI, "Null buffer passed to tconInfoFree\n");
 		return;
 	}
+	trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+			    netfs_trace_tcon_ref_free);
 	free_cached_dirs(tcon->cfids);
 	atomic_dec(&tconInfoAllocCount);
 	kfree(tcon->nativeFileSystem);
diff --git a/fs/smb/client/smb2misc.c b/fs/smb/client/smb2misc.c
index 82b84a4941dd..8544ac5914d6 100644
--- a/fs/smb/client/smb2misc.c
+++ b/fs/smb/client/smb2misc.c
@@ -763,7 +763,7 @@  smb2_cancelled_close_fid(struct work_struct *work)
 	if (rc)
 		cifs_tcon_dbg(VFS, "Close cancelled mid failed rc:%d\n", rc);
 
-	cifs_put_tcon(tcon);
+	cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_close_fid);
 	kfree(cancelled);
 }
 
@@ -807,6 +807,8 @@  smb2_handle_cancelled_close(struct cifs_tcon *tcon, __u64 persistent_fid,
 	if (tcon->tc_count <= 0) {
 		struct TCP_Server_Info *server = NULL;
 
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_see_cancelled_close);
 		WARN_ONCE(tcon->tc_count < 0, "tcon refcount is negative");
 		spin_unlock(&cifs_tcp_ses_lock);
 
@@ -819,12 +821,14 @@  smb2_handle_cancelled_close(struct cifs_tcon *tcon, __u64 persistent_fid,
 		return 0;
 	}
 	tcon->tc_count++;
+	trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+			    netfs_trace_tcon_ref_get_cancelled_close);
 	spin_unlock(&cifs_tcp_ses_lock);
 
 	rc = __smb2_handle_cancelled_cmd(tcon, SMB2_CLOSE_HE, 0,
 					 persistent_fid, volatile_fid);
 	if (rc)
-		cifs_put_tcon(tcon);
+		cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_close);
 
 	return rc;
 }
@@ -852,7 +856,7 @@  smb2_handle_cancelled_mid(struct mid_q_entry *mid, struct TCP_Server_Info *serve
 					 rsp->PersistentFileId,
 					 rsp->VolatileFileId);
 	if (rc)
-		cifs_put_tcon(tcon);
+		cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_mid);
 
 	return rc;
 }
diff --git a/fs/smb/client/smb2ops.c b/fs/smb/client/smb2ops.c
index 2413006e5f39..0700ced3106b 100644
--- a/fs/smb/client/smb2ops.c
+++ b/fs/smb/client/smb2ops.c
@@ -2912,8 +2912,11 @@  smb2_get_dfs_refer(const unsigned int xid, struct cifs_ses *ses,
 		tcon = list_first_entry_or_null(&ses->tcon_list,
 						struct cifs_tcon,
 						tcon_list);
-		if (tcon)
+		if (tcon) {
 			tcon->tc_count++;
+			trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+					    netfs_trace_tcon_ref_get_dfs_refer);
+		}
 		spin_unlock(&cifs_tcp_ses_lock);
 	}
 
@@ -2977,6 +2980,8 @@  smb2_get_dfs_refer(const unsigned int xid, struct cifs_ses *ses,
 		/* ipc tcons are not refcounted */
 		spin_lock(&cifs_tcp_ses_lock);
 		tcon->tc_count--;
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_dec_dfs_refer);
 		/* tc_count can never go negative */
 		WARN_ON(tcon->tc_count < 0);
 		spin_unlock(&cifs_tcp_ses_lock);
diff --git a/fs/smb/client/smb2pdu.c b/fs/smb/client/smb2pdu.c
index 96a23a26d205..f3d3895d6461 100644
--- a/fs/smb/client/smb2pdu.c
+++ b/fs/smb/client/smb2pdu.c
@@ -4129,6 +4129,8 @@  void smb2_reconnect_server(struct work_struct *work)
 		list_for_each_entry(tcon, &ses->tcon_list, tcon_list) {
 			if (tcon->need_reconnect || tcon->need_reopen_files) {
 				tcon->tc_count++;
+				trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+						    netfs_trace_tcon_ref_get_reconnect_server);
 				list_add_tail(&tcon->rlist, &tmp_list);
 				tcon_selected = true;
 			}
@@ -4167,7 +4169,7 @@  void smb2_reconnect_server(struct work_struct *work)
 		if (tcon->ipc)
 			cifs_put_smb_ses(tcon->ses);
 		else
-			cifs_put_tcon(tcon);
+			cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_reconnect_server);
 	}
 
 	if (!ses_exist)
diff --git a/fs/smb/client/smb2transport.c b/fs/smb/client/smb2transport.c
index 5a3ca62d2f07..8402077b855b 100644
--- a/fs/smb/client/smb2transport.c
+++ b/fs/smb/client/smb2transport.c
@@ -189,6 +189,8 @@  smb2_find_smb_sess_tcon_unlocked(struct cifs_ses *ses, __u32  tid)
 		if (tcon->tid != tid)
 			continue;
 		++tcon->tc_count;
+		trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+				    netfs_trace_tcon_ref_get_find_smb2);
 		return tcon;
 	}
 
diff --git a/fs/smb/client/trace.h b/fs/smb/client/trace.h
index 3972638c308f..dc84c0eef56c 100644
--- a/fs/smb/client/trace.h
+++ b/fs/smb/client/trace.h
@@ -3,6 +3,9 @@ 
  *   Copyright (C) 2018, Microsoft Corporation.
  *
  *   Author(s): Steve French <stfrench@microsoft.com>
+ *
+ * Please use this 3-part article as a reference for writing new tracepoints:
+ * https://lwn.net/Articles/379903/
  */
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM cifs
@@ -15,9 +18,64 @@ 
 #include <linux/inet.h>
 
 /*
- * Please use this 3-part article as a reference for writing new tracepoints:
- * https://lwn.net/Articles/379903/
+ * Specify enums for tracing information.
+ */
+#define smb3_tcon_ref_traces					    \
+	EM(netfs_trace_tcon_ref_dec_dfs_refer,		"DEC_DfsRf") \
+	EM(netfs_trace_tcon_ref_free,			"FREE     ") \
+	EM(netfs_trace_tcon_ref_get_cancelled_close,	"GET_C_Cls") \
+	EM(netfs_trace_tcon_ref_get_dfs_refer,		"GET_DfsRe") \
+	EM(netfs_trace_tcon_ref_get_find,		"GET_Find ") \
+	EM(netfs_trace_tcon_ref_get_find_smb2,		"GET_Find2") \
+	EM(netfs_trace_tcon_ref_get_reconnect_server,	"GET_Recon") \
+	EM(netfs_trace_tcon_ref_new,			"NEW      ") \
+	EM(netfs_trace_tcon_ref_put_cancelled_close,	"PUT_C_Cls") \
+	EM(netfs_trace_tcon_ref_put_cancelled_close_fid,"PUT_C_Fid") \
+	EM(netfs_trace_tcon_ref_put_cancelled_mid,	"PUT_C_Mid") \
+	EM(netfs_trace_tcon_ref_put_mnt_ctx,		"PUT_MntCx") \
+	EM(netfs_trace_tcon_ref_put_reconnect_server,	"PUT_Recon") \
+	EM(netfs_trace_tcon_ref_put_tlink,		"PUT_Tlink") \
+	EM(netfs_trace_tcon_ref_see_cancelled_close,	"SEE_C_Cls") \
+	EM(netfs_trace_tcon_ref_see_fscache_collision,	"SEE_F_CO!") \
+	EM(netfs_trace_tcon_ref_see_fscache_okay,	"SEE_F_Ok ") \
+	EM(netfs_trace_tcon_ref_see_fscache_relinq,	"SEE_F_Rlq") \
+	E_(netfs_trace_tcon_ref_see_umount,		"SEE_Umnt ")
+
+#undef EM
+#undef E_
+
+/*
+ * Define those tracing enums.
+ */
+#ifndef __SMB3_DECLARE_TRACE_ENUMS_ONCE_ONLY
+#define __SMB3_DECLARE_TRACE_ENUMS_ONCE_ONLY
+
+#define EM(a, b) a,
+#define E_(a, b) a
+
+enum smb3_tcon_ref_trace { smb3_tcon_ref_traces } __mode(byte);
+
+#undef EM
+#undef E_
+#endif
+
+/*
+ * Export enum symbols via userspace.
+ */
+#define EM(a, b) TRACE_DEFINE_ENUM(a);
+#define E_(a, b) TRACE_DEFINE_ENUM(a);
+
+smb3_tcon_ref_traces;
+
+#undef EM
+#undef E_
+
+/*
+ * Now redefine the EM() and E_() macros to map the enums to the strings that
+ * will be printed in the output.
  */
+#define EM(a, b)	{ a, b },
+#define E_(a, b)	{ a, b }
 
 /* For logging errors in read or write */
 DECLARE_EVENT_CLASS(smb3_rw_err_class,
@@ -1231,6 +1289,30 @@  DEFINE_SMB3_CREDIT_EVENT(waitff_credits);
 DEFINE_SMB3_CREDIT_EVENT(overflow_credits);
 DEFINE_SMB3_CREDIT_EVENT(set_credits);
 
+
+TRACE_EVENT(smb3_tcon_ref,
+	    TP_PROTO(unsigned int tcon_debug_id, int ref,
+		     enum smb3_tcon_ref_trace trace),
+	    TP_ARGS(tcon_debug_id, ref, trace),
+	    TP_STRUCT__entry(
+		    __field(unsigned int,		tcon		)
+		    __field(int,			ref		)
+		    __field(enum smb3_tcon_ref_trace,	trace		)
+			     ),
+	    TP_fast_assign(
+		    __entry->tcon	= tcon_debug_id;
+		    __entry->ref	= ref;
+		    __entry->trace	= trace;
+			   ),
+	    TP_printk("TC=%08x %s r=%u",
+		      __entry->tcon,
+		      __print_symbolic(__entry->trace, smb3_tcon_ref_traces),
+		      __entry->ref)
+	    );
+
+
+#undef EM
+#undef E_
 #endif /* _CIFS_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH