From 45cac95331fe32ec5acb1cc6946b8279c8fc5257 Mon Sep 17 00:00:00 2001
From: Rusty Russell <rusty@rustcorp.com.au>
Date: Fri, 1 Jul 2016 11:19:28 +0930
Subject: [PATCH] log: logging for HTLCs.

The most complex thing we've logged yet, so we extract the core of the
log_struct_ function to call it multiple times.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
---
 daemon/log.c | 90 +++++++++++++++++++++++++++++++++++++---------------
 daemon/log.h |  1 +
 2 files changed, 65 insertions(+), 26 deletions(-)

diff --git a/daemon/log.c b/daemon/log.c
index b7da4c6ff..93b1a3dcf 100644
--- a/daemon/log.c
+++ b/daemon/log.c
@@ -2,7 +2,10 @@
 #include "bitcoin/pubkey.h"
 #include "bitcoin/tx.h"
 #include "controlled_time.h"
+#include "htlc.h"
 #include "log.h"
+#include "peer.h"
+#include "protobuf_convert.h"
 #include "pseudorand.h"
 #include "utils.h"
 #include <ccan/array_size/array_size.h>
@@ -14,6 +17,7 @@
 #include <ccan/time/time.h>
 #include <errno.h>
 #include <fcntl.h>
+#include <inttypes.h>
 #include <signal.h>
 #include <stdio.h>
 #include <sys/stat.h>
@@ -267,10 +271,67 @@ void log_add(struct log *log, const char *fmt, ...)
 	va_end(ap);
 }
 
+#define to_string(ctx, structtype, ptr)				\
+	to_string_((ctx), stringify(structtype),			\
+		   ((void)sizeof((ptr) == (structtype *)NULL),		\
+		    ((union loggable_structs)((const structtype *)ptr))))
+
+static char *to_string_(const tal_t *ctx,
+			const char *structname,
+			union loggable_structs u)
+{
+	char *s = NULL;
+
+	/* GCC checks we're one of these, so we should be. */
+	if (streq(structname, "struct pubkey"))
+		s = tal_hexstr(ctx, u.pubkey->der, sizeof(u.pubkey->der));
+	else if (streq(structname, "struct sha256_double"))
+		s = tal_hexstr(ctx, u.sha256_double, sizeof(*u.sha256_double));
+	else if (streq(structname, "struct sha256"))
+		s = tal_hexstr(ctx, u.sha256, sizeof(*u.sha256));
+	else if (streq(structname, "struct rel_locktime")) {
+		if (rel_locktime_is_seconds(u.rel_locktime))
+			s = tal_fmt(ctx, "+%usec",
+				    rel_locktime_to_seconds(u.rel_locktime));
+		else
+			s = tal_fmt(ctx, "+%ublocks",
+				    rel_locktime_to_blocks(u.rel_locktime));
+	} else if (streq(structname, "struct abs_locktime")) {
+		if (abs_locktime_is_seconds(u.abs_locktime))
+			s = tal_fmt(ctx, "%usec",
+				    abs_locktime_to_seconds(u.abs_locktime));
+		else
+			s = tal_fmt(ctx, "%ublocks",
+				    abs_locktime_to_blocks(u.abs_locktime));
+	} else if (streq(structname, "struct bitcoin_tx")) {
+		u8 *lin = linearize_tx(ctx, u.bitcoin_tx);
+		s = tal_hexstr(ctx, lin, tal_count(lin));
+	} else if (streq(structname, "struct htlc")) {
+		const struct htlc *h = u.htlc;
+		s = tal_fmt(ctx, "{ id=%"PRIu64
+			    " msatoshis=%"PRIu64
+			    " expiry=%s"
+			    " rhash=%s"
+			    " rval=%s"
+			    " src=%s }",
+			    h->id, h->msatoshis,
+			    to_string(ctx, struct abs_locktime, &h->expiry),
+			    to_string(ctx, struct sha256, &h->rhash),
+			    h->r ? tal_hexstr(ctx, h->r, sizeof(*h->r))
+			    : "UNKNOWN",
+			    h->src ? to_string(ctx, struct pubkey,
+					       &h->src->peer->id)
+			    : "local");
+	}
+
+	return s;
+}
+
 void log_struct_(struct log *log, int level,
 		 const char *structname,
 		 const char *fmt, ...)
 {
+	tal_t *ctx = tal(log, char);
 	char *s;
 	union loggable_structs u;
 	va_list ap;
@@ -281,31 +342,8 @@ void log_struct_(struct log *log, int level,
 	va_end(ap);
 
 	/* GCC checks we're one of these, so we should be. */
-	if (streq(structname, "struct pubkey"))
-		s = tal_hexstr(log, u.pubkey->der, sizeof(u.pubkey->der));
-	else if (streq(structname, "struct sha256_double"))
-		s = tal_hexstr(log, u.sha256_double, sizeof(*u.sha256_double));
-	else if (streq(structname, "struct sha256"))
-		s = tal_hexstr(log, u.sha256, sizeof(*u.sha256));
-	else if (streq(structname, "struct rel_locktime")) {
-		if (rel_locktime_is_seconds(u.rel_locktime))
-			s = tal_fmt(log, "+%usec",
-				    rel_locktime_to_seconds(u.rel_locktime));
-		else
-			s = tal_fmt(log, "+%ublocks",
-				    rel_locktime_to_blocks(u.rel_locktime));
-	} else if (streq(structname, "struct abs_locktime")) {
-		if (abs_locktime_is_seconds(u.abs_locktime))
-			s = tal_fmt(log, "%usec",
-				    abs_locktime_to_seconds(u.abs_locktime));
-		else
-			s = tal_fmt(log, "%ublocks",
-				    abs_locktime_to_blocks(u.abs_locktime));
-	} else if (streq(structname, "struct bitcoin_tx")) {
-		u8 *lin = linearize_tx(NULL, u.bitcoin_tx);
-		s = tal_hexstr(log, lin, tal_count(lin));
-		tal_free(lin);
-	} else
+	s = to_string_(ctx, structname, u);
+	if (!s)
 		fatal("Logging unknown type %s", structname);
 
 	if (level == -1)
@@ -313,7 +351,7 @@ void log_struct_(struct log *log, int level,
 	else
 		log_(log, level, fmt, s);
 
-	tal_free(s);
+	tal_free(ctx);
 }
 
 void log_each_line_(const struct log_record *lr,
diff --git a/daemon/log.h b/daemon/log.h
index 5339af6fe..abf7ab18e 100644
--- a/daemon/log.h
+++ b/daemon/log.h
@@ -69,6 +69,7 @@ union loggable_structs {
 	const struct rel_locktime *rel_locktime;
 	const struct abs_locktime *abs_locktime;
 	const struct bitcoin_tx *bitcoin_tx;
+	const struct htlc *htlc;
 	const char *charp_;
 };