Drop pending greetings from resend_queue in set_valid_greeting.

There's a race possible where set_valid_greeting() runs just as
another greeting reply sits on the resend_queue from a handshake:

  1. server_greeting() calls scoutfs_net_response() to queue the
     server's greeting reply on send_queue and kicks send_work.
  2. server_greeting() falls through to scoutfs_net_server_greeting()
     which calls set_valid_greeting() under conn->lock.
  3. If send_work already ran between steps 1 and 2 it moved the
     reply onto resend_queue.
  4. set_valid_greeting() splices resend_queue back into send_queue,
     re-queueing the greeting reply for a second send on the same
     socket.

The receiver treats a duplicate greeting as fatal: the recieve path
invalid_message check on the saw_greeting flag tears the connection
down silently. The client never sees a normal disconnect, just a
stalled connection, and the server only notices once the 30s
recovery timeout fires and fences the client.

Fix by walking resend_queue in set_valid_greeting() and dropping any
queued greeting before splicing them in. Dropping them should be safe
and mimics what scoutfs_net_shutdown_worker() does.

Signed-off-by: Auke Kok <auke.kok@versity.com>

kmod/src/lock.c

@@ -980,7 +980,7 @@ static bool lock_flags_invalid(int flags)
  */
 static int lock_key_range(struct super_block *sb, enum scoutfs_lock_mode mode, int flags,
 			  struct scoutfs_key *start, struct scoutfs_key *end,
-			  u64 ino, struct scoutfs_lock **ret_lock)
+			  struct scoutfs_lock **ret_lock)
 {
 	DECLARE_LOCK_INFO(sb, linfo);
 	struct scoutfs_lock *lock;
@@ -1028,8 +1028,6 @@ static int lock_key_range(struct super_block *sb, enum scoutfs_lock_mode mode, i
 		/* the fast path where we can use the granted mode */
 		if (lock_modes_match(lock->mode, mode)) {
 			lock_inc_count(lock->users, mode);
-			lock->last_user_pid[mode] = task_pid_nr(current);
-			lock->last_user_ino[mode] = ino;
 			*ret_lock = lock;
 			ret = 0;
 			break;
@@ -1110,7 +1108,7 @@ int scoutfs_lock_ino(struct super_block *sb, enum scoutfs_lock_mode mode, int fl
 	end.sk_zone = SCOUTFS_FS_ZONE;
 	end.ski_ino = cpu_to_le64(ino | SCOUTFS_LOCK_INODE_GROUP_MASK);
 
-	return lock_key_range(sb, mode, flags, &start, &end, ino, ret_lock);
+	return lock_key_range(sb, mode, flags, &start, &end, ret_lock);
 }
 
 /*
@@ -1240,7 +1238,7 @@ int scoutfs_lock_rename(struct super_block *sb, enum scoutfs_lock_mode mode, int
 		.sk_type = SCOUTFS_RENAME_TYPE,
 	};
 
-	return lock_key_range(sb, mode, flags, &key, &key, 0, lock);
+	return lock_key_range(sb, mode, flags, &key, &key, lock);
 }
 
 /*
@@ -1288,7 +1286,7 @@ int scoutfs_lock_inode_index(struct super_block *sb, enum scoutfs_lock_mode mode
 
 	scoutfs_lock_get_index_item_range(type, major, ino, &start, &end);
 
-	return lock_key_range(sb, mode, 0, &start, &end, ino, ret_lock);
+	return lock_key_range(sb, mode, 0, &start, &end, ret_lock);
 }
 
 /*
@@ -1315,7 +1313,7 @@ int scoutfs_lock_orphan(struct super_block *sb, enum scoutfs_lock_mode mode, int
 	end.sko_ino = cpu_to_le64(U64_MAX);
 	end.sk_type = SCOUTFS_ORPHAN_TYPE;
 
-	return lock_key_range(sb, mode, flags, &start, &end, ino, lock);
+	return lock_key_range(sb, mode, flags, &start, &end, lock);
 }
 
 int scoutfs_lock_xattr_totl(struct super_block *sb, enum scoutfs_lock_mode mode, int flags,
@@ -1326,7 +1324,7 @@ int scoutfs_lock_xattr_totl(struct super_block *sb, enum scoutfs_lock_mode mode,
 
 	scoutfs_totl_set_range(&start, &end);
 
-	return lock_key_range(sb, mode, flags, &start, &end, 0, lock);
+	return lock_key_range(sb, mode, flags, &start, &end, lock);
 }
 
 int scoutfs_lock_xattr_indx(struct super_block *sb, enum scoutfs_lock_mode mode, int flags,
@@ -1337,7 +1335,7 @@ int scoutfs_lock_xattr_indx(struct super_block *sb, enum scoutfs_lock_mode mode,
 
 	scoutfs_xattr_indx_get_range(&start, &end);
 
-	return lock_key_range(sb, mode, flags, &start, &end, 0, lock);
+	return lock_key_range(sb, mode, flags, &start, &end, lock);
 }
 
 int scoutfs_lock_quota(struct super_block *sb, enum scoutfs_lock_mode mode, int flags,
@@ -1348,7 +1346,7 @@ int scoutfs_lock_quota(struct super_block *sb, enum scoutfs_lock_mode mode, int
 
 	scoutfs_quota_get_lock_range(&start, &end);
 
-	return lock_key_range(sb, mode, flags, &start, &end, 0, lock);
+	return lock_key_range(sb, mode, flags, &start, &end, lock);
 }
 
 void scoutfs_unlock(struct super_block *sb, struct scoutfs_lock *lock, enum scoutfs_lock_mode mode)
@@ -1465,7 +1463,7 @@ static void lock_tseq_show(struct seq_file *m, struct scoutfs_tseq_entry *ent)
 	struct scoutfs_lock *lock =
 		container_of(ent, struct scoutfs_lock, tseq_entry);
 
-	seq_printf(m, "start "SK_FMT" end "SK_FMT" refresh_gen %llu mode %d waiters: rd %u wr %u wo %u users: rd %u wr %u wo %u ino: rd %llu wr %llu wo %llu pid: rd %d wr %d wo %d\n",
+	seq_printf(m, "start "SK_FMT" end "SK_FMT" refresh_gen %llu mode %d waiters: rd %u wr %u wo %u users: rd %u wr %u wo %u\n",
 			   SK_ARG(&lock->start), SK_ARG(&lock->end),
 			   lock->refresh_gen, lock->mode,
 			   lock->waiters[SCOUTFS_LOCK_READ],
@@ -1473,13 +1471,7 @@ static void lock_tseq_show(struct seq_file *m, struct scoutfs_tseq_entry *ent)
 			   lock->waiters[SCOUTFS_LOCK_WRITE_ONLY],
 			   lock->users[SCOUTFS_LOCK_READ],
 			   lock->users[SCOUTFS_LOCK_WRITE],
-			   lock->users[SCOUTFS_LOCK_WRITE_ONLY],
-			   lock->last_user_ino[SCOUTFS_LOCK_READ],
-			   lock->last_user_ino[SCOUTFS_LOCK_WRITE],
-			   lock->last_user_ino[SCOUTFS_LOCK_WRITE_ONLY],
-			   lock->last_user_pid[SCOUTFS_LOCK_READ],
-			   lock->last_user_pid[SCOUTFS_LOCK_WRITE],
-			   lock->last_user_pid[SCOUTFS_LOCK_WRITE_ONLY]);
+			   lock->users[SCOUTFS_LOCK_WRITE_ONLY]);
 }
 
 /*

kmod/src/lock.h

@@ -42,8 +42,6 @@ struct scoutfs_lock {
 	enum scoutfs_lock_mode invalidating_mode;
 	unsigned int waiters[SCOUTFS_LOCK_NR_MODES];
 	unsigned int users[SCOUTFS_LOCK_NR_MODES];
-	pid_t last_user_pid[SCOUTFS_LOCK_NR_MODES];
-	u64 last_user_ino[SCOUTFS_LOCK_NR_MODES];
 
 	struct scoutfs_tseq_entry tseq_entry;
 

kmod/src/lock_server.c

@@ -626,9 +626,14 @@ out:
 int scoutfs_lock_server_greeting(struct super_block *sb, u64 rid)
 {
 	struct scoutfs_key key;
+	bool pending;
 	int ret;
 
-	if (scoutfs_recov_is_pending(sb, rid, SCOUTFS_RECOV_LOCKS)) {
+	pending = scoutfs_recov_is_pending(sb, rid, SCOUTFS_RECOV_LOCKS);
+
+	trace_scoutfs_lock_server_greeting(sb, rid, pending);
+
+	if (pending) {
 		scoutfs_key_set_zeros(&key);
 		ret = scoutfs_server_lock_recover_request(sb, rid, &key);
 	} else {

kmod/src/net.c

@@ -1730,12 +1730,30 @@ int scoutfs_net_connect(struct super_block *sb,
 
 static void set_valid_greeting(struct scoutfs_net_connection *conn)
 {
+	struct net_info *ninf = SCOUTFS_SB(conn->sb)->net_info;
+	struct message_send *msend;
+	struct message_send *tmp;
+
 	assert_spin_locked(&conn->lock);
 
 	/* recv should have dropped invalid duplicate greeting messages */
 	BUG_ON(test_conn_fl(conn, valid_greeting));
 
 	set_conn_fl(conn, valid_greeting);
+
+	/*
+	 * Drop greetings from the resend_queue before splicing it into
+	 * the send_queue. We might have a greeting left in the resend
+	 * queue at the moment that we reach this point. A duplicate
+	 * greeting is treated as fatal and causes a stall and fence.
+	 */
+	list_for_each_entry_safe(msend, tmp, &conn->resend_queue, head) {
+		if (msend->nh.cmd == SCOUTFS_NET_CMD_GREETING) {
+			msend->dead = 1;
+			free_msend(ninf, conn, msend);
+		}
+	}
+
 	list_splice_tail_init(&conn->resend_queue, &conn->send_queue);
 	queue_work(conn->workq, &conn->send_work);
 }

kmod/src/recov.c

@@ -21,6 +21,7 @@
 #include "super.h"
 #include "recov.h"
 #include "cmp.h"
+#include "scoutfs_trace.h"
 
 /*
  * There are a few server messages which can't be processed until they
@@ -119,6 +120,9 @@ int scoutfs_recov_prepare(struct super_block *sb, u64 rid, int which)
 	spin_unlock(&recinf->lock);
 
 	kfree(alloc);
+
+	trace_scoutfs_recov_prepare(sb, rid, which);
+
 	return 0;
 }
 
@@ -135,6 +139,15 @@ static int recov_finished(struct recov_info *recinf)
 static void timer_callback(struct timer_list *timer)
 {
 	struct recov_info *recinf = from_timer(recinf, timer, timer);
+	struct recov_pending *pend;
+	int nr = 0;
+
+	spin_lock(&recinf->lock);
+	list_for_each_entry(pend, &recinf->pending, head)
+		nr++;
+	spin_unlock(&recinf->lock);
+
+	trace_scoutfs_recov_timeout_fire(recinf->sb, nr);
 
 	recinf->timeout_fn(recinf->sb);
 }
@@ -181,6 +194,8 @@ int scoutfs_recov_finish(struct super_block *sb, u64 rid, int which)
 {
 	DECLARE_RECOV_INFO(sb, recinf);
 	struct recov_pending *pend;
+	struct recov_pending *iter;
+	int remaining = 0;
 	int ret = 0;
 
 	spin_lock(&recinf->lock);
@@ -196,8 +211,13 @@ int scoutfs_recov_finish(struct super_block *sb, u64 rid, int which)
 		}
 	}
 
+	list_for_each_entry(iter, &recinf->pending, head)
+		remaining++;
+
 	spin_unlock(&recinf->lock);
 
+	trace_scoutfs_recov_finish(sb, rid, which, remaining);
+
 	if (ret > 0)
 		del_timer_sync(&recinf->timer);
 

kmod/src/scoutfs_trace.h

@@ -2121,6 +2121,110 @@ DEFINE_EVENT(scoutfs_server_client_count_class, scoutfs_server_client_down,
 	TP_ARGS(sb, rid, nr_clients)
 );
 
+TRACE_EVENT(scoutfs_recov_prepare,
+	TP_PROTO(struct super_block *sb, u64 rid, int which),
+
+	TP_ARGS(sb, rid, which),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(int, which)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->which = which;
+	),
+
+	TP_printk(SCSBF" rid %016llx which 0x%x",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->which)
+);
+
+TRACE_EVENT(scoutfs_recov_finish,
+	TP_PROTO(struct super_block *sb, u64 rid, int which, int remaining),
+
+	TP_ARGS(sb, rid, which, remaining),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(int, which)
+		__field(int, remaining)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->which = which;
+		__entry->remaining = remaining;
+	),
+
+	TP_printk(SCSBF" rid %016llx which 0x%x remaining %d",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->which,
+		  __entry->remaining)
+);
+
+TRACE_EVENT(scoutfs_recov_timeout_fire,
+	TP_PROTO(struct super_block *sb, int nr_pending),
+
+	TP_ARGS(sb, nr_pending),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(int, nr_pending)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->nr_pending = nr_pending;
+	),
+
+	TP_printk(SCSBF" nr_pending %d",
+		  SCSB_TRACE_ARGS, __entry->nr_pending)
+);
+
+TRACE_EVENT(scoutfs_recov_fence_rid,
+	TP_PROTO(struct super_block *sb, u64 rid),
+
+	TP_ARGS(sb, rid),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+	),
+
+	TP_printk(SCSBF" rid %016llx",
+		  SCSB_TRACE_ARGS, __entry->c_rid)
+);
+
+TRACE_EVENT(scoutfs_lock_server_greeting,
+	TP_PROTO(struct super_block *sb, u64 rid, bool recov_pending),
+
+	TP_ARGS(sb, rid, recov_pending),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(bool, recov_pending)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->recov_pending = recov_pending;
+	),
+
+	TP_printk(SCSBF" rid %016llx recov_pending %d",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->recov_pending)
+);
+
 DECLARE_EVENT_CLASS(scoutfs_server_commit_users_class,
         TP_PROTO(struct super_block *sb, int holding, int applying,
 		 int nr_holders, u32 budget,

kmod/src/server.c

@@ -4386,6 +4386,8 @@ static void fence_pending_recov_worker(struct work_struct *work)
 		scoutfs_err(sb, "%lu ms recovery timeout expired for client rid %016llx, fencing",
 			    SERVER_RECOV_TIMEOUT_MS, rid);
 
+		trace_scoutfs_recov_fence_rid(sb, rid);
+
 		ret = lookup_mounted_client_addr(sb, rid, &addr);
 		if (ret < 0) {
 			scoutfs_err(sb, "client rid addr lookup err %d, shutting down server", ret);

tests/golden/lock-pid-ino

@@ -1,6 +0,0 @@
-== set up file
-== exercise read, write, and write-only modes
-== verify FS-zone lock recorded read and write ino+pid
-== verify orphan-zone lock recorded write-only ino+pid
-== contend on a single inode with concurrent read and write loops
-== verify both rd and wr slots populated by concurrent contention

tests/sequence

@@ -32,7 +32,6 @@ totl-merge-read.sh
 quota-invalidate-race.sh
 totl-delta-inject.sh
 lock-refleak.sh
-lock-pid-ino.sh
 lock-shrink-consistency.sh
 lock-shrink-read-race.sh
 lock-pr-cw-conflict.sh

tests/tests/lock-pid-ino.sh

@@ -1,68 +0,0 @@
-#
-# verify debugfs client_locks reports per-mode last-user PID and inode.
-#
-
-t_require_commands stat touch awk rm
-
-FILE="$T_D0/file"
-
-echo "== set up file"
-touch "$FILE"
-INO=$(stat -c %i "$FILE")
-GROUP_START=$(( INO & ~1023 ))
-
-echo "== exercise read, write, and write-only modes"
-t_quiet stat "$FILE"
-echo data > "$FILE"
-rm -f "$FILE"
-
-echo "== verify FS-zone lock recorded read and write ino+pid"
-ERR=$(awk -v group="$GROUP_START" -v ino="$INO" '
-	$2 == "16." group ".0.0.0.0" {
-		if ($25 != ino || $32 <= 0)
-			print "read mode: ino=" $25 " pid=" $32 " want ino=" ino " pid>0"
-		if ($27 != ino || $34 <= 0)
-			print "write mode: ino=" $27 " pid=" $34 " want ino=" ino " pid>0"
-		found = 1
-	}
-	END { if (!found) print "no FS-zone client_locks line for group " group }
-' < "$(t_debugfs_path)/client_locks")
-[ -n "$ERR" ] && t_fail "$ERR"
-
-echo "== verify orphan-zone lock recorded write-only ino+pid"
-ERR=$(awk -v ino="$INO" '
-	$2 == "8.0.4.0.0.0" {
-		if ($29 != ino || $36 <= 0)
-			print "write-only mode: ino=" $29 " pid=" $36 " want ino=" ino " pid>0"
-		found = 1
-	}
-	END { if (!found) print "no orphan-zone client_locks line" }
-' < "$(t_debugfs_path)/client_locks")
-[ -n "$ERR" ] && t_fail "$ERR"
-
-echo "== contend on a single inode with concurrent read and write loops"
-FILE2="$T_D0/file2"
-touch "$FILE2"
-INO2=$(stat -c %i "$FILE2")
-GROUP2=$(( INO2 & ~1023 ))
-
-for i in $(seq 1 5); do t_quiet stat "$FILE2"; done &
-RPID=$!
-for i in $(seq 1 5); do echo $i > "$FILE2"; done &
-WPID=$!
-wait $RPID $WPID
-
-echo "== verify both rd and wr slots populated by concurrent contention"
-ERR=$(awk -v group="$GROUP2" -v ino="$INO2" '
-	$2 == "16." group ".0.0.0.0" {
-		if ($25 != ino || $32 <= 0)
-			print "concurrent read: ino=" $25 " pid=" $32 " want ino=" ino " pid>0"
-		if ($27 != ino || $34 <= 0)
-			print "concurrent write: ino=" $27 " pid=" $34 " want ino=" ino " pid>0"
-		found = 1
-	}
-	END { if (!found) print "no FS-zone client_locks line for group " group }
-' < "$(t_debugfs_path)/client_locks")
-[ -n "$ERR" ] && t_fail "$ERR"
-
-t_pass