subsys/logging/log_output.c

/*
 * Copyright (c) 2018 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr/logging/log_output.h>
#include <zephyr/logging/log_ctrl.h>
#include <zephyr/logging/log_output_custom.h>
#include <zephyr/logging/log.h>
#include <zephyr/sys/__assert.h>
#include <zephyr/sys/cbprintf.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_GREEN   "\x1B[1;32m"
#define LOG_COLOR_CODE_YELLOW  "\x1B[1;33m"

#define HEXDUMP_BYTES_IN_LINE 16

#define  DROPPED_COLOR_PREFIX \
	COND_CODE_1(CONFIG_LOG_BACKEND_SHOW_COLOR, (LOG_COLOR_CODE_RED), ())

#define DROPPED_COLOR_POSTFIX \
	COND_CODE_1(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 */
	IS_ENABLED(CONFIG_LOG_INFO_COLOR_GREEN) ? LOG_COLOR_CODE_GREEN : NULL,   /* info */
	NULL                    /* dbg */
};

static uint32_t freq;
static log_timestamp_t timestamp_div;

#define SECONDS_IN_DAY			86400U

static uint32_t days_in_month[12] = {31, 28, 31, 30, 31, 30, 31,
									31, 30, 31, 30, 31};

struct YMD_date {
	uint32_t year;
	uint32_t month;
	uint32_t day;
};

/* 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(uint32_t level)
{
	uint8_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;
	int idx;

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		/* Backend must be thread safe in synchronous operation. */
		/* Need that step for big endian */
		char x = (char)c;

		out_ctx->func((uint8_t *)&x, 1, out_ctx->control_block->ctx);
		return 0;
	}

	if (out_ctx->control_block->offset == out_ctx->size) {
		log_output_flush(out_ctx);
	}

	idx = atomic_inc(&out_ctx->control_block->offset);
	out_ctx->buf[idx] = (uint8_t)c;

	__ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size);

	return 0;
}

static int cr_out_func(int c, void *ctx)
{
	if (c == '\n') {
		out_func((int)'\r', ctx);
	}
	out_func(c, ctx);

	return 0;
}

static int print_formatted(const struct log_output *output,
			   const char *fmt, ...)
{
	va_list args;
	int length = 0;

	va_start(args, fmt);
	length = cbvprintf(out_func, (void *)output, fmt, args);
	va_end(args);

	return length;
}

static void buffer_write(log_output_func_t outf, uint8_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 *output)
{
	buffer_write(output->func, output->buf,
		     output->control_block->offset,
		     output->control_block->ctx);

	output->control_block->offset = 0;
}

static inline bool is_leap_year(uint32_t year)
{
	return (((year % 4 == 0) && (year % 100 != 0)) || (year % 400 == 0));
}

static void __attribute__((unused)) get_YMD_from_seconds(uint64_t seconds,
			struct YMD_date *output_date)
{
	uint64_t tmp;
	int i;

	output_date->year = 1970;
	output_date->month = 1;
	output_date->day = 1;

	/* compute the proper year */
	while (1) {
		tmp = (is_leap_year(output_date->year)) ?
					366*SECONDS_IN_DAY : 365*SECONDS_IN_DAY;
		if (tmp > seconds) {
			break;
		}
		seconds -= tmp;
		output_date->year++;
	}
	/* compute the proper month */
	for (i = 0; i < ARRAY_SIZE(days_in_month); i++) {
		tmp = ((i == 1) && is_leap_year(output_date->year)) ?
					((uint64_t)days_in_month[i] + 1) * SECONDS_IN_DAY :
					(uint64_t)days_in_month[i] * SECONDS_IN_DAY;
		if (tmp > seconds) {
			output_date->month += i;
			break;
		}
		seconds -= tmp;
	}

	output_date->day += seconds / SECONDS_IN_DAY;
}

static int timestamp_print(const struct log_output *output,
			   uint32_t flags, log_timestamp_t timestamp)
{
	int length;
	bool format =
		(flags & LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP) |
		(flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) |
		IS_ENABLED(CONFIG_LOG_OUTPUT_FORMAT_LINUX_TIMESTAMP) |
		IS_ENABLED(CONFIG_LOG_OUTPUT_FORMAT_CUSTOM_TIMESTAMP);


	if (!format) {
#ifndef CONFIG_LOG_TIMESTAMP_64BIT
		length = print_formatted(output, "[%08lu] ", timestamp);
#else
		length = print_formatted(output, "[%016llu] ", timestamp);
#endif
	} else if (freq != 0U) {
#ifndef CONFIG_LOG_TIMESTAMP_64BIT
		uint32_t total_seconds;
#else
		uint64_t total_seconds;
#endif
		uint32_t remainder;
		uint32_t seconds;
		uint32_t hours;
		uint32_t mins;
		uint32_t ms;
		uint32_t us;

		timestamp /= timestamp_div;
		total_seconds = timestamp / freq;
		seconds = total_seconds;
		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_OUTPUT_FORMAT_CUSTOM_TIMESTAMP)) {
			length = log_custom_timestamp_print(output, timestamp, print_formatted);
		} else 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 = total_seconds;
			tm = gmtime(&time);

			strftime(time_str, sizeof(time_str), "%FT%T", tm);

			length = print_formatted(output, "%s.%06uZ ",
						 time_str, ms * 1000U + us);
