[RFCv2] cld: replace "if (verbose) { act_log }" with CLD_DEBUG

[RFCv2] cld: replace "if (verbose) { act_log }" with CLD_DEBUG

[Colin McCabe]

Move prototypes for common.c functions out of cld_msg.h and into a new header
file, common.h. Create a structure that represents the current log level and
also the function to use for logging.

Create CLD_DEBUG and CLD_LOG macros to print debugging and informational log
messages, respectively. CLD_DEBUG will not evaluate its parameters unless
log->verbose is true. This patch converts over the client code to use these
macros.

Rationale:
1. Some functions in common.c can be called from the server _and_ the client
code. If these functions want to print a debug message, they would currently
need two extra parameters-- the logging function, and the verbose flag.
It's cleaner to condense this into one parameter.

2. The if (verbose) sess->act_log pattern leads to an excessive level of
indentation, which tends to make things more unclear.

version 2: add common.h

Signed-off-by: Colin McCabe <cmccabe@alumni.cmu.edu>
---
 include/cld_msg.h |   10 -----
 include/cldc.h    |    5 +--
 include/common.h  |   27 ++++++++++++++
 lib/cldc.c        |   98 +++++++++++++++++++++-------------------------------
 tools/cldcli.c    |    2 +-
 5 files changed, 70 insertions(+), 72 deletions(-)
 create mode 100644 include/common.h

diff --git a/include/cld_msg.h b/include/cld_msg.h
index 641b857..01837b7 100644
--- a/include/cld_msg.h
+++ b/include/cld_msg.h
@@ -250,14 +250,4 @@ struct cld_msg_event {
 	uint8_t			res[4];
 };
 
-/*
- * function prototypes for lib/common.c;
- * ideally these should not be in cld_msg.h
- */
-
-extern unsigned long long cld_sid2llu(const uint8_t *sid);
-extern void __cld_rand64(void *p);
-extern const char *cld_errstr(enum cle_err_codes ecode);
-extern int cld_readport(const char *fname);
-
 #endif /* __CLD_MSG_H__ */
diff --git a/include/cldc.h b/include/cldc.h
index 9ae6dfe..70062cf 100644
--- a/include/cldc.h
+++ b/include/cldc.h
@@ -5,6 +5,7 @@
 #include <stdbool.h>
 #include <glib.h>
 #include <cld_msg.h>
+#include <common.h>
 
 struct cldc_session;
 
