diff --git a/channeld/test/run-full_channel.c b/channeld/test/run-full_channel.c index 9e2773b3c..aff2c3929 100644 --- a/channeld/test/run-full_channel.c +++ b/channeld/test/run-full_channel.c @@ -1,8 +1,3 @@ - #include - #include -#define status_trace(fmt , ...) \ - printf(fmt "\n" , ## __VA_ARGS__) - #include "../../common/key_derive.c" #include "../../common/keyset.c" #include "../../common/initial_channel.c" @@ -17,6 +12,17 @@ #include #include #include +#include + +void status_fmt(enum log_level level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + vprintf(fmt, ap); + printf("\n"); + va_end(ap); +} const void *trc; diff --git a/common/Makefile b/common/Makefile index e549c227d..b252a5242 100644 --- a/common/Makefile +++ b/common/Makefile @@ -42,7 +42,7 @@ COMMON_SRC := \ common/wire_error.c \ common/withdraw_tx.c -COMMON_HEADERS_NOGEN := $(COMMON_SRC:.c=.h) common/overflows.h common/htlc.h +COMMON_HEADERS_NOGEN := $(COMMON_SRC:.c=.h) common/overflows.h common/htlc.h common/status_levels.h COMMON_HEADERS_GEN := common/gen_htlc_state_names.h COMMON_HEADERS := $(COMMON_HEADERS_GEN) $(COMMON_HEADERS_NOGEN) diff --git a/common/status.c b/common/status.c index c55285375..4aa70fd1e 100644 --- a/common/status.c +++ b/common/status.c @@ -75,12 +75,32 @@ static void status_send_with_hdr(u16 type, const void *p, size_t len) } } -void status_tracev(const char *fmt, va_list ap) +void status_io(enum side sender, const u8 *p) +{ + u16 type = STATUS_LOG_MIN + LOG_IO; + u8 *msg = tal_arr(NULL, u8, 0); + + towire_u16(&msg, type); + towire_bool(&msg, sender == REMOTE); + towire(&msg, p, tal_len(p)); + if (too_large(tal_len(msg), type)) + tal_resize(&msg, 65535); + + if (status_fd >= 0) { + if (!wire_sync_write(status_fd, take(msg))) + err(1, "Writing out status %u len %zu", + type, tal_len(p)); + } else { + daemon_conn_send(status_conn, take(msg)); + } +} + +void status_vfmt(enum log_level level, const char *fmt, va_list ap) { char *str; str = tal_vfmt(NULL, fmt, ap); - status_send_with_hdr(STATUS_TRACE, str, strlen(str)); + status_send_with_hdr(STATUS_LOG_MIN + level, str, strlen(str)); tal_free(str); /* Free up any temporary children. */ @@ -90,12 +110,12 @@ void status_tracev(const char *fmt, va_list ap) } } -void status_trace(const char *fmt, ...) +void status_fmt(enum log_level level, const char *fmt, ...) { va_list ap; va_start(ap, fmt); - status_tracev(fmt, ap); + status_vfmt(level, fmt, ap); va_end(ap); } diff --git a/common/status.h b/common/status.h index 99c1cc5e8..c5e4ff0b3 100644 --- a/common/status.h +++ b/common/status.h @@ -3,7 +3,10 @@ #include "config.h" #include #include +#include /* For enum side */ +#include #include +#include #include struct daemon_conn; @@ -15,44 +18,30 @@ void status_setup_async(struct daemon_conn *master); /* Convenient context, frees up after every status_update/failed */ extern const void *trc; -/* Special status code for tracing messages. */ -#define STATUS_TRACE 0x7FFF - -/* Failure codes always have high bit set. */ -#define STATUS_FAIL 0x8000 - -/* These are always followed by an ASCII string. */ -enum status_fail { - /* - * These errors shouldn't happen: - */ - /* Master daemon sent unknown/malformed command, or fd failed */ - STATUS_FAIL_MASTER_IO = STATUS_FAIL, - - /* Hsmd sent unknown/malformed command, or fd failed */ - STATUS_FAIL_HSM_IO, - - /* Gossipd sent unknown/malformed command, or fd failed */ - STATUS_FAIL_GOSSIP_IO, - - /* Other internal error. */ - STATUS_FAIL_INTERNAL_ERROR, - - /* - * These errors happen when the other peer misbehaves: - */ - /* I/O failure (probably they closed the socket) */ - STATUS_FAIL_PEER_IO, - /* Peer did something else wrong */ - STATUS_FAIL_PEER_BAD -}; - /* Send a message (frees the message). */ void status_send_sync(const u8 *msg); /* Send a printf-style debugging trace. */ -void status_trace(const char *fmt, ...) PRINTF_FMT(1,2); +void status_fmt(enum log_level level, const char *fmt, ...) + PRINTF_FMT(2,3); + /* vprintf-style */ -void status_tracev(const char *fmt, va_list ap); +void status_vfmt(enum log_level level, const char *fmt, va_list ap); + +void status_io(enum side sender, const u8 *msg); + +/* Helpers */ +#define status_debug(...) \ + status_fmt(LOG_DBG, __VA_ARGS__) +#define status_info(...) \ + status_fmt(LOG_INFORM, __VA_ARGS__) +#define status_unusual(...) \ + status_fmt(LOG_UNUSUAL, __VA_ARGS__) +#define status_broken( ...) \ + status_fmt(LOG_BROKEN, __VA_ARGS__) + +/* FIXME: Transition */ +#define status_trace(...) status_debug(__VA_ARGS__) + /* Send a failure status code with printf-style msg, and exit. */ void status_failed(enum status_fail code, const char *fmt, ...) PRINTF_FMT(2,3) NORETURN; diff --git a/common/status_levels.h b/common/status_levels.h new file mode 100644 index 000000000..7a16e477b --- /dev/null +++ b/common/status_levels.h @@ -0,0 +1,52 @@ +#ifndef LIGHTNING_COMMON_STATUS_LEVELS_H +#define LIGHTNING_COMMON_STATUS_LEVELS_H +#include "config.h" + +enum log_level { + /* Logging all IO. */ + LOG_IO, + /* Gory details which are mainly good for debugging. */ + LOG_DBG, + /* Information about what's going in. */ + LOG_INFORM, + /* That's strange... */ + LOG_UNUSUAL, + /* That's really bad, we're broken. */ + LOG_BROKEN +}; + +/* Special status code for tracing messages (subtract log_level). */ +#define STATUS_LOG_MIN (STATUS_LOG_MAX - LOG_BROKEN) +#define STATUS_LOG_MAX (0x7FFF) + +/* Failure codes always have high bit set. */ +#define STATUS_FAIL 0x8000 + +/* These are always followed by an ASCII string. */ +enum status_fail { + /* + * These errors shouldn't happen: + */ + /* Master daemon sent unknown/malformed command, or fd failed */ + STATUS_FAIL_MASTER_IO = STATUS_FAIL, + + /* Hsmd sent unknown/malformed command, or fd failed */ + STATUS_FAIL_HSM_IO, + + /* Gossipd sent unknown/malformed command, or fd failed */ + STATUS_FAIL_GOSSIP_IO, + + /* Other internal error. */ + STATUS_FAIL_INTERNAL_ERROR, + + /* + * These errors happen when the other peer misbehaves: + */ + /* I/O failure (probably they closed the socket) */ + STATUS_FAIL_PEER_IO, + + /* Peer did something else wrong */ + STATUS_FAIL_PEER_BAD +}; + +#endif /* LIGHTNING_COMMON_STATUS_LEVELS_H */ diff --git a/gossipd/test/run-bench-find_route.c b/gossipd/test/run-bench-find_route.c index 988f10ff4..effe8e5dc 100644 --- a/gossipd/test/run-bench-find_route.c +++ b/gossipd/test/run-bench-find_route.c @@ -7,13 +7,20 @@ #include #include #include +#include #include #include #include -#include -#define status_trace(fmt, ...) \ - do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0) +void status_fmt(enum log_level level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + vprintf(fmt, ap); + printf("\n"); + va_end(ap); +} static bool in_bench = 0; diff --git a/gossipd/test/run-find_route-specific.c b/gossipd/test/run-find_route-specific.c index 092c8a6b2..117d38743 100644 --- a/gossipd/test/run-find_route-specific.c +++ b/gossipd/test/run-find_route-specific.c @@ -8,7 +8,7 @@ #include #include -#define status_trace(fmt, ...) \ +#define status_fmt(level, fmt, ...) \ do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0) #include "../routing.c" diff --git a/gossipd/test/run-find_route.c b/gossipd/test/run-find_route.c index 96d07fcfa..428693705 100644 --- a/gossipd/test/run-find_route.c +++ b/gossipd/test/run-find_route.c @@ -1,16 +1,21 @@ -#include - -#include -#define status_trace(fmt, ...) \ - do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0) - #include "../routing.c" +#include struct broadcast_state *new_broadcast_state(tal_t *ctx UNNEEDED) { return NULL; } +void status_fmt(enum log_level level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + vprintf(fmt, ap); + printf("\n"); + va_end(ap); +} + /* AUTOGENERATED MOCKS START */ /* Generated stub for fromwire_channel_announcement */ bool fromwire_channel_announcement(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, size_t *plen UNNEEDED, secp256k1_ecdsa_signature *node_signature_1 UNNEEDED, secp256k1_ecdsa_signature *node_signature_2 UNNEEDED, secp256k1_ecdsa_signature *bitcoin_signature_1 UNNEEDED, secp256k1_ecdsa_signature *bitcoin_signature_2 UNNEEDED, u8 **features UNNEEDED, struct bitcoin_blkid *chain_hash UNNEEDED, struct short_channel_id *short_channel_id UNNEEDED, struct pubkey *node_id_1 UNNEEDED, struct pubkey *node_id_2 UNNEEDED, struct pubkey *bitcoin_key_1 UNNEEDED, struct pubkey *bitcoin_key_2 UNNEEDED) diff --git a/gossipd/test/run-initiator-success.c b/gossipd/test/run-initiator-success.c index 347776970..09df4e5c4 100644 --- a/gossipd/test/run-initiator-success.c +++ b/gossipd/test/run-initiator-success.c @@ -32,7 +32,7 @@ static struct io_plan *test_read(struct io_conn *conn, struct handshake *h); #define SUPERVERBOSE status_trace -void status_trace(const char *fmt, ...) +void status_fmt(enum log_level level, const char *fmt, ...) { va_list ap; diff --git a/gossipd/test/run-responder-success.c b/gossipd/test/run-responder-success.c index b750a6e3f..4a74836ca 100644 --- a/gossipd/test/run-responder-success.c +++ b/gossipd/test/run-responder-success.c @@ -31,8 +31,8 @@ static struct io_plan *test_read(struct io_conn *conn, struct handshake *), struct handshake *h); -#define SUPERVERBOSE status_trace -void status_trace(const char *fmt, ...) +#define SUPERVERBOSE status_debug +void status_fmt(enum log_level level, const char *fmt, ...) { va_list ap; diff --git a/lightningd/Makefile b/lightningd/Makefile index cd60db562..2981d8349 100644 --- a/lightningd/Makefile +++ b/lightningd/Makefile @@ -55,6 +55,7 @@ LIGHTNINGD_SRC := \ lightningd/jsonrpc.c \ lightningd/lightningd.c \ lightningd/log.c \ + lightningd/log_status.c \ lightningd/netaddress.c \ lightningd/opt_time.c \ lightningd/options.c \ diff --git a/lightningd/hsm_control.c b/lightningd/hsm_control.c index f9596c59d..3c9a2f0e6 100644 --- a/lightningd/hsm_control.c +++ b/lightningd/hsm_control.c @@ -11,6 +11,7 @@ #include #include #include +#include #include #include #include @@ -19,15 +20,13 @@ u8 *hsm_sync_read(const tal_t *ctx, struct lightningd *ld) { for (;;) { u8 *msg = wire_sync_read(ctx, ld->hsm_fd); + if (!msg) fatal("Could not read from HSM: %s", strerror(errno)); - if (fromwire_peektype(msg) != STATUS_TRACE) + if (log_status_msg(ld->log, msg)) + tal_free(msg); + else return msg; - - log_debug(ld->log, "HSM TRACE: %.*s", - (int)(tal_len(msg) - sizeof(be16)), - (char *)msg + sizeof(be16)); - tal_free(msg); } } diff --git a/lightningd/log.h b/lightningd/log.h index b257a55ea..9fe3de278 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -11,19 +12,6 @@ struct lightningd; struct timerel; struct lightningd; -enum log_level { - /* Logging all IO. */ - LOG_IO, - /* Gory details which are mainly good for debugging. */ - LOG_DBG, - /* Information about what's going in. */ - LOG_INFORM, - /* That's strange... */ - LOG_UNUSUAL, - /* That's really bad, we're broken. */ - LOG_BROKEN -}; - /* We can have a single log book, with multiple logs in it. */ struct log_book *new_log_book(const tal_t *ctx, size_t max_mem, diff --git a/lightningd/log_status.c b/lightningd/log_status.c new file mode 100644 index 000000000..6726871ec --- /dev/null +++ b/lightningd/log_status.c @@ -0,0 +1,28 @@ +#include +#include + +bool log_status_msg(struct log *log, const u8 *msg) +{ + size_t max = tal_len(msg); + int type = fromwire_u16(&msg, &max); + enum log_level level; + + if (type < STATUS_LOG_MIN || type > STATUS_LOG_MAX) + return false; + + level = type - STATUS_LOG_MIN; + if (level == LOG_IO) { + /* First byte is direction */ + bool dir = fromwire_bool(&msg, &max); + log_io(log, dir, msg, max); + } else { + int i; + /* Truncate if unprintable */ + for (i = 0; i < max; i++) { + if (!cisprint((char)msg[i])) + break; + } + log_(log, level, "%.*s%s", i, msg, i == max ? "" : "..."); + } + return true; +} diff --git a/lightningd/log_status.h b/lightningd/log_status.h new file mode 100644 index 000000000..fc8dd824a --- /dev/null +++ b/lightningd/log_status.h @@ -0,0 +1,10 @@ +#ifndef LIGHTNING_LIGHTNINGD_LOG_STATUS_H +#define LIGHTNING_LIGHTNINGD_LOG_STATUS_H +#include "config.h" +#include +#include + +/* Returns true (and writes it to log) if it's a status_log message. */ +bool log_status_msg(struct log *log, const u8 *msg); + +#endif /* LIGHTNING_LIGHTNINGD_LOG_STATUS_H */ diff --git a/lightningd/subd.c b/lightningd/subd.c index 6155b8e9e..bcdfcc587 100644 --- a/lightningd/subd.c +++ b/lightningd/subd.c @@ -7,11 +7,11 @@ #include #include #include -#include #include #include #include #include +#include #include #include #include @@ -438,14 +438,10 @@ static struct io_plan *sd_msg_read(struct io_conn *conn, struct subd *sd) tmpctx = tal_tmpctx(sd); tal_steal(tmpctx, sd->msg_in); - if (type == STATUS_TRACE) { - int str_len; - const char *str = string_from_msg(sd->msg_in, &str_len); - if (!str) - goto malformed; - log_debug(sd->log, "TRACE: %.*s", str_len, str); + if (log_status_msg(sd->log, sd->msg_in)) goto next; - } else if (type & STATUS_FAIL) { + + if (type & STATUS_FAIL) { int str_len; const char *str = string_from_msg(sd->msg_in, &str_len); if (!str) diff --git a/lightningd/test/run-cryptomsg.c b/lightningd/test/run-cryptomsg.c index 35126ede9..6642105fe 100644 --- a/lightningd/test/run-cryptomsg.c +++ b/lightningd/test/run-cryptomsg.c @@ -36,8 +36,15 @@ static void do_write(const void *buf, size_t len) #define io_write(conn, p, len, next, arg) \ (do_write((p), (len)), (next)((conn), (arg)), NULL) -#define status_trace(fmt, ...) \ - printf(fmt "\n", __VA_ARGS__) +void status_fmt(enum log_level level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + vprintf(fmt, ap); + printf("\n"); + va_end(ap); +} #if DEVELOPER /* AUTOGENERATED MOCKS START */