/* * Copyright (c) 2018 Nordic Semiconductor ASA * * SPDX-License-Identifier: Apache-2.0 */ #include #include #include #include #include #include #include #include #define LOG_COLOR_CODE_DEFAULT "\x1B[0m" #define LOG_COLOR_CODE_RED "\x1B[1;31m" #define LOG_COLOR_CODE_YELLOW "\x1B[1;33m" #define HEXDUMP_BYTES_IN_LINE 16 #define DROPPED_COLOR_PREFIX \ Z_LOG_EVAL(CONFIG_LOG_BACKEND_SHOW_COLOR, (LOG_COLOR_CODE_RED), ()) #define DROPPED_COLOR_POSTFIX \ Z_LOG_EVAL(CONFIG_LOG_BACKEND_SHOW_COLOR, (LOG_COLOR_CODE_DEFAULT), ()) static const char *const severity[] = { NULL, "err", "wrn", "inf", "dbg" }; static const char *const colors[] = { NULL, LOG_COLOR_CODE_RED, /* err */ LOG_COLOR_CODE_YELLOW, /* warn */ NULL, /* info */ NULL /* dbg */ }; static u32_t freq; static u32_t timestamp_div; typedef int (*out_func_t)(int c, void *ctx); extern int z_prf(int (*func)(), void *dest, char *format, va_list vargs); extern void z_vprintk(out_func_t out, void *log_output, const char *fmt, va_list ap); /* The RFC 5424 allows very flexible mapping and suggest the value 0 being the * highest severity and 7 to be the lowest (debugging level) severity. * * 0 Emergency System is unusable * 1 Alert Action must be taken immediately * 2 Critical Critical conditions * 3 Error Error conditions * 4 Warning Warning conditions * 5 Notice Normal but significant condition * 6 Informational Informational messages * 7 Debug Debug-level messages */ static int level_to_rfc5424_severity(u32_t level) { u8_t ret; switch (level) { case LOG_LEVEL_NONE: ret = 7U; break; case LOG_LEVEL_ERR: ret = 3U; break; case LOG_LEVEL_WRN: ret = 4U; break; case LOG_LEVEL_INF: ret = 6U; break; case LOG_LEVEL_DBG: ret = 7U; break; default: ret = 7U; break; } return ret; } static int out_func(int c, void *ctx) { const struct log_output *out_ctx = (const struct log_output *)ctx; out_ctx->buf[out_ctx->control_block->offset] = (u8_t)c; out_ctx->control_block->offset++; __ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size); if (out_ctx->control_block->offset == out_ctx->size) { log_output_flush(out_ctx); } return 0; } static int print_formatted(const struct log_output *log_output, const char *fmt, ...) { va_list args; int length = 0; va_start(args, fmt); #if !defined(CONFIG_NEWLIB_LIBC) && !defined(CONFIG_ARCH_POSIX) && \ defined(CONFIG_LOG_ENABLE_FANCY_OUTPUT_FORMATTING) length = z_prf(out_func, (void *)log_output, (char *)fmt, args); #else z_vprintk(out_func, (void *)log_output, fmt, args); #endif va_end(args); return length; } static void buffer_write(log_output_func_t outf, u8_t *buf, size_t len, void *ctx) { int processed; do { processed = outf(buf, len, ctx); len -= processed; buf += processed; } while (len != 0); } void log_output_flush(const struct log_output *log_output) { buffer_write(log_output->func, log_output->buf, log_output->control_block->offset, log_output->control_block->ctx); log_output->control_block->offset = 0; } static int timestamp_print(const struct log_output *log_output, u32_t flags, u32_t timestamp) { int length; bool format = (flags & LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP) | (flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG); if (!format) { length = print_formatted(log_output, "[%08lu] ", timestamp); } else if (freq != 0U) { u32_t remainder; u32_t seconds; u32_t hours; u32_t mins; u32_t ms; u32_t us; timestamp /= timestamp_div; seconds = timestamp / freq; hours = seconds / 3600U; seconds -= hours * 3600U; mins = seconds / 60U; seconds -= mins * 60U; remainder = timestamp % freq; ms = (remainder * 1000U) / freq; us = (1000 * (remainder * 1000U - (ms * freq))) / freq; if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) && flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) { #if defined(CONFIG_NEWLIB_LIBC) char time_str[sizeof("1970-01-01T00:00:00")]; struct tm *tm; time_t time; time = seconds; tm = gmtime(&time); strftime(time_str, sizeof(time_str), "%FT%T", tm); length = print_formatted(log_output, "%s.%06dZ ", time_str, ms * 1000U + us); #else length = print_formatted(log_output, "1970-01-01T%02d:%02d:%02d.%06dZ ", hours, mins, seconds, ms * 1000U + us); #endif } else { length = print_formatted(log_output, "[%02d:%02d:%02d.%03d,%03d] ", hours, mins, seconds, ms, us); } } else { length = 0; } return length; } static void color_print(const struct log_output *log_output, bool color, bool start, u32_t level) { if (color) { const char *color = start && (colors[level] != NULL) ? colors[level] : LOG_COLOR_CODE_DEFAULT; print_formatted(log_output, "%s", color); } } static void color_prefix(const struct log_output *log_output, bool color, u32_t level) { color_print(log_output, color, true, level); } static void color_postfix(const struct log_output *log_output, bool color, u32_t level) { color_print(log_output, color, false, level); } static int ids_print(const struct log_output *log_output, bool level_on, bool func_on, u32_t domain_id, u32_t source_id, u32_t level) { int total = 0; if (level_on) { total += print_formatted(log_output, "<%s> ", severity[level]); } total += print_formatted(log_output, (func_on && ((1 << level) & LOG_FUNCTION_PREFIX_MASK)) ? "%s." : "%s: ", log_source_name_get(domain_id, source_id)); return total; } static void newline_print(const struct log_output *ctx, u32_t flags) { if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) && flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) { return; } if ((flags & LOG_OUTPUT_FLAG_CRLF_NONE) != 0U) { return; } if ((flags & LOG_OUTPUT_FLAG_CRLF_LFONLY) != 0U) { print_formatted(ctx, "\n"); } else { print_formatted(ctx, "\r\n"); } } static void std_print(struct log_msg *msg, const struct log_output *log_output) { const char *str = log_msg_str_get(msg); u32_t nargs = log_msg_nargs_get(msg); u32_t *args = alloca(sizeof(u32_t)*nargs); int i; for (i = 0; i < nargs; i++) { args[i] = log_msg_arg_get(msg, i); } switch (log_msg_nargs_get(msg)) { case 0: print_formatted(log_output, str); break; case 1: print_formatted(log_output, str, args[0]); break; case 2: print_formatted(log_output, str, args[0], args[1]); break; case 3: print_formatted(log_output, str, args[0], args[1], args[2]); break; case 4: print_formatted(log_output, str, args[0], args[1], args[2], args[3]); break; case 5: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4]); break; case 6: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5]); break; case 7: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6]); break; case 8: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7]); break; case 9: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8]); break; case 10: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9]); break; case 11: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10]); break; case 12: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11]); break; case 13: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12]); break; case 14: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13]); break; case 15: print_formatted(log_output, str, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13], args[14]); break; default: /* Unsupported number of arguments. */ __ASSERT_NO_MSG(true); break; } } static void hexdump_line_print(const struct log_output *log_output, const u8_t *data, u32_t length, int prefix_offset, u32_t flags) { newline_print(log_output, flags); for (int i = 0; i < prefix_offset; i++) { print_formatted(log_output, " "); } for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { if (i > 0 && !(i % 8)) { print_formatted(log_output, " "); } if (i < length) { print_formatted(log_output, "%02x ", data[i]); } else { print_formatted(log_output, " "); } } print_formatted(log_output, "|"); for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { if (i > 0 && !(i % 8)) { print_formatted(log_output, " "); } if (i < length) { char c = (char)data[i]; print_formatted(log_output, "%c", isprint((int)c) ? c : '.'); } else { print_formatted(log_output, " "); } } } static void hexdump_print(struct log_msg *msg, const struct log_output *log_output, int prefix_offset, u32_t flags) { u32_t offset = 0U; u8_t buf[HEXDUMP_BYTES_IN_LINE]; size_t length; print_formatted(log_output, "%s", log_msg_str_get(msg)); do { length = sizeof(buf); log_msg_hexdump_data_get(msg, buf, &length, offset); if (length) { hexdump_line_print(log_output, buf, length, prefix_offset, flags); offset += length; } else { break; } } while (true); } static void raw_string_print(struct log_msg *msg, const struct log_output *log_output) { __ASSERT_NO_MSG(log_output->size); size_t offset = 0; size_t length; bool eol = false; do { length = log_output->size; /* Sting is stored in a hexdump message. */ log_msg_hexdump_data_get(msg, log_output->buf, &length, offset); log_output->control_block->offset = length; if (length != 0) { eol = (log_output->buf[length - 1] == '\n'); } log_output_flush(log_output); offset += length; } while (length > 0); if (eol) { print_formatted(log_output, "\r"); } } static u32_t prefix_print(const struct log_output *log_output, u32_t flags, bool func_on, u32_t timestamp, u8_t level, u8_t domain_id, u16_t source_id) { u32_t length = 0U; bool stamp = flags & LOG_OUTPUT_FLAG_TIMESTAMP; bool colors_on = flags & LOG_OUTPUT_FLAG_COLORS; bool level_on = flags & LOG_OUTPUT_FLAG_LEVEL; if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) && flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) { /* TODO: As there is no way to figure out the * facility at this point, use a pre-defined value. * Change this to use the real facility of the * logging call when that info is available. */ static const int facility = 16; /* local0 */ length += print_formatted( log_output, "<%d>1 ", facility * 8 + level_to_rfc5424_severity(level)); } if (stamp) { length += timestamp_print(log_output, flags, timestamp); } if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) && flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) { length += print_formatted( log_output, "%s - - - - ", log_output->control_block->hostname ? log_output->control_block->hostname : "zephyr"); } else { color_prefix(log_output, colors_on, level); length += ids_print(log_output, level_on, func_on, domain_id, source_id, level); } return length; } static void postfix_print(const struct log_output *log_output, u32_t flags, u8_t level) { color_postfix(log_output, (flags & LOG_OUTPUT_FLAG_COLORS), level); newline_print(log_output, flags); } void log_output_msg_process(const struct log_output *log_output, struct log_msg *msg, u32_t flags) { bool std_msg = log_msg_is_std(msg); u32_t timestamp = log_msg_timestamp_get(msg); u8_t level = (u8_t)log_msg_level_get(msg); u8_t domain_id = (u8_t)log_msg_domain_id_get(msg); u16_t source_id = (u16_t)log_msg_source_id_get(msg); bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING); int prefix_offset; prefix_offset = raw_string ? 0 : prefix_print(log_output, flags, std_msg, timestamp, level, domain_id, source_id); if (log_msg_is_std(msg)) { std_print(msg, log_output); } else if (raw_string) { raw_string_print(msg, log_output); } else { hexdump_print(msg, log_output, prefix_offset, flags); } if (!raw_string) { postfix_print(log_output, flags, level); } log_output_flush(log_output); } static bool ends_with_newline(const char *fmt) { char c = '\0'; while (*fmt != '\0') { c = *fmt; fmt++; } return (c == '\n'); } void log_output_string(const struct log_output *log_output, struct log_msg_ids src_level, u32_t timestamp, const char *fmt, va_list ap, u32_t flags) { int length; u8_t level = (u8_t)src_level.level; u8_t domain_id = (u8_t)src_level.domain_id; u16_t source_id = (u16_t)src_level.source_id; bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING); if (!raw_string) { prefix_print(log_output, flags, true, timestamp, level, domain_id, source_id); } #if !defined(CONFIG_NEWLIB_LIBC) && !defined(CONFIG_ARCH_POSIX) && \ defined(CONFIG_LOG_ENABLE_FANCY_OUTPUT_FORMATTING) length = z_prf(out_func, (void *)log_output, (char *)fmt, ap); #else z_vprintk(out_func, (void *)log_output, fmt, ap); #endif (void)length; if (raw_string) { /* add \r if string ends with newline. */ if (ends_with_newline(fmt)) { print_formatted(log_output, "\r"); } } else { postfix_print(log_output, flags, level); } log_output_flush(log_output); } void log_output_hexdump(const struct log_output *log_output, struct log_msg_ids src_level, u32_t timestamp, const char *metadata, const u8_t *data, u32_t length, u32_t flags) { u32_t prefix_offset; u8_t level = (u8_t)src_level.level; u8_t domain_id = (u8_t)src_level.domain_id; u16_t source_id = (u16_t)src_level.source_id; prefix_offset = prefix_print(log_output, flags, true, timestamp, level, domain_id, source_id); /* Print metadata */ print_formatted(log_output, "%s", metadata); while (length) { u32_t part_len = length > HEXDUMP_BYTES_IN_LINE ? HEXDUMP_BYTES_IN_LINE : length; hexdump_line_print(log_output, data, part_len, prefix_offset, flags); data += part_len; length -= part_len; }; postfix_print(log_output, flags, level); log_output_flush(log_output); } void log_output_dropped_process(const struct log_output *log_output, u32_t cnt) { char buf[5]; int len; static const char prefix[] = DROPPED_COLOR_PREFIX "--- "; static const char postfix[] = " messages dropped ---\r\n" DROPPED_COLOR_POSTFIX; log_output_func_t outf = log_output->func; struct device *dev = (struct device *)log_output->control_block->ctx; cnt = MIN(cnt, 9999); len = snprintf(buf, sizeof(buf), "%d", cnt); buffer_write(outf, (u8_t *)prefix, sizeof(prefix) - 1, dev); buffer_write(outf, buf, len, dev); buffer_write(outf, (u8_t *)postfix, sizeof(postfix) - 1, dev); } void log_output_timestamp_freq_set(u32_t frequency) { timestamp_div = 1U; /* There is no point to have frequency higher than 1MHz (ns are not * printed) and too high frequency leads to overflows in calculations. */ while (frequency > 1000000) { frequency /= 2U; timestamp_div *= 2U; } freq = frequency; }