From f9b09264a4857afc5b10db8b0f157676848de926 Mon Sep 17 00:00:00 2001
From: David Teigland <teigland@redhat.com>
Date: Mar 10 2020 17:29:41 +0000
Subject: sanlock: client debug logging


New debug logging for client connections, enabled with
debug_clients=1 in sanlock.conf.

---

diff --git a/src/cmd.c b/src/cmd.c
index b79e224..ee29a65 100644
--- a/src/cmd.c
+++ b/src/cmd.c
@@ -53,7 +53,7 @@ void client_resume(int ci);
 void client_free(int ci);
 void client_recv_all(int ci, struct sm_header *h_recv, int pos);
 void client_pid_dead(int ci);
-void send_result(int fd, struct sm_header *h_recv, int result);
+void send_result(int ci, int fd, struct sm_header *h_recv, int result);
 
 static uint32_t token_id_counter = 1;
 
@@ -533,7 +533,7 @@ static void cmd_acquire(struct task *task, struct cmd_args *ca)
  reply:
 	if (!recv_done)
 		client_recv_all(ca->ci_in, &ca->header, pos);
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -727,7 +727,7 @@ static void cmd_release(struct task *task, struct cmd_args *ca)
 		client_free(cl_ci);
 	}
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -943,7 +943,7 @@ static void cmd_convert(struct task *task, struct cmd_args *ca)
 		client_free(cl_ci);
 	}
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1052,7 +1052,7 @@ static void cmd_request(struct task *task, struct cmd_args *ca)
  reply:
 	log_debug("cmd_request %d,%d done %d", ca->ci_in, fd, result);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1101,7 +1101,7 @@ static void cmd_examine(struct task *task GNUC_UNUSED, struct cmd_args *ca)
  reply:
 	log_debug("cmd_examine %d,%d done %d", ca->ci_in, fd, count);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1153,7 +1153,7 @@ static void cmd_set_lvb(struct task *task GNUC_UNUSED, struct cmd_args *ca)
 	if (lvb)
 		free(lvb);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1242,7 +1242,7 @@ static void cmd_shutdown_wait(struct task *task GNUC_UNUSED, struct cmd_args *ca
 	if (!result)
 		return;
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1303,7 +1303,7 @@ static void cmd_add_lockspace(struct cmd_args *ca)
 	if (async) {
 		result = rv;
 		log_debug("cmd_add_lockspace %d,%d async done %d", ca->ci_in, fd, result);
-		send_result(fd, &ca->header, result);
+		send_result(ca->ci_in, fd, &ca->header, result);
 		client_resume(ca->ci_in);
 		add_lockspace_wait(sp);
 		return;
@@ -1312,7 +1312,7 @@ static void cmd_add_lockspace(struct cmd_args *ca)
 	result = add_lockspace_wait(sp);
  reply:
 	log_debug("cmd_add_lockspace %d,%d done %d", ca->ci_in, fd, result);
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1352,7 +1352,7 @@ static void cmd_inq_lockspace(struct cmd_args *ca)
  reply:
 	/* log_debug("cmd_inq_lockspace %d,%d done %d", ca->ci_in, fd, result); */
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1437,7 +1437,7 @@ static void cmd_rem_lockspace(struct cmd_args *ca)
 	if (async) {
 		result = rv;
 		log_debug("cmd_rem_lockspace %d,%d async done %d", ca->ci_in, fd, result);
-		send_result(fd, &ca->header, result);
+		send_result(ca->ci_in, fd, &ca->header, result);
 		client_resume(ca->ci_in);
 		rem_lockspace_wait(&lockspace, space_id);
 		return;
@@ -1446,7 +1446,7 @@ static void cmd_rem_lockspace(struct cmd_args *ca)
 	result = rem_lockspace_wait(&lockspace, space_id);
  reply:
 	log_debug("cmd_rem_lockspace %d,%d done %d", ca->ci_in, fd, result);
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1489,7 +1489,7 @@ static void cmd_align(struct task *task GNUC_UNUSED, struct cmd_args *ca)
  reply:
 	log_debug("cmd_align %d,%d done %d", ca->ci_in, fd, result);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1834,7 +1834,7 @@ static void cmd_write_lockspace(struct task *task, struct cmd_args *ca)
  reply:
 	log_debug("cmd_write_lockspace %d,%d done %d", ca->ci_in, fd, result);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1930,7 +1930,7 @@ static void cmd_write_resource(struct task *task, struct cmd_args *ca)
 	if (token)
 		free(token);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -1991,7 +1991,7 @@ static void cmd_killpath(struct task *task, struct cmd_args *ca)
 		return;
 	}
 
-	send_result(cl_fd, &ca->header, result);
+	send_result(ca->ci_in, cl_fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -2021,7 +2021,7 @@ static void cmd_set_event(struct task *task GNUC_UNUSED, struct cmd_args *ca)
 
 	log_debug("cmd_set_event result %d", result);
 reply:
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -2049,7 +2049,7 @@ static void cmd_format_rindex(struct task *task, struct cmd_args *ca)
  reply:
 	log_debug("cmd_format_rindex %d,%d done %d", ca->ci_in, fd, result);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -2077,7 +2077,7 @@ static void cmd_rebuild_rindex(struct task *task, struct cmd_args *ca)
  reply:
 	log_debug("cmd_rebuild_rindex %d,%d done %d", ca->ci_in, fd, result);
 
-	send_result(fd, &ca->header, result);
+	send_result(ca->ci_in, fd, &ca->header, result);
 	client_resume(ca->ci_in);
 }
 
@@ -2256,6 +2256,7 @@ static int print_state_daemon(char *str)
 		 "mlock_level=%d "
 		 "quiet_fail=%d "
 		 "debug_renew=%d "
+		 "debug_clients=%d "
 		 "renewal_history_size=%d "
 		 "gid=%d "
 		 "uid=%d "
@@ -2280,6 +2281,7 @@ static int print_state_daemon(char *str)
 		 com.mlock_level,
 		 com.quiet_fail,
 		 com.debug_renew,
+		 com.debug_clients,
 		 com.renewal_history_size,
 		 com.gid,
 		 com.uid,
@@ -2869,7 +2871,7 @@ static void cmd_restrict(int ci, int fd, struct sm_header *h_recv)
 	client[ci].restricted = h_recv->cmd_flags;
 
 	h_recv->version = SM_PROTO;
-	send_result(fd, h_recv, 0);
+	send_result(ci, fd, h_recv, 0);
 }
 
 static void cmd_version(int ci GNUC_UNUSED, int fd, struct sm_header *h_recv)
diff --git a/src/log.c b/src/log.c
index ed04790..35d0f73 100644
--- a/src/log.c
+++ b/src/log.c
@@ -127,23 +127,40 @@ void log_level(uint32_t space_id, uint32_t res_id, char *name_in, int level, con
 
 	memset(name, 0, sizeof(name));
 
-	if (space_id && !res_id)
-		snprintf(name, NAME_ID_SIZE, "s%u ", space_id);
-	else if (!space_id && res_id)
-		snprintf(name, NAME_ID_SIZE, "r%u ", res_id);
-	else if (space_id && res_id)
-		snprintf(name, NAME_ID_SIZE, "s%u:r%u ", space_id, res_id);
-	else if (name_in)
-		snprintf(name, NAME_ID_SIZE, "%.8s ", name_in);
+	if (level == LOG_CLIENT) {
+		int log_ci = 0, log_fd = 0;
+
+		if (!com.debug_clients)
+			return;
+
+		level = LOG_DEBUG;
+
+		log_ci = space_id;
+		log_fd = res_id;
+
+		if (!name_in)
+			snprintf(name, NAME_ID_SIZE, "cl %d:%d ", log_ci, log_fd);
+		else
+			snprintf(name, NAME_ID_SIZE, "cl %d:%d %.8s ", log_ci, log_fd, name_in);
+	} else {
+		if (space_id && !res_id)
+			snprintf(name, NAME_ID_SIZE, "s%u ", space_id);
+		else if (!space_id && res_id)
+			snprintf(name, NAME_ID_SIZE, "r%u ", res_id);
+		else if (space_id && res_id)
+			snprintf(name, NAME_ID_SIZE, "s%u:r%u ", space_id, res_id);
+		else if (name_in)
+			snprintf(name, NAME_ID_SIZE, "%.8s ", name_in);
+	}
 
 	pthread_mutex_lock(&log_mutex);
 
 	gettimeofday(&cur_time, NULL);
 
-    if (log_logfile_use_utc)
-	    gmtime_r(&cur_time.tv_sec, &time_info);
-    else
-	    localtime_r(&cur_time.tv_sec, &time_info);
+	if (log_logfile_use_utc)
+		gmtime_r(&cur_time.tv_sec, &time_info);
+	else
+		localtime_r(&cur_time.tv_sec, &time_info);
 
 	ret = strftime(log_str + pos, len - pos,
 		       "%Y-%m-%d %H:%M:%S ", &time_info);
diff --git a/src/log.h b/src/log.h
index 5de16ef..de8e3d3 100644
--- a/src/log.h
+++ b/src/log.h
@@ -9,6 +9,8 @@
 #ifndef __LOG_H__
 #define __LOG_H__
 
+#define LOG_CLIENT LOG_LOCAL0
+
 /*
  * Log levels are used mainly to indicate where the message
  * should be recorded:
@@ -49,6 +51,8 @@ void copy_log_dump(char *buf, int *len);
 #define log_taskw(task, fmt, args...)         log_level(0, 0, task->name, LOG_WARNING, fmt, ##args)
 #define log_taskd(task, fmt, args...)         log_level(0, 0, task->name, LOG_DEBUG, fmt, ##args)
 
+#define log_client(ci, fd, fmt, args...)      log_level(ci, fd, NULL, LOG_CLIENT, fmt, ##args)
+
 /* use log_tool for tool actions (non-daemon), and for daemon until
    logging is set up */
 
diff --git a/src/main.c b/src/main.c
index 5ed125b..060ac73 100644
--- a/src/main.c
+++ b/src/main.c
@@ -222,6 +222,11 @@ static void _client_free(int ci)
 {
 	struct client *cl = &client[ci];
 
+	if (cl->cmd_active || cl->pid_dead)
+		log_client(ci, cl->fd, "free cmd %d dead %d", cl->cmd_active, cl->pid_dead);
+	else
+		log_client(ci, cl->fd, "free");
+
 	if (!cl->used) {
 		/* should never happen */
 		log_error("client_free ci %d not used", ci);
@@ -241,6 +246,9 @@ static void _client_free(int ci)
 		goto out;
 	}
 
+	if (cl->need_free)
+		log_debug("client_free ci %d already need_free", ci);
+
 	if (cl->suspend) {
 		log_debug("client_free ci %d is suspended", ci);
 		cl->need_free = 1;
@@ -320,6 +328,8 @@ static int client_suspend(int ci)
 		goto out;
 	}
 
+	log_client(ci, cl->fd, "suspend");
+
 	cl->suspend = 1;
 
 	/* make poll() ignore this connection */
@@ -356,6 +366,8 @@ void client_resume(int ci)
 		goto out;
 	}
 
+	log_client(ci, cl->fd, "resume");
+
 	cl->suspend = 0;
 
 	if (cl->need_free) {
@@ -394,6 +406,8 @@ static int client_add(int fd, void (*workfn)(int ci), void (*deadfn)(int ci))
 			if (i > client_maxi)
 				client_maxi = i;
 			pthread_mutex_unlock(&cl->mutex);
+
+			log_client(i, fd, "add");
 			return i;
 		}
 		pthread_mutex_unlock(&cl->mutex);
@@ -435,15 +449,17 @@ void client_recv_all(int ci, struct sm_header *h_recv, int pos)
 			break;
 	}
 
-	log_debug("recv_all %d,%d,%d pos %d rv %d error %d retries %d rem %d total %d",
+	log_debug("client recv_all %d,%d,%d pos %d rv %d error %d retries %d rem %d total %d",
 		  ci, client[ci].fd, client[ci].pid, pos, rv, error, retries, rem, total);
 }
 
-void send_result(int fd, struct sm_header *h_recv, int result);
-void send_result(int fd, struct sm_header *h_recv, int result)
+void send_result(int ci, int fd, struct sm_header *h_recv, int result);
+void send_result(int ci, int fd, struct sm_header *h_recv, int result)
 {
 	struct sm_header h;
 
+	log_client(ci, fd, "send %d", result);
+
 	memcpy(&h, h_recv, sizeof(struct sm_header));
 	h.version = SM_PROTO;
 	h.length = sizeof(h);
@@ -761,6 +777,7 @@ static int main_loop(void)
 			continue;
 		if (rv < 0) {
 			/* not sure */
+			log_client(0, 0, "poll err %d", rv);
 		}
 		for (i = 0; i <= client_maxi + 1; i++) {
 			/*
@@ -771,6 +788,7 @@ static int main_loop(void)
 			 */
 			if (pollfd[i].fd == efd) {
 				if (pollfd[i].revents & POLLIN) {
+					log_client(i, efd, "efd wake"); /* N.B. i is not a ci */
 					eventfd_read(efd, &ebuf);
 				}
 				continue;
@@ -790,6 +808,7 @@ static int main_loop(void)
 					workfn(i);
 			}
 			if (pollfd[i].revents & (POLLERR | POLLHUP | POLLNVAL)) {
+				log_client(i, client[i].fd, "poll dead");
 				deadfn = client[i].deadfn;
 				if (deadfn)
 					deadfn(i);
@@ -1030,6 +1049,8 @@ static void process_cmd_thread_unregistered(int ci_in, struct sm_header *h_recv)
 
 	snprintf(client[ci_in].owner_name, SANLK_NAME_LEN, "cmd%d", h_recv->cmd);
 
+	log_client(ci_in, client[ci_in].fd, "process cmd %u", h_recv->cmd);
+
 	rv = thread_pool_add_work(ca);
 	if (rv < 0)
 		goto fail_free;
@@ -1041,7 +1062,7 @@ static void process_cmd_thread_unregistered(int ci_in, struct sm_header *h_recv)
 	log_error("cmd %d %d:%d process_unreg error %d",
 		  h_recv->cmd, ci_in, client[ci_in].fd, rv);
 	client_recv_all(ci_in, h_recv, 0);
-	send_result(client[ci_in].fd, h_recv, rv);
+	send_result(ci_in, client[ci_in].fd, h_recv, rv);
 	client_resume(ci_in);
 }
 
@@ -1091,9 +1112,14 @@ static void process_cmd_thread_registered(int ci_in, struct sm_header *h_recv)
 			result = -ESRCH;
 			goto fail;
 		}
+
+		log_client(ci_in, client[ci_in].fd, "process reg cmd %u target pid %d ci %d",
+			   h_recv->cmd, h_recv->data2, ci_target);
 	} else {
 		/* lease for this registered client */
 
+		log_client(ci_in, client[ci_in].fd, "process reg cmd %u", h_recv->cmd);
+
 		ci_target = ci_in;
 		cl = &client[ci_target];
 		pthread_mutex_lock(&cl->mutex);
@@ -1183,8 +1209,9 @@ static void process_cmd_thread_registered(int ci_in, struct sm_header *h_recv)
 	return;
 
  fail:
+	log_error("process_cmd_thread_reg failed ci %d fd %d cmd %u", ci_in, client[ci_in].fd, h_recv->cmd);
 	client_recv_all(ci_in, h_recv, 0);
-	send_result(client[ci_in].fd, h_recv, result);
+	send_result(ci_in, client[ci_in].fd, h_recv, result);
 	client_resume(ci_in);
 
 	if (ca)
@@ -1203,6 +1230,8 @@ static void process_connection(int ci)
 	if (!rv)
 		goto dead;
 
+	log_client(ci, client[ci].fd, "recv %d %d", rv, h.cmd);
+
 	if (rv < 0) {
 		log_error("ci %d fd %d pid %d recv errno %d",
 			  ci, client[ci].fd, client[ci].pid, errno);
@@ -1295,6 +1324,7 @@ static void process_connection(int ci)
 	return;
 
  dead:
+	log_client(ci, client[ci].fd, "recv dead");
 	deadfn = client[ci].deadfn;
 	if (deadfn)
 		deadfn(ci);
@@ -2687,6 +2717,10 @@ static void read_config_file(void)
 			if (strstr(str, "complete"))
 				com.debug_io_complete = 1;
 
+		} else if (!strcmp(str, "debug_clients")) {
+			get_val_int(line, &val);
+			com.debug_clients = val;
+
 		} else if (!strcmp(str, "max_sectors_kb")) {
 			memset(str, 0, sizeof(str));
 			get_val_str(line, str);
diff --git a/src/sanlock.conf b/src/sanlock.conf
index 7deecd2..40e8edd 100644
--- a/src/sanlock.conf
+++ b/src/sanlock.conf
@@ -55,3 +55,6 @@
 #
 # max_sectors_kb = <str>
 # command line: n/a
+#
+# debug_clients = 0
+# command line: n/a
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h
index a78c81f..45d29a9 100644
--- a/src/sanlock_internal.h
+++ b/src/sanlock_internal.h
@@ -334,11 +334,14 @@ EXTERN struct client *client;
 #define DEFAULT_MAX_SECTORS_KB_ALIGN  0     /* set it to align size */
 #define DEFAULT_MAX_SECTORS_KB_NUM    1024  /* set it to num KB for all lockspaces */
 
+#define DEBUG_CMD_INQ_LOCKSPACE 1
+
 struct command_line {
 	int type;				/* COM_ */
 	int action;				/* ACT_ */
 	int debug;
 	int debug_renew;
+	int debug_clients;
 	int debug_io_submit;
 	int debug_io_complete;
 	int paxos_debug_all;