[PATCH 1/4] flow: Regularise flow specific logging helpers

[David Gibson <david@gibson.dropbear.id.au>]

flow.h has a collection of logging helpers that automatically include
information about a specific flow.  Which variants are present are a bit
ad-hoc, based on what we happened to want use (e.g. there are no
LOG_WARNING level versions, at present).  There's also a rather awkward
and only occasionally used flow_log_details_() helper to print additional
log messages with more details of the flow (basically its addresses).
It's particularly awkward to try to combine that with ratelimiting.

Re-organise this to be based around a flow_log__() internal helper, which
has bool parameters to include strerror() / perror information and/or
the extra details.  Add wrapper macros for all combinations of perror,
ratelimiting and DEBUG/WARNING/ERR priorities.

Be a little more consistent about parameter order between the various
functions / macros / wrappers while we're at it.

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
 flow.c | 89 ++++++++++++++++++++++++++++------------------------------
 flow.h | 70 +++++++++++++++++++++++----------------------
 tcp.c  |  4 +--
 udp.c  |  6 ++--
 4 files changed, 85 insertions(+), 84 deletions(-)

diff --git a/flow.c b/flow.c
index 565ed2b2..6cf3905a 100644
--- a/flow.c
+++ b/flow.c
@@ -270,17 +270,20 @@ int flowside_connect(const struct ctx *c, int s,
 	return connect(s, &sa.sa, socklen_inany(&sa));
 }
 
-/** flow_log_ - Log flow-related message
+/** flow_log__ - Log flow-related message, internal helper
  * @f:		flow the message is related to
- * @newline:	Append newline at the end of the message, if missing
  * @pri:	Log priority
+ * @perror:	Append strerror(errno) output
+ * @details:	Add lines with flow addresses
+ * @state:	State to display details for (used during state changes)
  * @fmt:	Format string
  * @...:	printf-arguments
  */
-void flow_log_(const struct flow_common *f, bool newline, int pri,
-	       const char *fmt, ...)
+void flow_log__(const struct flow_common *f, int pri, bool perror, bool details,
+		enum flow_state state, const char *fmt, ...)
 {
 	const char *type_or_state;
+	int errno_ = errno;
 	char msg[BUFSIZ];
 	va_list args;
 
@@ -294,45 +297,41 @@ void flow_log_(const struct flow_common *f, bool newline, int pri,
 	else
 		type_or_state = FLOW_TYPE(f);
 
-	logmsg(newline, false, pri,
+	logmsg(!perror, false, pri,
 	       "Flow %u (%s): %s", flow_idx(f), type_or_state, msg);
-}
 
-/** flow_log_details_() - Log the details of a flow
- * @f:		flow to log
- * @pri:	Log priority
- * @state:	State to log details according to
- *
- * Logs the details of the flow: endpoints, interfaces, type etc.
- */
-void flow_log_details_(const struct flow_common *f, int pri,
-		       enum flow_state state)
-{
-	char estr0[INANY_ADDRSTRLEN], fstr0[INANY_ADDRSTRLEN];
-	char estr1[INANY_ADDRSTRLEN], fstr1[INANY_ADDRSTRLEN];
-	const struct flowside *ini = &f->side[INISIDE];
-	const struct flowside *tgt = &f->side[TGTSIDE];
-
-	if (state >= FLOW_STATE_TGT)
-		flow_log_(f, true, pri,
-			  "%s [%s]:%hu -> [%s]:%hu => %s [%s]:%hu -> [%s]:%hu",
-			  pif_name(f->pif[INISIDE]),
-			  inany_ntop(&ini->eaddr, estr0, sizeof(estr0)),
-			  ini->eport,
-			  inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)),
-			  ini->oport,
-			  pif_name(f->pif[TGTSIDE]),
-			  inany_ntop(&tgt->oaddr, fstr1, sizeof(fstr1)),
-			  tgt->oport,
-			  inany_ntop(&tgt->eaddr, estr1, sizeof(estr1)),
-			  tgt->eport);
-	else if (state >= FLOW_STATE_INI)
-		flow_log_(f, true, pri, "%s [%s]:%hu -> [%s]:%hu => ?",
-			  pif_name(f->pif[INISIDE]),
-			  inany_ntop(&ini->eaddr, estr0, sizeof(estr0)),
-			  ini->eport,
-			  inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)),
-			  ini->oport);
+	if (perror)
+		logmsg(true, true, pri, ": %s", strerror_(errno_));
+
+	if (details) {
+		char estr0[INANY_ADDRSTRLEN], fstr0[INANY_ADDRSTRLEN];
+		char estr1[INANY_ADDRSTRLEN], fstr1[INANY_ADDRSTRLEN];
+		const struct flowside *ini = &f->side[INISIDE];
+		const struct flowside *tgt = &f->side[TGTSIDE];
+
+		if (state >= FLOW_STATE_TGT) {
+			flow_log__(f, pri, false, false, state,
+"%s [%s]:%hu -> [%s]:%hu => %s [%s]:%hu -> [%s]:%hu",
+				  pif_name(f->pif[INISIDE]),
+				  inany_ntop(&ini->eaddr, estr0, sizeof(estr0)),
+				  ini->eport,
+				  inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)),
+				  ini->oport,
+				  pif_name(f->pif[TGTSIDE]),
+				  inany_ntop(&tgt->oaddr, fstr1, sizeof(fstr1)),
+				  tgt->oport,
+				  inany_ntop(&tgt->eaddr, estr1, sizeof(estr1)),
+				  tgt->eport);
+		} else if (state >= FLOW_STATE_INI) {
+			flow_log__(f, pri, false, false, state,
+				  "%s [%s]:%hu -> [%s]:%hu => ?",
+				  pif_name(f->pif[INISIDE]),
+				  inany_ntop(&ini->eaddr, estr0, sizeof(estr0)),
+				  ini->eport,
+				  inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)),
+				  ini->oport);
+		}
+	}
 }
 
 /**
@@ -348,10 +347,9 @@ static void flow_set_state(struct flow_common *f, enum flow_state state)
 	assert(oldstate < FLOW_NUM_STATES);
 
 	f->state = state;
-	flow_log_(f, true, LOG_DEBUG, "%s -> %s", flow_state_str[oldstate],
+	flow_log__(f, LOG_DEBUG, false, true, MAX(state, oldstate),
+		   "%s -> %s", flow_state_str[oldstate],
 		  FLOW_STATE(f));
-
-	flow_log_details_(f, LOG_DEBUG, MAX(state, oldstate));
 }
 
 /**
@@ -552,8 +550,7 @@ norule:
 	/* This shouldn't happen, because if there's no rule for it we should
 	 * have no listening socket that would let us get here
 	 */