@@ -84,10 +85,8 @@ struct cldc_ops {
 struct cldc_session {
 	uint8_t		sid[CLD_SID_SZ];	/* client id */
 
-	bool		verbose;
-
 	const struct cldc_ops *ops;
-	void		(*act_log)(int prio, const char *fmt, ...);
+	struct		cld_log log;
 	void		*private;
 
 	uint8_t		addr[64];		/* server address */
diff --git a/include/common.h b/include/common.h
new file mode 100644
index 0000000..c98f4ab
--- /dev/null
+++ b/include/common.h
@@ -0,0 +1,27 @@
+#ifndef __CLD_COMMON_H__
+#define __CLD_COMMON_H__
+
+#include <stdint.h>
+#include <glib.h>
+
+unsigned long long cld_sid2llu(const uint8_t *sid);
+void __cld_rand64(void *p);
+const char *cld_errstr(enum cle_err_codes ecode);
+int cld_readport(const char *fname);
+
+/** Print out a debug message if 'verbose' is enabled */
+#define CLD_DEBUG(cld_log, ...) \
+	if ((cld_log).verbose) { \
+		(cld_log).fun(LOG_DEBUG, __VA_ARGS__); \
+	}
+
+/** Print out an informational log message */
+#define CLD_LOG(cld_log, ...) \
+	(cld_log).fun(LOG_INFO, __VA_ARGS__);
+
+struct cld_log {
+	void (*fun)(int prio, const char *fmt, ...);
+	bool verbose;
+};
+
+#endif /* __CLD_COMMON_H__ */
diff --git a/lib/cldc.c b/lib/cldc.c
index 0ab4f19..38bed8f 100644
--- a/lib/cldc.c
+++ b/lib/cldc.c
@@ -111,7 +111,7 @@ static int ack_seqid(struct cldc_session *sess, uint64_t seqid_le)
 	memcpy(resp, &def_msg_ack, sizeof(*resp));
 
 	if (!authsign(sess, pkt, pkt_len)) {
-		sess->act_log(LOG_INFO, "authsign failed 2");
+		CLD_LOG(sess->log, "authsign failed 2");
 		return -1;
 	}
 
@@ -135,12 +135,10 @@ static int cldc_rx_generic(struct cldc_session *sess,
 	while (tmp) {
 		req = tmp->data;
 
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG,
-				      "rx_gen: comparing req->xid (%llu) "
-				      "with resp->xid_in (%llu)",
-				(unsigned long long) le64_to_cpu(req->xid),
-			        (unsigned long long) le64_to_cpu(resp->xid_in));
+		CLD_DEBUG(sess->log, "rx_gen: comparing req->xid (%llu) "
+			"with resp->xid_in (%llu)",
+			(unsigned long long) le64_to_cpu(req->xid),
+			(unsigned long long) le64_to_cpu(resp->xid_in));
 
 		if (req->xid == resp->xid_in)
 			break;
@@ -150,12 +148,9 @@ static int cldc_rx_generic(struct cldc_session *sess,
 		return -1005;
 
 	if (req->done) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "rx_gen: re-acking");
+		CLD_DEBUG(sess->log, "rx_gen: re-acking");
 	} else {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG,
-				      "rx_gen: issuing completion, acking");
+		CLD_DEBUG(sess->log, "rx_gen: issuing completion, acking");
 
 		req->done = true;
 
@@ -181,9 +176,8 @@ static int cldc_rx_ack_frag(struct cldc_session *sess,
 	if (buflen < sizeof(*ack_msg))
 		return -1008;
 
-	if (sess->verbose)
-		sess->act_log(LOG_DEBUG, "ack-frag: seqid %llu, want to ack",
-			      ack_msg->seqid);
+	CLD_DEBUG(sess->log, "ack-frag: seqid %llu, want to ack",
+			ack_msg->seqid);
 
 	tmp = sess->out_msg;
 	while (tmp) {
@@ -201,10 +195,8 @@ static int cldc_rx_ack_frag(struct cldc_session *sess,
 			if (pi->pkt.seqid != ack_msg->seqid)
 				continue;
 
-			if (sess->verbose)
-				sess->act_log(LOG_DEBUG,
-					      "ack-frag: seqid %llu, expiring",
-					      ack_msg->seqid);
+			CLD_DEBUG(sess->log, "ack-frag: seqid %llu, expiring",
+				ack_msg->seqid);
 
 			req->pkt_info[i] = NULL;
 			free(pi);
@@ -248,7 +240,7 @@ static int cldc_rx_not_master(struct cldc_session *sess,
 			      const void *msgbuf,
 			      size_t buflen)
 {
-	sess->act_log(LOG_INFO, "FIXME: not-master message received");
+	CLD_DEBUG(sess->log, "FIXME: not-master message received");
 	return -1055;	/* FIXME */
 }
 
@@ -315,8 +307,8 @@ static bool authcheck(struct cldc_session *sess, const struct cld_packet *pkt,
 	     md, &md_len);
 
 	if (md_len != SHA_DIGEST_LENGTH)
-		sess->act_log(LOG_INFO,
-			      "authsign BUG: md_len != SHA_DIGEST_LENGTH");
+		CLD_LOG(sess->log,
+			"authsign BUG: md_len != SHA_DIGEST_LENGTH");
 
 	if (memcmp(buf + buflen - SHA_DIGEST_LENGTH, md, SHA_DIGEST_LENGTH))
 		return false;
@@ -340,8 +332,8 @@ static bool authsign(struct cldc_session *sess, struct cld_packet *pkt,
 	     md, &md_len);
 
 	if (md_len != SHA_DIGEST_LENGTH)
-		sess->act_log(LOG_INFO,
-			      "authsign BUG: md_len != SHA_DIGEST_LENGTH");
+		CLD_LOG(sess->log,
+			"authsign BUG: md_len != SHA_DIGEST_LENGTH");
 
 	memcpy(buf + (buflen - SHA_DIGEST_LENGTH), md, SHA_DIGEST_LENGTH);
 
@@ -380,8 +372,7 @@ static int cldc_receive_msg(struct cldc_session *sess,
 	size_t msglen = sess->msg_buf_len;
 
 	if (memcmp(msg->magic, CLD_MSG_MAGIC, sizeof(msg->magic))) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: bad msg magic");
+		CLD_DEBUG(sess->log, "receive_pkt: bad msg magic");
 		return -EPROTO;
 	}
 
@@ -433,8 +424,7 @@ int cldc_receive_pkt(struct cldc_session *sess,
 	current_time = tv.tv_sec;
 
 	if (pkt_len < (sizeof(*pkt) + SHA_DIGEST_LENGTH)) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: msg too short");
+		CLD_DEBUG(sess->log, "receive_pkt: msg too short");
 		return -EPROTO;
 	}
 
@@ -448,11 +438,11 @@ int cldc_receive_pkt(struct cldc_session *sess,
 	no_seqid = first_frag && ((msg->op == cmo_not_master) ||
 				  (msg->op == cmo_ack_frag));
 
-	if (sess->verbose) {
+	if (sess->log.verbose) {
 		if (have_get) {
 			struct cld_msg_get_resp *dp;
 			dp = (struct cld_msg_get_resp *) msg;
-			sess->act_log(LOG_DEBUG, "receive_pkt(len %u, op %s"
+			CLD_DEBUG(sess->log, "receive_pkt(len %u, op %s"
 				      ", seqid %llu, user %s, size %u)",
 				(unsigned int) pkt_len,
 				opstr(msg->op),
@@ -462,7 +452,7 @@ int cldc_receive_pkt(struct cldc_session *sess,
 		} else if (have_new_sess) {
 			struct cld_msg_resp *dp;
 			dp = (struct cld_msg_resp *) msg;
-			sess->act_log(LOG_DEBUG, "receive_pkt(len %u, op %s"
+			CLD_DEBUG(sess->log, "receive_pkt(len %u, op %s"
 				      ", seqid %llu, user %s, xid_in %llu)",
 				(unsigned int) pkt_len,
 				opstr(msg->op),
@@ -470,8 +460,8 @@ int cldc_receive_pkt(struct cldc_session *sess,
 				pkt->user,
 				(unsigned long long) le64_to_cpu(dp->xid_in));
 		} else {
-			sess->act_log(LOG_DEBUG, "receive_pkt(len %u, "
-				      "flags %s%s, op %s, seqid %llu, user %s)",
+			CLD_DEBUG(sess->log, "receive_pkt(len %u, "
+				"flags %s%s, op %s, seqid %llu, user %s)",
 				(unsigned int) pkt_len,
 				first_frag ? "F" : "",
 				last_frag ? "L" : "",
@@ -482,24 +472,20 @@ int cldc_receive_pkt(struct cldc_session *sess,
 	}
 
 	if (memcmp(pkt->magic, CLD_PKT_MAGIC, sizeof(pkt->magic))) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: bad pkt magic");
+		CLD_DEBUG(sess->log, "receive_pkt: bad pkt magic");
 		return -EPROTO;
 	}
 
 	/* check HMAC signature */
 	if (!authcheck(sess, pkt, pkt_len)) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: invalid auth");
+		CLD_DEBUG(sess->log, "receive_pkt: invalid auth");
 		return -EACCES;
 	}
 
 	/* verify stored server addr matches pkt addr */
 	if (((sess->addr_len != net_addrlen) ||
 	    memcmp(sess->addr, net_addr, net_addrlen))) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG,
-				      "receive_pkt: server address mismatch");
+		CLD_DEBUG(sess->log, "receive_pkt: server address mismatch");
 		return -EBADE;
 	}
 
@@ -511,8 +497,7 @@ int cldc_receive_pkt(struct cldc_session *sess,
 		sess->msg_buf_len = 0;
 
 	if ((sess->msg_buf_len + msglen) > CLD_MAX_MSG_SZ) {
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: bad pkt length");
+		CLD_DEBUG(sess->log, "receive_pkt: bad pkt length");
 		return -EPROTO;
 	}
 
@@ -526,8 +511,7 @@ int cldc_receive_pkt(struct cldc_session *sess,
 		sess->next_seqid_in_tr =
 			sess->next_seqid_in - CLDC_MSG_REMEMBER;
 
-		if (sess->verbose)
-			sess->act_log(LOG_DEBUG, "receive_pkt: "
+		CLD_DEBUG(sess->log, "receive_pkt: "
 				      "setting next_seqid_in to %llu",
 				      (unsigned long long) seqid);
 	} else if (!no_seqid) {
@@ -537,9 +521,7 @@ int cldc_receive_pkt(struct cldc_session *sess,
 					   sess->next_seqid_in))
 				return ack_seqid(sess, pkt->seqid);
 
-			if (sess->verbose)
-				sess->act_log(LOG_DEBUG,
-					      "receive_pkt: bad seqid %llu",
+			CLD_DEBUG(sess->log, "receive_pkt: bad seqid %llu",
 					      (unsigned long long) seqid);
 			return -EBADSLT;
 		}
@@ -664,7 +646,7 @@ static void sess_expire(struct cldc_session *sess)
 static int sess_send_pkt(struct cldc_session *sess,
 			 const struct cld_packet *pkt, size_t pkt_len)
 {
-	if (sess->verbose) {
+	if (sess->log.verbose) {
 		uint32_t flags = le32_to_cpu(pkt->flags);
 		bool first = (flags & CPF_FIRST);
 		bool last = (flags & CPF_LAST);
@@ -677,14 +659,14 @@ static int sess_send_pkt(struct cldc_session *sess,
 			op = hdr->op;
 		}
 
-		sess->act_log(LOG_DEBUG,
-			      "send_pkt(len %zu, flags %s%s, "
-			      "op %s, seqid %llu)",
-			      pkt_len,
-			      first ? "F" : "",
-			      last ? "L" : "",
-			      first ? opstr(op) : "n/a",
-			      le64_to_cpu(pkt->seqid));
+		CLD_DEBUG(sess->log,
+			"send_pkt(len %zu, flags %s%s, "
+			"op %s, seqid %llu)",
+			pkt_len,
+			first ? "F" : "",
+			last ? "L" : "",
+			first ? opstr(op) : "n/a",
+			le64_to_cpu(pkt->seqid));
 	}
 
 	return sess->ops->pkt_send(sess->private,
@@ -876,12 +858,12 @@ int cldc_new_sess(const struct cldc_ops *ops,
 		return -ENOMEM;
 
 #if 0
-	sess->verbose = true;
+	sess->log.verbose = true;
 #endif
 
 	sess->private = private;
 	sess->ops = ops;
-	sess->act_log = ops->errlog ? ops->errlog : cldc_errlog;
+	sess->log.fun = ops->errlog ? ops->errlog : cldc_errlog;
 	sess->fh = g_array_sized_new(FALSE, TRUE, sizeof(struct cldc_fh), 16);
 	strcpy(sess->user, user);
 	strcpy(sess->secret_key, secret_key);
diff --git a/tools/cldcli.c b/tools/cldcli.c
index 60ab301..23cba99 100644
--- a/tools/cldcli.c
+++ b/tools/cldcli.c
@@ -823,7 +823,7 @@ static gpointer cld_thread(gpointer dummy)
 		return NULL;
 	}
 
-	thr_udp->sess->verbose = cldcli_verbose;
+	thr_udp->sess->log.verbose = cldcli_verbose;
 
 	pfd[0].fd = thr_udp->fd;
 	pfd[0].events = POLLIN;
-- 
1.6.2.5

Re: [RFCv2] cld: replace "if (verbose) { act_log }" with CLD_DEBUG

[Pete Zaitcev]

On Sun,  6 Dec 2009 07:41:05 -0800
Colin McCabe <cmccabe@alumni.cmu.edu> wrote:

> Move prototypes for common.c functions out of cld_msg.h and into a new header
> file, common.h. Create a structure that represents the current log level and
> also the function to use for logging.

>  static int sess_send_pkt(struct cldc_session *sess,
>  			 const struct cld_packet *pkt, size_t pkt_len)
>  {
> -	if (sess->verbose) {
> +	if (sess->log.verbose) {
>  		uint32_t flags = le32_to_cpu(pkt->flags);
>  		bool first = (flags & CPF_FIRST);
>  		bool last = (flags & CPF_LAST);

I'm wondering if we can drop these ifs now, at the cost of some
small inefficiency.

-- Pete

Re: [RFCv2] cld: replace "if (verbose) { act_log }" with CLD_DEBUG

[Jeff Garzik]

On 12/06/2009 07:23 PM, Pete Zaitcev wrote:
> On Sun,  6 Dec 2009 07:41:05 -0800
> Colin McCabe<cmccabe@alumni.cmu.edu>  wrote:
>
>> Move prototypes for common.c functions out of cld_msg.h and into a new header
>> file, common.h. Create a structure that represents the current log level and
>> also the function to use for logging.
>
>>   static int sess_send_pkt(struct cldc_session *sess,
>>   			 const struct cld_packet *pkt, size_t pkt_len)
>>   {
>> -	if (sess->verbose) {
>> +	if (sess->log.verbose) {
>>   		uint32_t flags = le32_to_cpu(pkt->flags);
>>   		bool first = (flags&  CPF_FIRST);
>>   		bool last = (flags&  CPF_LAST);
>
> I'm wondering if we can drop these ifs now, at the cost of some
> small inefficiency.

I would rather keep the if's.  The verbose logging is unlikely to be 
used in production.  Therefore, the common case would be to execute 
unnecessary code for each packet.

	Jeff

Re: [RFCv2] cld: replace "if (verbose) { act_log }" with CLD_DEBUG

[Jeff Garzik]

On 12/06/2009 10:41 AM, Colin McCabe wrote:
> Move prototypes for common.c functions out of cld_msg.h and into a new header
> file, common.h. Create a structure that represents the current log level and
> also the function to use for logging.
>
> Create CLD_DEBUG and CLD_LOG macros to print debugging and informational log
> messages, respectively. CLD_DEBUG will not evaluate its parameters unless
> log->verbose is true. This patch converts over the client code to use these
> macros.
>
> Rationale:
> 1. Some functions in common.c can be called from the server _and_ the client
> code. If these functions want to print a debug message, they would currently
> need two extra parameters-- the logging function, and the verbose flag.
> It's cleaner to condense this into one parameter.
>
> 2. The if (verbose) sess->act_log pattern leads to an excessive level of
> indentation, which tends to make things more unclear.
>
> version 2: add common.h
>
> Signed-off-by: Colin McCabe<cmccabe@alumni.cmu.edu>
> ---
>   include/cld_msg.h |   10 -----
>   include/cldc.h    |    5 +--
>   include/common.h  |   27 ++++++++++++++
>   lib/cldc.c        |   98 +++++++++++++++++++++-------------------------------
>   tools/cldcli.c    |    2 +-
>   5 files changed, 70 insertions(+), 72 deletions(-)
>   create mode 100644 include/common.h
>
> diff --git a/include/cld_msg.h b/include/cld_msg.h
> index 641b857..01837b7 100644
> --- a/include/cld_msg.h
> +++ b/include/cld_msg.h
> @@ -250,14 +250,4 @@ struct cld_msg_event {
>   	uint8_t			res[4];
>   };
>
> -/*
> - * function prototypes for lib/common.c;
> - * ideally these should not be in cld_msg.h
> - */
> -
> -extern unsigned long long cld_sid2llu(const uint8_t *sid);
> -extern void __cld_rand64(void *p);
> -extern const char *cld_errstr(enum cle_err_codes ecode);
> -extern int cld_readport(const char *fname);
> -
>   #endif /* __CLD_MSG_H__ */
> diff --git a/include/cldc.h b/include/cldc.h
> index 9ae6dfe..70062cf 100644
> --- a/include/cldc.h
> +++ b/include/cldc.h
> @@ -5,6 +5,7 @@
>   #include<stdbool.h>
>   #include<glib.h>
>   #include<cld_msg.h>
> +#include<common.h>
>
>   struct cldc_session;
>
> @@ -84,10 +85,8 @@ struct cldc_ops {
>   struct cldc_session {
>   	uint8_t		sid[CLD_SID_SZ];	/* client id */
>
> -	bool		verbose;
> -
>   	const struct cldc_ops *ops;
> -	void		(*act_log)(int prio, const char *fmt, ...);
> +	struct		cld_log log;
>   	void		*private;
>
>   	uint8_t		addr[64];		/* server address */
> diff --git a/include/common.h b/include/common.h
> new file mode 100644
> index 0000000..c98f4ab
> --- /dev/null
> +++ b/include/common.h
> @@ -0,0 +1,27 @@
> +#ifndef __CLD_COMMON_H__
> +#define __CLD_COMMON_H__
> +
> +#include<stdint.h>
> +#include<glib.h>
> +
> +unsigned long long cld_sid2llu(const uint8_t *sid);
> +void __cld_rand64(void *p);
> +const char *cld_errstr(enum cle_err_codes ecode);
> +int cld_readport(const char *fname);
> +
> +/** Print out a debug message if 'verbose' is enabled */
> +#define CLD_DEBUG(cld_log, ...) \
> +	if ((cld_log).verbose) { \
> +		(cld_log).fun(LOG_DEBUG, __VA_ARGS__); \
> +	}
> +
> +/** Print out an informational log message */
> +#define CLD_LOG(cld_log, ...) \
> +	(cld_log).fun(LOG_INFO, __VA_ARGS__);
> +
> +struct cld_log {
> +	void (*fun)(int prio, const char *fmt, ...);
> +	bool verbose;

No major objections.  I would rather call the hook 'cb' or 'func' or 
something other than 'fun', even though I do consider Project Hail fun :)

And thinking long-term, the ideal target is giving the admin the ability 
to selectively enable or disable various classes of logging messages. 
In a very rudimentary form, this means a "log_level" variable where 
increasing values imply increasing verbosity.  In a more refined form, a 
la ISC's BIND server, the admin may mask log classes A, B, C, G, H and I 
into /var/log/foobar, and mask log classes B, C, D, E anf F into 
/var/log/bazbang.

What does that mean for your patch?  Probably nothing :)  But maybe we 
might want 'verbose' to be an unsigned integer log_level or log_mask.

But that's optional... this email is more for future readers than 
present programmers, I think.

	Jeff