#else
			struct YMD_date date;

			get_YMD_from_seconds(total_seconds, &date);
			hours = hours % 24;
			length = print_formatted(output,
					"%04u-%02u-%02uT%02u:%02u:%02u.%06uZ ",
					date.year, date.month, date.day,
					hours, mins, seconds, ms * 1000U + us);
#endif
		} else {
			if (IS_ENABLED(CONFIG_LOG_OUTPUT_FORMAT_LINUX_TIMESTAMP)) {
				length = print_formatted(output,
#if defined(CONFIG_LOG_TIMESTAMP_64BIT)
							"[%5llu.%06d] ",
#else
							"[%5lu.%06d] ",
#endif
							total_seconds, ms * 1000U + us);
			} else {
				length = print_formatted(output,
							"[%02u:%02u:%02u.%03u,%03u] ",
							hours, mins, seconds, ms, us);
			}
		}
	} else {
		length = 0;
	}

	return length;
}

static void color_print(const struct log_output *output,
			bool color, bool start, uint32_t level)
{
	if (color) {
		const char *log_color = start && (colors[level] != NULL) ?
				colors[level] : LOG_COLOR_CODE_DEFAULT;
		print_formatted(output, "%s", log_color);
	}
}

static void color_prefix(const struct log_output *output,
			 bool color, uint32_t level)
{
	color_print(output, color, true, level);
}

static void color_postfix(const struct log_output *output,
			  bool color, uint32_t level)
{
	color_print(output, color, false, level);
}


static int ids_print(const struct log_output *output,
		     bool level_on,
		     bool func_on,
		     bool thread_on,
		     const char *domain,
		     const char *source,
		     k_tid_t tid,
		     uint32_t level)
{
	int total = 0;

	if (level_on) {
		total += print_formatted(output, "<%s> ", severity[level]);
	}

	if (IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX) && thread_on) {
		if (IS_ENABLED(CONFIG_THREAD_NAME)) {
			total += print_formatted(output, "[%s] ",
				tid == NULL ? "irq" : k_thread_name_get(tid));
		} else {
			total += print_formatted(output, "[%p] ", tid);
		}
	}

	if (domain) {
		total += print_formatted(output, "%s/", domain);
	}

	if (source) {
		total += print_formatted(output,
				(func_on &&
				((1 << level) & LOG_FUNCTION_PREFIX_MASK)) ?
				"%s." : "%s: ",
				source);
	}

	return total;
}

static void newline_print(const struct log_output *ctx, uint32_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 hexdump_line_print(const struct log_output *output,
			       const uint8_t *data, uint32_t length,
			       int prefix_offset, uint32_t flags)
{
	newline_print(output, flags);

	for (int i = 0; i < prefix_offset; i++) {
		print_formatted(output, " ");
	}

	for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) {
		if (i > 0 && !(i % 8)) {
			print_formatted(output, " ");
		}

		if (i < length) {
			print_formatted(output, "%02x ", data[i]);
		} else {
			print_formatted(output, "   ");
		}
	}

	print_formatted(output, "|");

	for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) {
		if (i > 0 && !(i % 8)) {
			print_formatted(output, " ");
		}

		if (i < length) {
			unsigned char c = (unsigned char)data[i];

			print_formatted(output, "%c",
			      isprint((int)c) != 0 ? c : '.');
		} else {
			print_formatted(output, " ");
		}
	}
}

static void log_msg_hexdump(const struct log_output *output,
			    uint8_t *data, uint32_t len,
			    int prefix_offset, uint32_t flags)
{
	size_t length;

	do {
		length = MIN(len, HEXDUMP_BYTES_IN_LINE);

		hexdump_line_print(output, data, length,
				   prefix_offset, flags);
		data += length;
		len -= length;
	} while (len);
}

static uint32_t prefix_print(const struct log_output *output,
			     uint32_t flags,
			     bool func_on,
			     log_timestamp_t timestamp,
			     const char *domain,
			     const char *source,
			     k_tid_t tid,
			     uint8_t level)
{
	__ASSERT_NO_MSG(level <= LOG_LEVEL_DBG);
	uint32_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;
	bool thread_on = IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX) &&
			 (flags & LOG_OUTPUT_FLAG_THREAD);
	bool source_off = flags & LOG_OUTPUT_FLAG_SKIP_SOURCE;
	const char *tag = IS_ENABLED(CONFIG_LOG) ? z_log_get_tag() : NULL;

	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(
			output,
			"<%d>1 ",
			facility * 8 +
			level_to_rfc5424_severity(level));
	}

	if (tag) {
		length += print_formatted(output, "%s ", tag);
	}

	if (stamp) {
		length += timestamp_print(output, flags, timestamp);
	}

	if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) &&
	    flags & LOG_OUTPUT_FLAG_FORMAT_SYSLOG) {
		length += print_formatted(
			output, "%s - - - - ",
			output->control_block->hostname ?
			output->control_block->hostname :
			"zephyr");
	} else {
		color_prefix(output, colors_on, level);
	}

	length += ids_print(output, level_on, func_on, thread_on, domain,
			    source_off ? NULL : source, tid, level);

	return length;
}

static void postfix_print(const struct log_output *output,
			  uint32_t flags, uint8_t level)
{
	color_postfix(output, (flags & LOG_OUTPUT_FLAG_COLORS),
			      level);
	newline_print(output, flags);
}

void log_output_process(const struct log_output *output,
			log_timestamp_t timestamp,
			const char *domain,
			const char *source,
			k_tid_t tid,
			uint8_t level,
			const uint8_t *package,
			const uint8_t *data,
			size_t data_len,
			uint32_t flags)
{
	bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING);
	uint32_t prefix_offset;
	cbprintf_cb cb;

	if (!raw_string) {
		prefix_offset = prefix_print(output, flags, 0, timestamp,
					     domain, source, tid, level);
		cb = out_func;
	} else {
		prefix_offset = 0;
		/* source set to 1 indicates raw string and contrary to printk
		 * case it should not append anything to the output (printk is
		 * appending <CR> to the new line character).
		 */
		cb = ((uintptr_t)source == 1) ? out_func : cr_out_func;
	}

	if (package) {
		int err = cbpprintf(cb, (void *)output, (void *)package);

		(void)err;
		__ASSERT_NO_MSG(err >= 0);
	}

	if (data_len) {
		log_msg_hexdump(output, (uint8_t *)data, data_len, prefix_offset, flags);
	}

	if (!raw_string) {
		postfix_print(output, flags, level);
	}

	log_output_flush(output);
}

void log_output_msg_process(const struct log_output *output,
			    struct log_msg *msg, uint32_t flags)
{
	log_timestamp_t timestamp = log_msg_get_timestamp(msg);
	uint8_t level = log_msg_get_level(msg);
	uint8_t domain_id = log_msg_get_domain(msg);
	int16_t source_id;

	if (IS_ENABLED(CONFIG_LOG_MULTIDOMAIN) && domain_id != Z_LOG_LOCAL_DOMAIN_ID) {
		/* Remote domain is converting source pointer to ID */
		source_id = (int16_t)(uintptr_t)log_msg_get_source(msg);
	} else {
		void *source = (void *)log_msg_get_source(msg);

		if (source != NULL) {
			source_id = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ?
					log_dynamic_source_id(source) :
					log_const_source_id(source);
		} else {
			source_id = -1;
		}
	}

	const char *sname = source_id >= 0 ? log_source_name_get(domain_id, source_id) : NULL;
	size_t plen, dlen;
	uint8_t *package = log_msg_get_package(msg, &plen);
	uint8_t *data = log_msg_get_data(msg, &dlen);

	log_output_process(output, timestamp, NULL, sname, (k_tid_t)log_msg_get_tid(msg), level,
			   plen > 0 ? package : NULL, data, dlen, flags);
}

void log_output_dropped_process(const struct log_output *output, uint32_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 = output->func;

	cnt = MIN(cnt, 9999);
	len = snprintk(buf, sizeof(buf), "%d", cnt);

	buffer_write(outf, (uint8_t *)prefix, sizeof(prefix) - 1,
		     output->control_block->ctx);
	buffer_write(outf, buf, len, output->control_block->ctx);
	buffer_write(outf, (uint8_t *)postfix, sizeof(postfix) - 1,
		     output->control_block->ctx);
}

void log_output_timestamp_freq_set(uint32_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;
}

uint64_t log_output_timestamp_to_us(log_timestamp_t timestamp)
{
	timestamp /= timestamp_div;

	return ((uint64_t) timestamp * 1000000U) / freq;
}