/* * Copyright (c) 2017 Richard Braun. * * This program is free software: you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation, either version 3 of the License, or * (at your option) any later version. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with this program. If not, see . */ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #define LOG_BUFFER_SIZE 16384 #if !ISP2(LOG_BUFFER_SIZE) #error "log buffer size must be a power-of-two" #endif #define LOG_MSG_SIZE 128 #define LOG_MARKER 0x1 static struct thread *log_thread; static struct cbuf log_cbuf; static char log_buffer[LOG_BUFFER_SIZE]; /* * This index is used by the log thread to report what it has consumed * so that producers can detect overruns. */ static size_t log_index; static size_t log_nr_overruns; static unsigned int log_print_level; /* * Global lock. * * Interrupts must be disabled when holding this lock. */ static struct spinlock log_lock; /* * A record starts with a marker byte and ends with a null terminating byte. * * There must be no null byte inside the header, and the buffer is expected * to be a standard null-terminated string. */ struct log_record { uint8_t mark; uint8_t level; char buffer[LOG_MSG_SIZE]; }; /* * A consumer context allows faster, buffered reads of the circular buffer, * by retaining bytes that weren't consumed in case a read spans multiple * records. */ struct log_consume_ctx { struct cbuf *cbuf; size_t cbuf_index; char buf[LOG_MSG_SIZE]; size_t index; size_t size; }; static void log_consume_ctx_init(struct log_consume_ctx *ctx, struct cbuf *cbuf) { ctx->cbuf = cbuf; ctx->cbuf_index = cbuf_start(cbuf); ctx->index = 0; ctx->size = 0; } static size_t log_consume_ctx_index(const struct log_consume_ctx *ctx) { return ctx->cbuf_index; } static void log_consume_ctx_set_index(struct log_consume_ctx *ctx, size_t index) { ctx->cbuf_index = index; } static bool log_consume_ctx_empty(const struct log_consume_ctx *ctx) { return ctx->cbuf_index == cbuf_end(ctx->cbuf); } static int log_consume_ctx_pop(struct log_consume_ctx *ctx, char *byte) { int error; if (ctx->index >= ctx->size) { ctx->index = 0; ctx->size = sizeof(ctx->buf); error = cbuf_read(ctx->cbuf, ctx->cbuf_index, ctx->buf, &ctx->size); if (error) { ctx->cbuf_index = cbuf_start(ctx->cbuf); return error; } } ctx->cbuf_index++; *byte = ctx->buf[ctx->index]; ctx->index++; return 0; } static const char * log_level2str(unsigned int level) { switch (level) { case LOG_EMERG: return "emerg"; case LOG_ALERT: return "alert"; case LOG_CRIT: return "crit"; case LOG_ERR: return "error"; case LOG_WARNING: return "warning"; case LOG_NOTICE: return "notice"; case LOG_INFO: return "info"; case LOG_DEBUG: return "debug"; default: return NULL; } } static char log_level2char(unsigned int level) { assert(level < LOG_NR_LEVELS); return '0' + level; } static uint8_t log_char2level(char c) { uint8_t level; level = c - '0'; assert(level < LOG_NR_LEVELS); return level; } static void log_record_init_produce(struct log_record *record, unsigned int level) { record->mark = LOG_MARKER; record->level = log_level2char(level); } static void log_record_consume(struct log_record *record, char c, size_t *sizep) { char *ptr; assert(*sizep < sizeof(*record)); ptr = (char *)record; ptr[*sizep] = c; (*sizep)++; } static int log_record_init_consume(struct log_record *record, struct log_consume_ctx *ctx) { bool marker_found; size_t size; int error; char c; marker_found = false; size = 0; for (;;) { if (log_consume_ctx_empty(ctx)) { if (!marker_found) { return EINVAL; } break; } error = log_consume_ctx_pop(ctx, &c); if (error) { continue; } if (!marker_found) { if (c != LOG_MARKER) { continue; } marker_found = true; log_record_consume(record, c, &size); continue; } else if (size == offsetof(struct log_record, level)) { record->level = log_char2level(c); size++; continue; } log_record_consume(record, c, &size); if (c == '\0') { break; } } return 0; } static void log_record_print(const struct log_record *record, unsigned int level) { if (record->level > level) { return; } if (record->level <= LOG_WARNING) { printf("%7s %s\n", log_level2str(record->level), record->buffer); } else { printf("%s\n", record->buffer); } } #ifdef CONFIG_SHELL static void log_start_shell(unsigned long *flags) { static bool shell_started = false; if (shell_started) { return; } spinlock_unlock_intr_restore(&log_lock, *flags); shell_start(); spinlock_lock_intr_save(&log_lock, flags); shell_started = true; } #else /* CONFIG_SHELL */ #define log_start_shell(flags) #endif /* CONFIG_SHELL*/ static void log_run(void *arg) { unsigned long flags, nr_overruns; struct log_consume_ctx ctx; struct log_record record; int error; (void)arg; nr_overruns = 0; spinlock_lock_intr_save(&log_lock, &flags); log_consume_ctx_init(&ctx, &log_cbuf); for (;;) { while (log_consume_ctx_empty(&ctx)) { /* * Starting the shell after the log thread sleeps for the first * time cleanly serializes log messages and shell prompt, making * a clean ordered output. */ log_start_shell(&flags); log_index = log_consume_ctx_index(&ctx); thread_sleep(&log_lock, &log_cbuf, "log_cbuf"); log_consume_ctx_set_index(&ctx, log_index); } error = log_record_init_consume(&record, &ctx); /* Drain the log buffer before reporting overruns */ if (log_consume_ctx_empty(&ctx)) { nr_overruns = log_nr_overruns; log_nr_overruns = 0; } log_index = log_consume_ctx_index(&ctx); spinlock_unlock_intr_restore(&log_lock, flags); if (!error) { log_record_print(&record, log_print_level); } if (nr_overruns != 0) { log_msg(LOG_ERR, "log: buffer overruns, %lu bytes dropped", nr_overruns); nr_overruns = 0; } spinlock_lock_intr_save(&log_lock, &flags); log_consume_ctx_set_index(&ctx, log_index); } } #ifdef CONFIG_SHELL static void log_dump(unsigned int level) { struct log_consume_ctx ctx; struct log_record record; unsigned long flags; int error; spinlock_lock_intr_save(&log_lock, &flags); log_consume_ctx_init(&ctx, &log_cbuf); for (;;) { error = log_record_init_consume(&record, &ctx); if (error) { break; } spinlock_unlock_intr_restore(&log_lock, flags); log_record_print(&record, level); spinlock_lock_intr_save(&log_lock, &flags); } spinlock_unlock_intr_restore(&log_lock, flags); } static void log_shell_dump(int argc, char **argv) { unsigned int level; int ret; if (argc != 2) { level = log_print_level; } else { ret = sscanf(argv[1], "%u", &level); if ((ret != 1) || (level >= LOG_NR_LEVELS)) { printf("log: dump: invalid arguments\n"); return; } } log_dump(level); } static struct shell_cmd log_shell_cmds[] = { SHELL_CMD_INITIALIZER2("log_dump", log_shell_dump, "log_dump []", "dump the log buffer", "Only records of level less than or equal to the given level" " are printed. Level may be one of :\n" " 0: emergency\n" " 1: alert\n" " 2: critical\n" " 3: error\n" " 4: warning\n" " 5: notice\n" " 6: info\n" " 7: debug"), }; static int __init log_setup_shell(void) { SHELL_REGISTER_CMDS(log_shell_cmds); return 0; } INIT_OP_DEFINE(log_setup_shell, INIT_OP_DEP(log_setup, true), INIT_OP_DEP(shell_setup, true)); #endif /* CONFIG_SHELL */ static int __init log_setup(void) { cbuf_init(&log_cbuf, log_buffer, sizeof(log_buffer)); log_index = cbuf_start(&log_cbuf); spinlock_init(&log_lock); log_print_level = LOG_INFO; boot_log_info(); arg_log_info(); cpu_log_info(cpu_current()); return 0; } INIT_OP_DEFINE(log_setup, INIT_OP_DEP(arg_setup, true), INIT_OP_DEP(cpu_setup, true), INIT_OP_DEP(spinlock_setup, true)); static int __init log_start(void) { struct thread_attr attr; int error; thread_attr_init(&attr, THREAD_KERNEL_PREFIX "log_run"); thread_attr_set_detached(&attr); error = thread_create(&log_thread, &attr, log_run, NULL); if (error) { panic("log: unable to create thread"); } return 0; } INIT_OP_DEFINE(log_start, INIT_OP_DEP(log_setup, true), INIT_OP_DEP(panic_setup, true), INIT_OP_DEP(thread_setup, true)); static void log_write(const void *s, size_t size) { int error; error = cbuf_push(&log_cbuf, s, size, true); assert(!error); if (!cbuf_range_valid(&log_cbuf, log_index, log_index + 1)) { log_nr_overruns += cbuf_start(&log_cbuf) - log_index; log_index = cbuf_start(&log_cbuf); } } int log_msg(unsigned int level, const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vmsg(level, format, ap); va_end(ap); return ret; } int log_vmsg(unsigned int level, const char *format, va_list ap) { struct log_record record; unsigned long flags; int nr_chars; size_t size; char *ptr; log_record_init_produce(&record, level); nr_chars = vsnprintf(record.buffer, sizeof(record.buffer), format, ap); if ((unsigned int)nr_chars >= sizeof(record.buffer)) { log_msg(LOG_ERR, "log: message too large"); goto out; } ptr = strchr(record.buffer, '\n'); if (ptr != NULL) { *ptr = '\0'; nr_chars = ptr - record.buffer; } assert(nr_chars >= 0); size = offsetof(struct log_record, buffer) + nr_chars + 1; spinlock_lock_intr_save(&log_lock, &flags); log_write(&record, size); thread_wakeup(log_thread); spinlock_unlock_intr_restore(&log_lock, flags); out: return nr_chars; } int log_emerg(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vemerg(format, ap); va_end(ap); return ret; } int log_alert(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_valert(format, ap); va_end(ap); return ret; } int log_crit(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vcrit(format, ap); va_end(ap); return ret; } int log_err(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_verr(format, ap); va_end(ap); return ret; } int log_warning(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vwarning(format, ap); va_end(ap); return ret; } int log_notice(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vnotice(format, ap); va_end(ap); return ret; } int log_info(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vinfo(format, ap); va_end(ap); return ret; } int log_debug(const char *format, ...) { va_list ap; int ret; va_start(ap, format); ret = log_vdebug(format, ap); va_end(ap); return ret; } int log_vemerg(const char *format, va_list ap) { return log_vmsg(LOG_EMERG, format, ap); } int log_valert(const char *format, va_list ap) { return log_vmsg(LOG_ALERT, format, ap); } int log_vcrit(const char *format, va_list ap) { return log_vmsg(LOG_CRIT, format, ap); } int log_verr(const char *format, va_list ap) { return log_vmsg(LOG_ERR, format, ap); } int log_vwarning(const char *format, va_list ap) { return log_vmsg(LOG_WARNING, format, ap); } int log_vnotice(const char *format, va_list ap) { return log_vmsg(LOG_NOTICE, format, ap); } int log_vinfo(const char *format, va_list ap) { return log_vmsg(LOG_INFO, format, ap); } int log_vdebug(const char *format, va_list ap) { return log_vmsg(LOG_DEBUG, format, ap); }