From 87cd628f5244b9cb0ca380c06c58722854dfa28c Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 8 Apr 2019 09:22:19 +0930 Subject: [PATCH] log: truncate giant IO logging. Adding a giant IO message simply causes it to be pruned immediately, so truncate it if it's more than 1/64 the max size. Signed-off-by: Rusty Russell --- lightningd/log.c | 31 ++++++++++++++++----- lightningd/log.h | 4 +-- lightningd/peer_control.c | 4 +-- lightningd/test/run-invoice-select-inchan.c | 2 +- wallet/test/run-wallet.c | 1 + 5 files changed, 30 insertions(+), 12 deletions(-) diff --git a/lightningd/log.c b/lightningd/log.c index ef02ced2c..e0fbec20c 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -49,7 +49,9 @@ struct log_book { enum log_level level, bool continued, const struct timeabs *time, - const char *str, const u8 *io, void *arg); + const char *str, + const u8 *io, size_t io_len, + void *arg); void *print_arg; enum log_level print_level; struct timeabs init_time; @@ -68,6 +70,7 @@ static void log_to_file(const char *prefix, const struct timeabs *time, const char *str, const u8 *io, + size_t io_len, FILE *logf) { char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ")]; @@ -77,7 +80,7 @@ static void log_to_file(const char *prefix, if (level == LOG_IO_IN || level == LOG_IO_OUT) { const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]"; - char *hex = tal_hex(NULL, io); + char *hex = tal_hexstr(NULL, io, io_len); fprintf(logf, "%s %s%s%s %s\n", iso8601_s, prefix, str, dir, hex); tal_free(hex); @@ -94,9 +97,10 @@ static void log_to_stdout(const char *prefix, bool continued, const struct timeabs *time, const char *str, - const u8 *io, void *unused UNUSED) + const u8 *io, size_t io_len, + void *unused UNUSED) { - log_to_file(prefix, level, continued, time, str, io, stdout); + log_to_file(prefix, level, continued, time, str, io, io_len, stdout); } static size_t mem_used(const struct log_entry *e) @@ -191,7 +195,9 @@ void set_log_outfn_(struct log_book *lr, enum log_level level, bool continued, const struct timeabs *time, - const char *str, const u8 *io, void *arg), + const char *str, + const u8 *io, size_t io_len, + void *arg), void *arg) { lr->print = print; @@ -250,7 +256,7 @@ static void maybe_print(const struct log *log, const struct log_entry *l, 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); + l->io, tal_bytelen(l->io), log->lr->print_arg); } void logv(struct log *log, enum log_level level, const char *fmt, va_list ap) @@ -282,10 +288,21 @@ void log_io(struct log *log, enum log_level dir, assert(dir == LOG_IO_IN || dir == LOG_IO_OUT); + /* Print first, in case we need to truncate. */ + if (l->level >= log->lr->print_level) + log->lr->print(log->prefix, l->level, false, + &l->time, str, + data, len, log->lr->print_arg); + l->log = tal_strdup(l, str); + + /* Don't immediately fill buffer with giant IOs */ + if (len > log->lr->max_mem / 64) { + l->skipped++; + len = log->lr->max_mem / 64; + } l->io = tal_dup_arr(l, u8, data, len, 0); - maybe_print(log, l, 0); add_entry(log, l); errno = save_errno; } diff --git a/lightningd/log.h b/lightningd/log.h index fb38a316c..0e74bc4aa 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -50,7 +50,7 @@ struct log_book *get_log_book(const struct log *log); bool, \ const struct timeabs *, \ const char *, \ - const u8 *), (arg)) + const u8 *, size_t), (arg)) /* If level == LOG_IO_IN/LOG_IO_OUT, then io contains data */ void set_log_outfn_(struct log_book *lr, @@ -59,7 +59,7 @@ void set_log_outfn_(struct log_book *lr, bool continued, const struct timeabs *time, const char *str, - const u8 *io, + const u8 *io, size_t io_len, void *arg), void *arg); diff --git a/lightningd/peer_control.c b/lightningd/peer_control.c index debb69737..206838712 100644 --- a/lightningd/peer_control.c +++ b/lightningd/peer_control.c @@ -72,11 +72,11 @@ static void copy_to_parent_log(const char *prefix, bool continued, const struct timeabs *time UNUSED, const char *str, - const u8 *io, + const u8 *io, size_t io_len, struct log *parent_log) { if (level == LOG_IO_IN || level == LOG_IO_OUT) - log_io(parent_log, level, prefix, io, tal_count(io)); + log_io(parent_log, level, prefix, io, io_len); else if (continued) log_add(parent_log, "%s ... %s", prefix, str); else diff --git a/lightningd/test/run-invoice-select-inchan.c b/lightningd/test/run-invoice-select-inchan.c index d4c1a462d..0c047edf1 100644 --- a/lightningd/test/run-invoice-select-inchan.c +++ b/lightningd/test/run-invoice-select-inchan.c @@ -382,7 +382,7 @@ void set_log_outfn_(struct log_book *lr UNNEEDED, bool continued UNNEEDED, const struct timeabs *time UNNEEDED, const char *str UNNEEDED, - const u8 *io UNNEEDED, + const u8 *io UNNEEDED, size_t io_len UNNEEDED, void *arg) UNNEEDED, void *arg UNNEEDED) { fprintf(stderr, "set_log_outfn_ called!\n"); abort(); } diff --git a/wallet/test/run-wallet.c b/wallet/test/run-wallet.c index caa399b82..c3765fa4f 100644 --- a/wallet/test/run-wallet.c +++ b/wallet/test/run-wallet.c @@ -623,6 +623,7 @@ void set_log_outfn_(struct log_book *lr UNNEEDED, const struct timeabs *time UNNEEDED, const char *str UNNEEDED, const u8 *io UNNEEDED, + size_t io_len UNNEEDED, void *arg) UNNEEDED, void *arg UNNEEDED) {