diff --git a/Makefile b/Makefile index fc09910dd..24c1751af 100644 --- a/Makefile +++ b/Makefile @@ -190,7 +190,7 @@ CFLAGS := $(CWARNFLAGS) $(CDEBUGFLAGS) -I $(CCANDIR) -I secp256k1/include/ $(FEA LDLIBS := -lcrypto -lprotobuf-c $(PROGRAMS): CFLAGS+=-I. -default: $(PROGRAMS) +default: $(PROGRAMS) daemon-all # Everything depends on the CCAN headers. $(CCAN_OBJS) $(CDUMP_OBJS) $(HELPER_OBJS) $(BITCOIN_OBJS) $(TEST_CLI_PROGRAMS:=.o) $(TEST_PROGRAMS:=.o): $(CCAN_HEADERS) @@ -327,6 +327,8 @@ clean: $(RM) bitcoin/*.o *.o $(PROGRAMS:=.o) $(CCAN_OBJS) $(RM) doc/deployable-lightning.{aux,bbl,blg,dvi,log,out,tex} +include daemon/Makefile + ccan-tal.o: $(CCANDIR)/ccan/tal/tal.c $(CC) $(CFLAGS) -c -o $@ $< ccan-tal-str.o: $(CCANDIR)/ccan/tal/str/str.c diff --git a/daemon/.gitignore b/daemon/.gitignore new file mode 100644 index 000000000..c9af60b4c --- /dev/null +++ b/daemon/.gitignore @@ -0,0 +1 @@ +lightningd diff --git a/daemon/Makefile b/daemon/Makefile new file mode 100644 index 000000000..77e45b8cd --- /dev/null +++ b/daemon/Makefile @@ -0,0 +1,25 @@ +#! /usr/bin/make + +# Designed to be run one level up +daemon-wrongdir: + $(MAKE) -C .. daemon-all + +daemon-all: daemon/lightningd + +DAEMON_SRC := \ + daemon/lightningd.c \ + daemon/log.c \ + daemon/pseudorand.c +DAEMON_OBJS := $(DAEMON_SRC:.c=.o) + +DAEMON_HEADERS := \ + daemon/lightningd.h \ + daemon/log.h \ + daemon/pseudorand.h + +$(DAEMON_OBJS): $(DAEMON_HEADERS) $(BITCOIN_HEADERS) $(CORE_HEADERS) $(GEN_HEADERS) $(CCAN_HEADERS) + +check-source: $(DAEMON_SRC:%=check-src-include-order/%) +check-source: $(DAEMON_HEADERS:%=check-hdr-include-order/%) + +daemon/lightningd: $(DAEMON_OBJS) $(CCAN_OBJS) diff --git a/daemon/lightningd.c b/daemon/lightningd.c new file mode 100644 index 000000000..8da40fe5b --- /dev/null +++ b/daemon/lightningd.c @@ -0,0 +1,25 @@ +#include "lightningd.h" +#include "log.h" +#include +#include +#include + +static struct lightningd_state *lightningd_state(void) +{ + struct lightningd_state *state = tal(NULL, struct lightningd_state); + + state->log_record = new_log_record(state, 20 * 1024 * 1024, LOG_INFORM); + state->base_log = new_log(state, state->log_record, + "lightningd(%u):", (int)getpid()); + + return state; +} + +int main(int argc, char *argv[]) +{ + struct lightningd_state *state = lightningd_state(); + + log_info(state->base_log, "Hello world!"); + tal_free(state); + return 0; +} diff --git a/daemon/lightningd.h b/daemon/lightningd.h new file mode 100644 index 000000000..591345ec9 --- /dev/null +++ b/daemon/lightningd.h @@ -0,0 +1,11 @@ +#ifndef LIGHTNING_DAEMON_LIGHTNING_H +#define LIGHTNING_DAEMON_LIGHTNING_H +#include "config.h" + +/* Here's where the global variables hide! */ +struct lightningd_state { + /* Where all our logging goes. */ + struct log_record *log_record; + struct log *base_log; +}; +#endif /* LIGHTNING_DAEMON_LIGHTNING_H */ diff --git a/daemon/log.c b/daemon/log.c new file mode 100644 index 000000000..b21544e19 --- /dev/null +++ b/daemon/log.c @@ -0,0 +1,313 @@ +#include "log.h" +#include "pseudorand.h" +#include +#include +#include +#include +#include +#include +#include + +struct log_entry { + struct list_node list; + struct timeabs time; + enum log_level level; + unsigned int skipped; + const char *prefix; + char *log; +}; + +struct log_record { + size_t mem_used; + size_t max_mem; + enum log_level print; + struct timeabs init_time; + + struct list_head log; +}; + +struct log { + struct log_record *lr; + const char *prefix; +}; + +static size_t log_bufsize(const struct log_entry *e) +{ + if (e->level == LOG_IO) + return tal_count(e->log); + else + return strlen(e->log) + 1; +} + +static size_t prune_log(struct log_record *log) +{ + struct log_entry *i, *next, *tail; + size_t skipped = 0, deleted = 0; + + /* Never delete the last one. */ + 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. */ + if (i == tail || !pseudorand(2 << i->level)) { + i->skipped += skipped; + skipped = 0; + continue; + } + + list_del_from(&log->log, &i->list); + log->mem_used -= sizeof(*i) + log_bufsize(i); + tal_free(i); + skipped++; + deleted++; + } + + assert(!skipped); + return deleted; +} + +struct log_record *new_log_record(const tal_t *ctx, + size_t max_mem, + enum log_level printlevel) +{ + struct log_record *lr = tal(ctx, struct log_record); + + /* Give a reasonable size for memory limit! */ + assert(max_mem > sizeof(struct log) * 2); + lr->mem_used = 0; + lr->max_mem = max_mem; + lr->print = printlevel; + lr->init_time = time_now(); + list_head_init(&lr->log); + + return lr; +} + +/* With different entry points */ +struct log *PRINTF_FMT(3,4) +new_log(const tal_t *ctx, struct log_record *record, const char *fmt, ...) +{ + struct log *log = tal(ctx, struct log); + va_list ap; + + log->lr = record; + va_start(ap, fmt); + /* log->lr owns this, since its entries keep a pointer to it. */ + log->prefix = tal_vfmt(log->lr, fmt, ap); + va_end(ap); + + return log; +} + +void set_log_level(struct log_record *lr, enum log_level level) +{ + lr->print = level; +} + +void set_log_prefix(struct log *log, const char *prefix) +{ + /* log->lr owns this, since it keeps a pointer to it. */ + log->prefix = tal_strdup(log->lr, prefix); +} + +const char *log_prefix(const struct log *log) +{ + return log->prefix; +} + +size_t log_max_mem(const struct log_record *lr) +{ + return lr->max_mem; +} + +size_t log_used(const struct log_record *lr) +{ + return lr->mem_used; +} + +const struct timeabs *log_init_time(const struct log_record *lr) +{ + return &lr->init_time; +} + +static void add_entry(struct log *log, struct log_entry *l) +{ + log->lr->mem_used += sizeof(*l) + log_bufsize(l); + list_add_tail(&log->lr->log, &l->list); + + if (log->lr->mem_used > log->lr->max_mem) { + size_t old_mem = log->lr->mem_used, deleted; + deleted = prune_log(log->lr); + log_debug(log, "Log pruned %zu entries (mem %zu -> %zu)", + deleted, old_mem, log->lr->mem_used); + } +} + +static struct log_entry *new_log_entry(struct log *log, enum log_level level) +{ + struct log_entry *l = tal(log->lr, struct log_entry); + + l->time = time_now(); + l->level = level; + l->skipped = 0; + l->prefix = log->prefix; + + return l; +} + +void logv(struct log *log, enum log_level level, const char *fmt, va_list ap) +{ + struct log_entry *l = new_log_entry(log, level); + + l->log = tal_vfmt(l, fmt, ap); + + if (level >= log->lr->print) + printf("%s %s\n", log->prefix, l->log); + + add_entry(log, l); +} + +void log_io(struct log *log, bool in, const void *data, 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) { + char *hex = tal_arr(l, char, hex_str_size(len)); + hex_encode(data, len, hex, hex_str_size(len)); + printf("%s[%s] %s\n", log->prefix, in ? "IN" : "OUT", hex); + tal_free(hex); + } + add_entry(log, l); + errno = save_errno; +} + +static void do_log_add(struct log *log, const char *fmt, va_list ap) +{ + struct log_entry *l = list_tail(&log->lr->log, struct log_entry, list); + size_t oldlen = strlen(l->log); + + /* Remove from list, so it doesn't get pruned. */ + log->lr->mem_used -= sizeof(*l) + oldlen + 1; + 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) + printf("%s \t%s\n", log->prefix, l->log + oldlen); +} + +void log_(struct log *log, enum log_level level, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + logv(log, level, fmt, ap); + va_end(ap); +} + +void log_add(struct log *log, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + do_log_add(log, fmt, ap); + va_end(ap); +} + +void log_each_line_(const struct log_record *lr, + void (*func)(unsigned int skipped, + struct timerel time, + enum log_level level, + const char *prefix, + const char *log, + void *arg), + void *arg) +{ + const struct log_entry *i; + + list_for_each(&lr->log, i, list) { + func(i->skipped, time_between(i->time, lr->init_time), + i->level, i->prefix, i->log, arg); + } +} + +struct log_data { + int fd; + const char *prefix; +}; + +static void log_one_line(unsigned int skipped, + struct timerel diff, + enum log_level level, + const char *prefix, + const char *log, + struct log_data *data) +{ + char buf[101]; + + if (skipped) { + sprintf(buf, "%s... %u skipped...", data->prefix, skipped); + write_all(data->fd, buf, strlen(buf)); + data->prefix = "\n"; + } + + sprintf(buf, "%s+%lu.%09u %s%s: ", + data->prefix, + (unsigned long)diff.ts.tv_sec, + (unsigned)diff.ts.tv_nsec, + prefix, + level == LOG_IO ? (log[0] ? "IO-IN" : "IO-OUT") + : level == LOG_DBG ? "DEBUG" + : level == LOG_INFORM ? "INFO" + : level == LOG_UNUSUAL ? "UNUSUAL" + : level == LOG_BROKEN ? "BROKEN" + : "**INVALID**"); + + write_all(data->fd, buf, strlen(buf)); + if (level == LOG_IO) { + size_t off, used, len = tal_count(log)-1; + + /* 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)); + write_all(data->fd, buf, strlen(buf)); + } + } else { + write_all(data->fd, log, strlen(log)); + } + + data->prefix = "\n"; +} + +void log_dump_to_file(int fd, const struct log_record *lr) +{ + const struct log_entry *i; + char buf[100]; + struct log_data data; + time_t start; + + i = list_top(&lr->log, const struct log_entry, list); + if (!i) { + write_all(fd, "0 bytes:\n\n", strlen("0 bytes:\n\n")); + return; + } + + start = lr->init_time.ts.tv_sec; + sprintf(buf, "%zu bytes, %s", lr->mem_used, ctime(&start)); + write_all(fd, buf, strlen(buf)); + + /* ctime includes \n... WTF? */ + data.prefix = ""; + data.fd = fd; + log_each_line(lr, log_one_line, &data); + write_all(fd, "\n\n", strlen("\n\n")); +} diff --git a/daemon/log.h b/daemon/log.h new file mode 100644 index 000000000..5cc20c198 --- /dev/null +++ b/daemon/log.h @@ -0,0 +1,82 @@ +#ifndef LIGHTNING_DAEMON_LOG_H +#define LIGHTNING_DAEMON_LOG_H +#include "config.h" +#include +#include +#include + +struct timerel; + +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 have a single record. */ +struct log_record *new_log_record(const tal_t *ctx, + size_t max_mem, + enum log_level printlevel); + +/* With different entry points */ +struct log *PRINTF_FMT(3,4) +new_log(const tal_t *ctx, struct log_record *record, const char *fmt, ...); + +#define log_debug(log, ...) log_((log), LOG_DBG, __VA_ARGS__) +#define log_info(log, ...) log_((log), LOG_INFORM, __VA_ARGS__) +#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_(struct log *log, enum log_level level, const char *fmt, ...) + PRINTF_FMT(3,4); +void log_add(struct log *log, const char *fmt, ...) PRINTF_FMT(2,3); +void logv(struct log *log, enum log_level level, const char *fmt, va_list ap); + +#define log_add_struct(log, structtype, ptr) \ + log_add_struct_((log), stringify(structtype), \ + ((void)sizeof((ptr) == (structtype *)NULL), (ptr))) + +#define log_add_enum(log, enumtype, val) \ + log_add_enum_((log), stringify(enumtype), (val)) + +void log_add_struct_(struct log *log, const char *structname, const void *ptr); +void log_add_enum_(struct log *log, const char *enumname, unsigned int val); + +void set_log_level(struct log_record *lr, enum log_level level); +void set_log_prefix(struct log *log, const char *prefix); +const char *log_prefix(const struct log *log); + +size_t log_max_mem(const struct log_record *lr); +size_t log_used(const struct log_record *lr); +const struct timeabs *log_init_time(const struct log_record *lr); + +#define log_each_line(lr, func, arg) \ + log_each_line_((lr), \ + typesafe_cb_preargs(void, void *, (func), (arg), \ + unsigned int, \ + struct timerel, \ + enum log_level, \ + const char *, \ + const char *), (arg)) + +void log_each_line_(const struct log_record *lr, + void (*func)(unsigned int skipped, + struct timerel time, + enum log_level level, + const char *prefix, + const char *log, + void *arg), + void *arg); + + +void log_dump_to_file(int fd, const struct log_record *lr); +#endif /* LIGHTNING_DAEMON_LOG_H */ diff --git a/daemon/pseudorand.c b/daemon/pseudorand.c new file mode 100644 index 000000000..27394eca3 --- /dev/null +++ b/daemon/pseudorand.c @@ -0,0 +1,28 @@ +#include "pseudorand.h" +#include +#include +#include +#include +#include +#include +#include + +static struct isaac64_ctx isaac64; +static bool pseudorand_initted = false; + +uint64_t pseudorand(uint64_t max) +{ + if (unlikely(!pseudorand_initted)) { + unsigned char seedbuf[16]; + + /* PRNG */ + if (RAND_bytes(seedbuf, sizeof(seedbuf)) != 1) + errx(1, "Could not seed PRNG: %s", + ERR_error_string(ERR_get_error(), NULL)); + + isaac64_init(&isaac64, seedbuf, sizeof(seedbuf)); + pseudorand_initted = true; + } + assert(max); + return isaac64_next_uint(&isaac64, max); +} diff --git a/daemon/pseudorand.h b/daemon/pseudorand.h new file mode 100644 index 000000000..50c233ff0 --- /dev/null +++ b/daemon/pseudorand.h @@ -0,0 +1,10 @@ +#ifndef LIGHTNING_DAEMON_PSEUDORAND_H +#define LIGHTNING_DAEMON_PSEUDORAND_H +#include "config.h" +#include + +/** + * pseudorand - pseudo (guessable!) random number between 0 and max-1. + */ +uint64_t pseudorand(uint64_t max); +#endif /* LIGHTNING_DAEMON_PSEUDORAND_H */