638 lines
15 KiB
C
638 lines
15 KiB
C
/*
|
|
* Copyright (c) 2018 Nordic Semiconductor ASA
|
|
*
|
|
* SPDX-License-Identifier: Apache-2.0
|
|
*/
|
|
|
|
#include <logging/log_output.h>
|
|
#include <logging/log_ctrl.h>
|
|
#include <logging/log.h>
|
|
#include <assert.h>
|
|
#include <ctype.h>
|
|
#include <time.h>
|
|
#include <stdio.h>
|
|
#include <stdbool.h>
|
|
|
|
#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 8
|
|
|
|
#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 < 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 < 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;
|
|
}
|