From b7acd935781446aad7fb906c2b63420f57d98b0b Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 5 Feb 2018 14:39:28 +1030 Subject: [PATCH] log: separate levels for IO directions, allow msg + io data. We currently don't handle LOG_IO properly, and we turn it into a string before handing it to the ->print function, which makes it ugly for the case where we're using copy_to_parent_log, and also means in that case we lose *what peer* the IO is coming from. Now, we handle the io as a separate arg, which is much neater. Signed-off-by: Rusty Russell --- common/status.c | 6 +- common/status.h | 2 +- common/status_levels.h | 3 +- lightningd/jsonrpc.c | 5 +- lightningd/log.c | 118 ++++++++++++++++++++------------------ lightningd/log.h | 15 +++-- lightningd/log_status.c | 6 +- lightningd/peer_control.c | 5 +- 8 files changed, 87 insertions(+), 73 deletions(-) diff --git a/common/status.c b/common/status.c index 4aa70fd1e..bc6b61f2e 100644 --- a/common/status.c +++ b/common/status.c @@ -75,13 +75,13 @@ static void status_send_with_hdr(u16 type, const void *p, size_t len) } } -void status_io(enum side sender, const u8 *p) +void status_io(enum log_level iodir, const u8 *p) { - u16 type = STATUS_LOG_MIN + LOG_IO; + u16 type = STATUS_LOG_MIN + iodir; u8 *msg = tal_arr(NULL, u8, 0); + assert(iodir == LOG_IO_IN || iodir == LOG_IO_OUT); 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); diff --git a/common/status.h b/common/status.h index c5e4ff0b3..f222e9c92 100644 --- a/common/status.h +++ b/common/status.h @@ -27,7 +27,7 @@ void status_fmt(enum log_level level, const char *fmt, ...) /* vprintf-style */ void status_vfmt(enum log_level level, const char *fmt, va_list ap); -void status_io(enum side sender, const u8 *msg); +void status_io(enum log_level iodir, const u8 *p); /* Helpers */ #define status_debug(...) \ diff --git a/common/status_levels.h b/common/status_levels.h index 7a16e477b..456030723 100644 --- a/common/status_levels.h +++ b/common/status_levels.h @@ -4,7 +4,8 @@ enum log_level { /* Logging all IO. */ - LOG_IO, + LOG_IO_OUT, + LOG_IO_IN, /* Gory details which are mainly good for debugging. */ LOG_DBG, /* Information about what's going in. */ diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index 0ff2f8623..55fd9d4d2 100644 --- a/lightningd/jsonrpc.c +++ b/lightningd/jsonrpc.c @@ -634,7 +634,7 @@ static struct io_plan *write_json(struct io_conn *conn, jcon->outbuf = tal_steal(jcon, out->json); tal_free(out); - log_io(jcon->log, false, jcon->outbuf, strlen(jcon->outbuf)); + log_io(jcon->log, LOG_IO_OUT, "", jcon->outbuf, strlen(jcon->outbuf)); return io_write(conn, jcon->outbuf, strlen(jcon->outbuf), write_json, jcon); } @@ -645,7 +645,8 @@ static struct io_plan *read_json(struct io_conn *conn, jsmntok_t *toks; bool valid; - log_io(jcon->log, true, jcon->buffer + jcon->used, jcon->len_read); + log_io(jcon->log, LOG_IO_IN, "", + jcon->buffer + jcon->used, jcon->len_read); /* Resize larger if we're full. */ jcon->used += jcon->len_read; diff --git a/lightningd/log.c b/lightningd/log.c index 17942609d..a759296a7 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -29,6 +29,8 @@ struct log_entry { unsigned int skipped; const char *prefix; char *log; + /* Iff LOG_IO */ + const u8 *io; }; struct log_book { @@ -38,7 +40,7 @@ struct log_book { enum log_level level, bool continued, const struct timeabs *time, - const char *str, void *arg); + const char *str, const u8 *io, void *arg); void *print_arg; enum log_level print_level; struct timeabs init_time; @@ -56,13 +58,21 @@ static void log_to_file(const char *prefix, bool continued, const struct timeabs *time, const char *str, + const u8 *io, FILE *logf) { char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ")]; strftime(iso8601_msec_fmt, sizeof(iso8601_msec_fmt), "%FT%T.%%03dZ", gmtime(&time->ts.tv_sec)); char iso8601_s[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ")]; snprintf(iso8601_s, sizeof(iso8601_s), iso8601_msec_fmt, (int) time->ts.tv_nsec / 1000000); - if (!continued) { + + if (level == LOG_IO_IN || level == LOG_IO_OUT) { + const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]"; + char *hex = tal_hex(NULL, io); + fprintf(logf, "%s %s%s%s %s\n", + iso8601_s, prefix, str, dir, hex); + tal_free(hex); + } else if (!continued) { fprintf(logf, "%s %s %s\n", iso8601_s, prefix, str); } else { fprintf(logf, "%s %s \t%s\n", iso8601_s, prefix, str); @@ -74,17 +84,15 @@ static void log_to_stdout(const char *prefix, enum log_level level, bool continued, const struct timeabs *time, - const char *str, void *unused UNUSED) + const char *str, + const u8 *io, void *unused UNUSED) { - log_to_file(prefix, level, continued, time, str, stdout); + log_to_file(prefix, level, continued, time, str, io, stdout); } -static size_t log_bufsize(const struct log_entry *e) +static size_t mem_used(const struct log_entry *e) { - if (e->level == LOG_IO) - return tal_count(e->log); - else - return strlen(e->log) + 1; + return sizeof(*e) + strlen(e->log) + 1 + tal_len(e->io); } static size_t prune_log(struct log_book *log) @@ -96,7 +104,7 @@ static size_t prune_log(struct log_book *log) tail = list_tail(&log->log, struct log_entry, list); list_for_each_safe(&log->log, i, next, list) { - /* 50% chance of deleting debug, 25% inform, 12.5% unusual. */ + /* 50% chance of deleting IO_IN, 25% IO_OUT, 12.5% DEBUG... */ if (i == tail || !pseudorand(2 << i->level)) { i->skipped += skipped; skipped = 0; @@ -104,7 +112,7 @@ static size_t prune_log(struct log_book *log) } list_del_from(&log->log, &i->list); - log->mem_used -= sizeof(*i) + log_bufsize(i); + log->mem_used -= mem_used(i); tal_free(i); skipped++; deleted++; @@ -174,7 +182,7 @@ void set_log_outfn_(struct log_book *lr, enum log_level level, bool continued, const struct timeabs *time, - const char *str, void *arg), + const char *str, const u8 *io, void *arg), void *arg) { lr->print = print; @@ -203,7 +211,7 @@ const struct timeabs *log_init_time(const struct log_book *lr) static void add_entry(struct log *log, struct log_entry *l) { - log->lr->mem_used += sizeof(*l) + log_bufsize(l); + log->lr->mem_used += mem_used(l); list_add_tail(&log->lr->log, &l->list); if (log->lr->mem_used > log->lr->max_mem) { @@ -228,44 +236,45 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level) l->level = level; l->skipped = 0; l->prefix = log->prefix; + l->io = NULL; return l; } +static void maybe_print(const struct log *log, const struct log_entry *l, + size_t offset) +{ + if (l->level >= log->lr->print_level) + log->lr->print(log->prefix, l->level, offset != 0, + &l->time, l->log + offset, + l->io, log->lr->print_arg); +} + void logv(struct log *log, enum log_level level, const char *fmt, va_list ap) { int save_errno = errno; struct log_entry *l = new_log_entry(log, level); l->log = tal_vfmt(l, fmt, ap); - - if (level >= log->lr->print_level) - log->lr->print(log->prefix, level, false, &l->time, l->log, - log->lr->print_arg); + maybe_print(log, l, 0); add_entry(log, l); errno = save_errno; } -void log_io(struct log *log, bool in, const void *data, size_t len) +void log_io(struct log *log, enum log_level dir, + const char *str TAKES, + const void *data TAKES, size_t len) { int save_errno = errno; - struct log_entry *l = new_log_entry(log, LOG_IO); - - l->log = tal_arr(l, char, 1 + len); - l->log[0] = in; - memcpy(l->log + 1, data, len); - - if (LOG_IO >= log->lr->print_level) { - const char *dir = in ? "[IN]" : "[OUT]"; - char *hex = tal_arr(l, char, strlen(dir) + hex_str_size(len)); - strcpy(hex, dir); - hex_encode(data, len, hex + strlen(dir), hex_str_size(len)); - log->lr->print(log->prefix, LOG_IO, false, &l->time, l->log, - log->lr->print_arg); - tal_free(hex); - } + struct log_entry *l = new_log_entry(log, dir); + + assert(dir == LOG_IO_IN || dir == LOG_IO_OUT); + + l->log = tal_strdup(l, str); + l->io = tal_dup_arr(l, u8, data, len, 0); + maybe_print(log, l, 0); add_entry(log, l); errno = save_errno; } @@ -276,15 +285,13 @@ void logv_add(struct log *log, const char *fmt, va_list ap) size_t oldlen = strlen(l->log); /* Remove from list, so it doesn't get pruned. */ - log->lr->mem_used -= sizeof(*l) + oldlen + 1; + log->lr->mem_used -= mem_used(l); list_del_from(&log->lr->log, &l->list); tal_append_vfmt(&l->log, fmt, ap); add_entry(log, l); - if (l->level >= log->lr->print_level) - log->lr->print(log->prefix, l->level, true, &l->time, l->log + oldlen, - log->lr->print_arg); + maybe_print(log, l, oldlen); } void log_(struct log *log, enum log_level level, const char *fmt, ...) @@ -311,6 +318,7 @@ void log_each_line_(const struct log_book *lr, enum log_level level, const char *prefix, const char *log, + const u8 *io, void *arg), void *arg) { @@ -318,7 +326,7 @@ void log_each_line_(const struct log_book *lr, list_for_each(&lr->log, i, list) { func(i->skipped, time_between(i->time, lr->init_time), - i->level, i->prefix, i->log, arg); + i->level, i->prefix, i->log, i->io, arg); } } @@ -332,6 +340,7 @@ static void log_one_line(unsigned int skipped, enum log_level level, const char *prefix, const char *log, + const u8 *io, struct log_data *data) { char buf[101]; @@ -347,7 +356,8 @@ static void log_one_line(unsigned int skipped, (unsigned long)diff.ts.tv_sec, (unsigned)diff.ts.tv_nsec, prefix, - level == LOG_IO ? (log[0] ? "IO-IN" : "IO-OUT") + level == LOG_IO_IN ? "IO_IN" + : level == LOG_IO_OUT ? "IO_OUT" : level == LOG_DBG ? "DEBUG" : level == LOG_INFORM ? "INFO" : level == LOG_UNUSUAL ? "UNUSUAL" @@ -355,19 +365,18 @@ static void log_one_line(unsigned int skipped, : "**INVALID**"); write_all(data->fd, buf, strlen(buf)); - if (level == LOG_IO) { - size_t off, used, len = tal_count(log)-1; + write_all(data->fd, log, strlen(log)); + if (level == LOG_IO_IN || level == LOG_IO_OUT) { + size_t off, used, len = tal_count(io); /* No allocations, may be in signal handler. */ for (off = 0; off < len; off += used) { used = len - off; if (hex_str_size(used) > sizeof(buf)) used = hex_data_size(sizeof(buf)); - hex_encode(log + 1 + off, used, buf, hex_str_size(used)); + hex_encode(io + off, used, buf, hex_str_size(used)); write_all(data->fd, buf, strlen(buf)); } - } else { - write_all(data->fd, log, strlen(log)); } data->prefix = "\n"; @@ -377,7 +386,7 @@ static struct { const char *name; enum log_level level; } log_levels[] = { - { "IO", LOG_IO }, + { "IO", LOG_IO_OUT }, { "DEBUG", LOG_DBG }, { "INFO", LOG_INFORM }, { "UNUSUAL", LOG_UNUSUAL }, @@ -599,6 +608,7 @@ static void log_to_json(unsigned int skipped, enum log_level level, const char *prefix, const char *log, + const u8 *io, struct log_info *info) { info->num_skipped += skipped; @@ -616,20 +626,14 @@ static void log_to_json(unsigned int skipped, : level == LOG_UNUSUAL ? "UNUSUAL" : level == LOG_INFORM ? "INFO" : level == LOG_DBG ? "DEBUG" - : level == LOG_IO ? "IO" + : level == LOG_IO_IN ? "IO_IN" + : level == LOG_IO_OUT ? "IO_OUT" : "UNKNOWN"); json_add_time(info->response, "time", diff.ts); json_add_string(info->response, "source", prefix); - if (level == LOG_IO) { - assert(tal_count(log) > 0); - if (log[0]) - json_add_string(info->response, "direction", "IN"); - else - json_add_string(info->response, "direction", "OUT"); - - json_add_hex(info->response, "data", log+1, tal_count(log)-1); - } else - json_add_string(info->response, "log", log); + json_add_string(info->response, "log", log); + if (io) + json_add_hex(info->response, "data", io, tal_count(io)); json_object_end(info->response); } @@ -664,7 +668,7 @@ static void json_getlog(struct command *cmd, if (!level) minlevel = LOG_INFORM; else if (json_tok_streq(buffer, level, "io")) - minlevel = LOG_IO; + minlevel = LOG_IO_OUT; else if (json_tok_streq(buffer, level, "debug")) minlevel = LOG_DBG; else if (json_tok_streq(buffer, level, "info")) diff --git a/lightningd/log.h b/lightningd/log.h index 39cc10bc4..22ab534ba 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -25,7 +25,8 @@ struct log *new_log(const tal_t *ctx, struct log_book *record, const char *fmt, #define log_unusual(log, ...) log_((log), LOG_UNUSUAL, __VA_ARGS__) #define log_broken(log, ...) log_((log), LOG_BROKEN, __VA_ARGS__) -void log_io(struct log *log, bool in, const void *data, size_t len); +void log_io(struct log *log, enum log_level dir, const char *comment, + const void *data, size_t len); void log_(struct log *log, enum log_level level, const char *fmt, ...) PRINTF_FMT(3,4); @@ -44,14 +45,18 @@ const char *log_prefix(const struct log *log); enum log_level, \ bool, \ const struct timeabs *, \ - const char *), (arg)) + const char *, \ + const u8 *), (arg)) +/* If level == LOG_IO_IN/LOG_IO_OUT, then io contains data */ void set_log_outfn_(struct log_book *lr, void (*print)(const char *prefix, enum log_level level, bool continued, const struct timeabs *time, - const char *str, void *arg), + const char *str, + const u8 *io, + void *arg), void *arg); size_t log_max_mem(const struct log_book *lr); @@ -65,7 +70,8 @@ const struct timeabs *log_init_time(const struct log_book *lr); struct timerel, \ enum log_level, \ const char *, \ - const char *), (arg)) + const char *, \ + const u8 *), (arg)) void log_each_line_(const struct log_book *lr, void (*func)(unsigned int skipped, @@ -73,6 +79,7 @@ void log_each_line_(const struct log_book *lr, enum log_level level, const char *prefix, const char *log, + const u8 *io, void *arg), void *arg); diff --git a/lightningd/log_status.c b/lightningd/log_status.c index 6726871ec..adb9fa6d2 100644 --- a/lightningd/log_status.c +++ b/lightningd/log_status.c @@ -11,10 +11,8 @@ bool log_status_msg(struct log *log, const u8 *msg) 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); + if (level == LOG_IO_IN || level == LOG_IO_OUT) { + log_io(log, level, "", msg, max); } else { int i; /* Truncate if unprintable */ diff --git a/lightningd/peer_control.c b/lightningd/peer_control.c index 6ca037ba1..068e245f5 100644 --- a/lightningd/peer_control.c +++ b/lightningd/peer_control.c @@ -699,9 +699,12 @@ static void copy_to_parent_log(const char *prefix, bool continued, const struct timeabs *time, const char *str, + const u8 *io, struct peer *peer) { - if (continued) + if (level == LOG_IO_IN || level == LOG_IO_OUT) + log_io(peer->ld->log, level, prefix, io, tal_len(io)); + else if (continued) log_add(peer->ld->log, "%s ... %s", prefix, str); else log_(peer->ld->log, level, "%s %s", prefix, str);