-	flow_dbg(flow, "Missing forward rule");
-	flow_log_details_(f, LOG_DEBUG, f->state);
+	flow_log(flow, LOG_DEBUG, false, true, "Missing forward rule");
 
 nofwd:
 	flow_err(flow, "No rules to forward %s %s [%s]:%hu -> [%s]:%hu",
diff --git a/flow.h b/flow.h
index 6c6a9260..d168a35a 100644
--- a/flow.h
+++ b/flow.h
@@ -280,42 +280,46 @@ int flow_migrate_source(struct ctx *c, const struct migrate_stage *stage,
 int flow_migrate_target(struct ctx *c, const struct migrate_stage *stage,
 			int fd);
 
-void flow_log_(const struct flow_common *f, bool newline, int pri,
-	       const char *fmt, ...)
-	__attribute__((format(printf, 4, 5)));
-
-#define flow_log(f_, pri, ...)	flow_log_(&(f_)->f, true, (pri), __VA_ARGS__)
-#define flow_dbg(f, ...)	flow_log((f), LOG_DEBUG, __VA_ARGS__)
-#define flow_err(f, ...)	flow_log((f), LOG_ERR, __VA_ARGS__)
-
-#define flow_trace(f, ...)						\
+void flow_log__(const struct flow_common *f, int pri, bool perror, bool details,
+		enum flow_state state, const char *fmt, ...);
+
+#define flow_log_(f_, pri_, perror_, details_, ...)			\
+	flow_log__((f_), (pri_), (perror_), (details_), (f_)->state,	\
+		   __VA_ARGS__)
+
+#define flow_log(flow_, pri_, perror_, details_, ...)			\
+	flow_log_(&(flow_)->f, (pri_), (perror_), (details_), __VA_ARGS__)
+
+#define flow_dbg(flow_, ...)						\
+	flow_log((flow_), LOG_DEBUG, false, false, __VA_ARGS__)
+#define flow_warn(flow_, ...)						\
+	flow_log((flow_), LOG_WARNING, false, false, __VA_ARGS__)
+#define flow_err(flow_, ...)						\
+	flow_log((flow_), LOG_ERR, false, false, __VA_ARGS__)
+#define flow_trace(flow_, ...)						\
 	do {								\
 		if (log_trace)						\
-			flow_dbg((f), __VA_ARGS__);			\
-	} while (0)
-
-#define flow_log_perror_(f, pri, ...)					\
-	do {								\
-		int errno_ = errno;					\
-		flow_log_((f), false, (pri), __VA_ARGS__);		\
-		logmsg(true, true, (pri), ": %s", strerror_(errno_));	\
+			flow_dbg((flow_), __VA_ARGS__);			\
 	} while (0)
 
-#define flow_dbg_perror(f_, ...) flow_log_perror_(&(f_)->f, LOG_DEBUG, __VA_ARGS__)
-#define flow_perror(f_, ...)	flow_log_perror_(&(f_)->f, LOG_ERR, __VA_ARGS__)
-
-void flow_log_details_(const struct flow_common *f, int pri,
-		       enum flow_state state);
-#define flow_log_details(f_, pri) \
-	flow_log_details_(&((f_)->f), (pri), (f_)->f.state)
-#define flow_dbg_details(f_)	flow_log_details((f_), LOG_DEBUG)
-#define flow_err_details(f_)	flow_log_details((f_), LOG_ERR)
-
-#define flow_dbg_ratelimit(f, now, ...)					\
-	logmsg_ratelimit(flow_dbg, debug, now, f, __VA_ARGS__)
-#define flow_err_ratelimit(f, now, ...)					\
-	logmsg_ratelimit(flow_err, err, now, f, __VA_ARGS__)
-#define flow_perror_ratelimit(f, now, ...)				\
-	logmsg_ratelimit(flow_perror, err, now, f, __VA_ARGS__)
+#define flow_dbg_perror(flow_, ...) \
+	flow_log((flow_), LOG_DEBUG, true, false, __VA_ARGS__)
+#define flow_warn_perror(flow_, ...) \
+	flow_log((flow_), LOG_WARNING, true, false, __VA_ARGS__)
+#define flow_perror(flow_, ...) \
+	flow_log((flow_), LOG_ERR, true, false, __VA_ARGS__)
+
+#define flow_dbg_ratelimit(flow_, now_, ...)				\
+	logmsg_ratelimit(flow_dbg, debug, (now_), (flow_), __VA_ARGS__)
+#define flow_dbg_perror_ratelimit(flow_, now_, ...)			\
+	logmsg_ratelimit(flow_dbg_perror, debug, (now_), (flow_), __VA_ARGS__)
+#define flow_warn_ratelimit(flow_, now_, ...)				\
+	logmsg_ratelimit(flow_warn, warn, (now_), (flow_), __VA_ARGS__)
+#define flow_warn_perror_ratelimit(flow_, now_, ...)			\
+	logmsg_ratelimit(flow_warn_perror, warn, (now_), (flow_), __VA_ARGS__)
+#define flow_err_ratelimit(flow_, now_, ...)				\
+	logmsg_ratelimit(flow_err, err, (now_), (flow_), __VA_ARGS__)
+#define flow_perror_ratelimit(flow_, now_, ...)				\
+	logmsg_ratelimit(flow_perror, err, (now_), (flow_), __VA_ARGS__)
 
 #endif /* FLOW_H */
diff --git a/tcp.c b/tcp.c
index c4000754..6fba865f 100644
--- a/tcp.c
+++ b/tcp.c
@@ -1404,8 +1404,8 @@ void tcp_linger0_(const struct flow_common *f, int s)
 	 */
 	if (setsockopt(s, SOL_SOCKET, SO_LINGER,
 		       &linger0, sizeof(linger0)) < 0) {
-		flow_log_perror_(f, LOG_DEBUG,
-				 "SO_LINGER failed, may not send RST to peer");
+		flow_log_(f, LOG_DEBUG, true, false,
+			  "SO_LINGER failed, may not send RST to peer");
 	}
 }
 
diff --git a/udp.c b/udp.c
index c28d6ee2..f29ca3da 100644
--- a/udp.c
+++ b/udp.c
@@ -943,7 +943,8 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref,
 
 	if (events & EPOLLERR) {
 		if (udp_sock_errs(c, ref.fd, ref.flowside, PIF_NONE, 0) < 0) {
-			flow_err(uflow, "Unrecoverable error on flow socket");
+			flow_log(uflow, LOG_ERR, false, true,
+				 "Unrecoverable error on flow socket");
 			goto fail;
 		}
 	}
@@ -974,7 +975,7 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref,
 				udp_buf_sock_to_tap(c, s, n, tosidx);
 			}
 		} else {
-			flow_err(uflow,
+			flow_log(uflow, LOG_ERR, false, true,
 				 "No support for forwarding UDP from %s to %s",
 				 pif_name(pif_at_sidx(ref.flowside)),
 				 pif_name(topif));
@@ -984,7 +985,6 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref,
 	return;
 
 fail:
-	flow_err_details(uflow);
 	udp_flow_close(c, uflow);
 }
 
-- 
2.54.0