[prev in list] [next in list] [prev in thread] [next in thread]
List: sanlock-devel
Subject: [sanlock] 04/06: sanlock: client debug logging
From: pagure () pagure ! io
Date: 2020-03-10 17:57:51
Message-ID: 20200310175747.5875924388CB () pagure01 ! fedoraproject ! org
[Download RAW message or body]
This is an automated email from the git hooks/post-receive script.
teigland pushed a commit to branch master
in repository sanlock.
commit f9b09264a4857afc5b10db8b0f157676848de926
Author: David Teigland <teigland@redhat.com>
AuthorDate: Mon Mar 9 15:56:05 2020 -0500
sanlock: client debug logging
New debug logging for client connections, enabled with
debug_clients=1 in sanlock.conf.
---
src/cmd.c | 44 +++++++++++++++++++++++---------------------
src/log.c | 41 +++++++++++++++++++++++++++++------------
src/log.h | 4 ++++
src/main.c | 44 +++++++++++++++++++++++++++++++++++++++-----
src/sanlock.conf | 3 +++
src/sanlock_internal.h | 3 +++
6 files changed, 101 insertions(+), 38 deletions(-)
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;
--
To stop receiving notification emails like this one, please contact
the administrator of this repository.
_______________________________________________
sanlock-devel mailing list -- sanlock-devel@lists.fedorahosted.org
To unsubscribe send an email to sanlock-devel-leave@lists.fedorahosted.org
Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedorahosted.org/archives/list/sanlock-devel@lists.fedorahosted.org
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic