src/logging.c

/*! \file logging.c
 * Debugging/Logging support code. */
/*
 * (C) 2008-2010 by Harald Welte <laforge@gnumonks.org>
 * (C) 2008 by Holger Hans Peter Freyther <zecke@selfish.org>
 * All Rights Reserved
 *
 * SPDX-License-Identifier: GPL-2.0+
 *
 * 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 2 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.
 *
 */

/*! \addtogroup logging
 * @{
 * libosmocore Logging sub-system
 *
 * \file logging.c */

#include "../config.h"

#include <stdarg.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <unistd.h>

#ifdef HAVE_STRINGS_H
#include <strings.h>
#endif

#ifdef HAVE_SYSLOG_H
#include <syslog.h>
#endif

#ifdef HAVE_SYSTEMTAP
/* include the generated probes header and put markers in code */
#include "probes.h"
#define TRACE(probe) probe
#define TRACE_ENABLED(probe) probe ## _ENABLED()
#else
/* Wrap the probe to allow it to be removed when no systemtap available */
#define TRACE(probe)
#define TRACE_ENABLED(probe) (0)
#endif /* HAVE_SYSTEMTAP */

#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <errno.h>
#include <pthread.h>

#include <osmocom/core/talloc.h>
#include <osmocom/core/utils.h>
#include <osmocom/core/logging.h>
#include <osmocom/core/timer.h>
#include <osmocom/core/thread.h>
#include <osmocom/core/select.h>
#include <osmocom/core/write_queue.h>

#include <osmocom/vty/logging.h>	/* for LOGGING_STR. */

/* maximum length of the log string of a single log event (typically  line) */
#define MAX_LOG_SIZE	4096

/* maximum number of log statements we queue in file/stderr target write queue */
#define LOG_WQUEUE_LEN	156

osmo_static_assert(_LOG_CTX_COUNT <= ARRAY_SIZE(((struct log_context*)NULL)->ctx),
		   enum_logging_ctx_items_fit_in_struct_log_context);
osmo_static_assert(_LOG_FLT_COUNT <= ARRAY_SIZE(((struct log_target*)NULL)->filter_data),
		   enum_logging_filters_fit_in_log_target_filter_data);
osmo_static_assert(_LOG_FLT_COUNT <= 8*sizeof(((struct log_target*)NULL)->filter_map),
		   enum_logging_filters_fit_in_log_target_filter_map);

struct log_info *osmo_log_info;

static struct log_context log_context;
void *tall_log_ctx = NULL;
LLIST_HEAD(osmo_log_target_list);

static __thread long int logging_tid;

#if (!EMBEDDED)
/*! This mutex must be held while using osmo_log_target_list or any of its
  log_targets in a multithread program. Prevents race conditions between threads
  like producing unordered timestamps or VTY deleting a target while another
  thread is writing to it */
static pthread_mutex_t osmo_log_tgt_mutex;
static bool osmo_log_tgt_mutex_on = false;

/*! Enable multithread support (mutex) in libosmocore logging system.
 * Must be called by processes willing to use logging subsystem from several
 * threads. Once enabled, it's not possible to disable it again.
 */
void log_enable_multithread(void) {
	if (osmo_log_tgt_mutex_on)
		return;
	pthread_mutex_init(&osmo_log_tgt_mutex, NULL);
	osmo_log_tgt_mutex_on = true;
}

/*! Acquire the osmo_log_tgt_mutex. Don't use this function directly, always use
 *  macro log_tgt_mutex_lock() instead.
 */
void log_tgt_mutex_lock_impl(void) {
	/* These lines are useful to debug scenarios where there's only 1 thread
	   and a double lock appears, for instance during startup and some
	   unlock() missing somewhere:
	if (osmo_log_tgt_mutex_on && pthread_mutex_trylock(&osmo_log_tgt_mutex) != 0)
		osmo_panic("acquiring already locked mutex!\n");
	return;
	*/

	if (osmo_log_tgt_mutex_on)
		pthread_mutex_lock(&osmo_log_tgt_mutex);
}

/*! Release the osmo_log_tgt_mutex. Don't use this function directly, always use
 *  macro log_tgt_mutex_unlock() instead.
 */
void log_tgt_mutex_unlock_impl(void) {
	if (osmo_log_tgt_mutex_on)
		pthread_mutex_unlock(&osmo_log_tgt_mutex);
}

#else /* if (!EMBEDDED) */
#pragma message ("logging multithread support disabled in embedded build")
void log_enable_multithread(void) {}
void log_tgt_mutex_lock_impl(void) {}
void log_tgt_mutex_unlock_impl(void) {}
#endif /* if (!EMBEDDED) */

const struct value_string loglevel_strs[] = {
	{ LOGL_DEBUG,	"DEBUG" },
	{ LOGL_INFO,	"INFO" },
	{ LOGL_NOTICE,	"NOTICE" },
	{ LOGL_ERROR,	"ERROR" },
	{ LOGL_FATAL,	"FATAL" },
	{ 0, NULL },
};

/* 256 color palette see https://en.wikipedia.org/wiki/ANSI_escape_code#8-bit */
#define INT2IDX(x)	(-1*(x)-1)
static const struct log_info_cat internal_cat[OSMO_NUM_DLIB] = {
	[INT2IDX(DLGLOBAL)] = {	/* -1 becomes 0 */
		.name = "DLGLOBAL",
		.description = "Library-internal global log family",
		.loglevel = LOGL_NOTICE,
		.enabled = 1,
	},
	[INT2IDX(DLLAPD)] = {	/* -2 becomes 1 */
		.name = "DLLAPD",
		.description = "LAPD in libosmogsm",
		.loglevel = LOGL_NOTICE,
		.enabled = 1,
		.color = "\033[38;5;12m",
	},
	[INT2IDX(DLINP)] = {
		.name = "DLINP",
		.description = "A-bis Intput Subsystem",
		.loglevel = LOGL_NOTICE,
		.enabled = 1,
		.color = "\033[38;5;23m",
	},
	[INT2IDX(DLMUX)] = {
		.name = "DLMUX",
		.description = "A-bis B-Subchannel TRAU Frame Multiplex",
		.loglevel = LOGL_NOTICE,
		.enabled = 1,
		.color = "\033[38;5;25m",
	},
	[INT2IDX(DLMI)] = {
		.name = "DLMI",
		.description = "A-bis Input Driver for Signalling",
		.enabled = 0, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;27m",
	},
	[INT2IDX(DLMIB)] = {
		.name = "DLMIB",
		.description = "A-bis Input Driver for B-Channels (voice)",
		.enabled = 0, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;29m",
	},
	[INT2IDX(DLSMS)] = {
		.name = "DLSMS",
		.description = "Layer3 Short Message Service (SMS)",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;31m",
	},
	[INT2IDX(DLCTRL)] = {
		.name = "DLCTRL",
		.description = "Control Interface",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;33m",
	},
	[INT2IDX(DLGTP)] = {
		.name = "DLGTP",
		.description = "GPRS GTP library",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;35m",
	},
	[INT2IDX(DLSTATS)] = {
		.name = "DLSTATS",
		.description = "Statistics messages and logging",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;37m",
	},
	[INT2IDX(DLGSUP)] = {
		.name = "DLGSUP",
		.description = "Generic Subscriber Update Protocol",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;39m",
	},
	[INT2IDX(DLOAP)] = {
		.name = "DLOAP",
		.description = "Osmocom Authentication Protocol",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;41m",
	},
	[INT2IDX(DLSS7)] = {
		.name = "DLSS7",
		.description = "libosmo-sigtran Signalling System 7",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;43m",
	},
	[INT2IDX(DLSCCP)] = {
		.name = "DLSCCP",
		.description = "libosmo-sigtran SCCP Implementation",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;45m",
	},
	[INT2IDX(DLSUA)] = {
		.name = "DLSUA",
		.description = "libosmo-sigtran SCCP User Adaptation",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;47m",
	},
	[INT2IDX(DLM3UA)] = {
		.name = "DLM3UA",
		.description = "libosmo-sigtran MTP3 User Adaptation",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;49m",
	},
	[INT2IDX(DLMGCP)] = {
		.name = "DLMGCP",
		.description = "libosmo-mgcp Media Gateway Control Protocol",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;51m",
	},
	[INT2IDX(DLJIBUF)] = {
		.name = "DLJIBUF",
		.description = "libosmo-netif Jitter Buffer",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;53m",
	},
	[INT2IDX(DLRSPRO)] = {
		.name = "DLRSPRO",
		.description = "Remote SIM protocol",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;55m",
	},
	[INT2IDX(DLNS)] = {
		.name = "DLNS",
		.description = "GPRS NS layer",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;57m",
	},
	[INT2IDX(DLBSSGP)] = {
		.name = "DLBSSGP",
		.description = "GPRS BSSGP layer",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;59m",
	},
	[INT2IDX(DLNSDATA)] = {
		.name = "DLNSDATA",
		.description = "GPRS NS layer data PDU",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;61m",
	},
	[INT2IDX(DLNSSIGNAL)] = {
		.name = "DLNSSIGNAL",
		.description = "GPRS NS layer signal PDU",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;63m",
	},
	[INT2IDX(DLIUUP)] = {
		.name = "DLIUUP",
		.description = "Iu UP layer",
		.enabled = 1, .loglevel = LOGL_NOTICE,
		.color = "\033[38;5;65m",
	},
};

void assert_loginfo(const char *src)
{
	if (!osmo_log_info) {
		fprintf(stderr, "ERROR: osmo_log_info == NULL! "
			"You must call log_init() before using logging in %s()!\n", src);
		OSMO_ASSERT(osmo_log_info);
	}
}

/* special magic for negative (library-internal) log subsystem numbers */
static int subsys_lib2index(int subsys)
{
	return (subsys * -1) + (osmo_log_info->num_cat_user-1);
}

/*! Parse a human-readable log level into a numeric value
 *  \param[in] lvl zero-terminated string containing log level name
 *  \returns numeric log level
 */
int log_parse_level(const char *lvl)
{
	return get_string_value(loglevel_strs, lvl);
}

/*! convert a numeric log level into human-readable string
 *  \param[in] lvl numeric log level
 *  \returns zero-terminated string (log level name)
 */
const char *log_level_str(unsigned int lvl)
{
	return get_value_string(loglevel_strs, lvl);
}

/*! parse a human-readable log category into numeric form
 *  \param[in] category human-readable log category name
 *  \returns numeric category value, or -EINVAL otherwise
 */
int log_parse_category(const char *category)
{
	int i;

	assert_loginfo(__func__);

	for (i = 0; i < osmo_log_info->num_cat; ++i) {
		if (osmo_log_info->cat[i].name == NULL)
			continue;
		if (!strcasecmp(osmo_log_info->cat[i].name+1, category))
			return i;
	}

	return -EINVAL;
}

/*! parse the log category mask
 *  \param[in] target log target to be configured
 *  \param[in] _mask log category mask string
 *
 * The format can be this: category1:category2:category3
 * or category1,2:category2,3:...
 */
void log_parse_category_mask(struct log_target* target, const char *_mask)
{
	int i = 0;
	char *mask = strdup(_mask);
	char *category_token = NULL;

	assert_loginfo(__func__);

	/* Disable everything to enable it afterwards */
	for (i = 0; i < osmo_log_info->num_cat; ++i)
		target->categories[i].enabled = 0;

	category_token = strtok(mask, ":");
	OSMO_ASSERT(category_token);
	do {
		for (i = 0; i < osmo_log_info->num_cat; ++i) {
			size_t length, cat_length;
			char* colon = strstr(category_token, ",");

			if (!osmo_log_info->cat[i].name)
				continue;

			length = strlen(category_token);
			cat_length = strlen(osmo_log_info->cat[i].name);

			/* Use longest length not to match subocurrences. */
			if (cat_length > length)
				length = cat_length;

			if (colon)
			    length = colon - category_token;

			if (strncasecmp(osmo_log_info->cat[i].name,
					category_token, length) == 0) {
				int level = 0;

				if (colon)
					level = atoi(colon+1);

				target->categories[i].enabled = 1;
				target->categories[i].loglevel = level;
			}
		}
	} while ((category_token = strtok(NULL, ":")));

	free(mask);
}

static const char* color(int subsys)
{
	if (subsys < osmo_log_info->num_cat)
		return osmo_log_info->cat[subsys].color;

	return NULL;
}

static const struct value_string level_colors[] = {
	{ LOGL_DEBUG, OSMO_LOGCOLOR_BLUE },
	{ LOGL_INFO, OSMO_LOGCOLOR_GREEN },
	{ LOGL_NOTICE, OSMO_LOGCOLOR_YELLOW },
	{ LOGL_ERROR, OSMO_LOGCOLOR_RED },
	{ LOGL_FATAL, OSMO_LOGCOLOR_RED },
	{ 0, NULL }
};

static const char *level_color(int level)
{
	const char *c = get_value_string_or_null(level_colors, level);
	if (!c)
		return get_value_string(level_colors, LOGL_FATAL);
	return c;
}

const char* log_category_name(int subsys)
{
	if (subsys < osmo_log_info->num_cat)
		return osmo_log_info->cat[subsys].name;

	return NULL;
}

static const char *const_basename(const char *path)
{
	const char *bn = strrchr(path, '/');
	if (!bn || !bn[1])
		return path;
	return bn + 1;
}

/*! main output formatting function for log lines.
 *  \param[out] buf caller-allocated output buffer for the generated string
 *  \param[in] buf_len number of bytes available in buf
 *  \param[in] target log target for which the string is to be formatted
 *  \param[in] subsys Log sub-system number
 *  \param[in] level Log level
 *  \param[in] file name of source code file generating the log
 *  \param[in] line line source code line number within 'file' generating the log
 *  \param[in] cont is this a continuation (true) or not (false)
 *  \param[in] format format string
 *  \param[in] ap variable argument list for format
 *  \returns number of bytes written to out */
static int _output_buf(char *buf, int buf_len, struct log_target *target, unsigned int subsys,
			unsigned int level, const char *file, int line, int cont,
			const char *format, va_list ap)
{
	int ret, len = 0, offset = 0, rem = buf_len;
	const char *c_subsys = NULL;

	/* are we using color */
	if (target->use_color) {
		c_subsys = color(subsys);
		if (c_subsys) {
			ret = snprintf(buf + offset, rem, "%s", c_subsys);
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}
	}
	if (!cont) {
		if (target->print_ext_timestamp) {
#ifdef HAVE_LOCALTIME_R
			struct tm tm;
			struct timeval tv;
			osmo_gettimeofday(&tv, NULL);
			localtime_r(&tv.tv_sec, &tm);
			ret = snprintf(buf + offset, rem, "%04d%02d%02d%02d%02d%02d%03d ",
					tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
					tm.tm_hour, tm.tm_min, tm.tm_sec,
					(int)(tv.tv_usec / 1000));
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
#endif
		} else if (target->print_timestamp) {
			time_t tm;
			if ((tm = time(NULL)) == (time_t) -1)
				goto err;
			/* Get human-readable representation of time.
			   man ctime: we need at least 26 bytes in buf */
			if (rem < 26 || !ctime_r(&tm, buf + offset))
				goto err;
			ret = strlen(buf + offset);
			if (ret <= 0)
				goto err;
			/* Get rid of useless final '\n' added by ctime_r. We want a space instead. */
			buf[offset + ret - 1] = ' ';
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}
		if (target->print_tid) {
			if (logging_tid == 0)
				logging_tid = (long int)osmo_gettid();
			ret = snprintf(buf + offset, rem, "%ld ", logging_tid);
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}
		if (target->print_category) {
			ret = snprintf(buf + offset, rem, "%s%s%s%s ",
				       target->use_color ? level_color(level) : "",
				       log_category_name(subsys),
				       target->use_color ? OSMO_LOGCOLOR_END : "",
				       c_subsys ? c_subsys : "");
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}
		if (target->print_level) {
			ret = snprintf(buf + offset, rem, "%s%s%s%s ",
				       target->use_color ? level_color(level) : "",
				       log_level_str(level),
				       target->use_color ? OSMO_LOGCOLOR_END : "",
				       c_subsys ? c_subsys : "");
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}
		if (target->print_category_hex) {
			ret = snprintf(buf + offset, rem, "<%4.4x> ", subsys);
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
		}

		if (target->print_filename_pos == LOG_FILENAME_POS_HEADER_END) {
			switch (target->print_filename2) {
			case LOG_FILENAME_NONE:
				break;
			case LOG_FILENAME_PATH:
				ret = snprintf(buf + offset, rem, "%s:%d ", file, line);
				if (ret < 0)
					goto err;
				OSMO_SNPRINTF_RET(ret, rem, offset, len);
				break;
			case LOG_FILENAME_BASENAME:
				ret = snprintf(buf + offset, rem, "%s:%d ", const_basename(file), line);
				if (ret < 0)
					goto err;
				OSMO_SNPRINTF_RET(ret, rem, offset, len);
				break;
			}
		}
	}
	ret = vsnprintf(buf + offset, rem, format, ap);
	if (ret < 0)
		goto err;
	OSMO_SNPRINTF_RET(ret, rem, offset, len);

	/* For LOG_FILENAME_POS_LAST, print the source file info only when the caller ended the log
	 * message in '\n'. If so, nip the last '\n' away, insert the source file info and re-append an
	 * '\n'. All this to allow LOGP("start..."); LOGPC("...end\n") constructs. */
	if (target->print_filename_pos == LOG_FILENAME_POS_LINE_END
	    && offset > 0 && buf[offset-1] == '\n') {
		switch (target->print_filename2) {
		case LOG_FILENAME_NONE:
			break;
		case LOG_FILENAME_PATH:
			offset --;
			ret = snprintf(buf + offset, rem, " (%s:%d)\n", file, line);
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
			break;
		case LOG_FILENAME_BASENAME:
			offset --;
			ret = snprintf(buf + offset, rem, " (%s:%d)\n", const_basename(file), line);
			if (ret < 0)
				goto err;
			OSMO_SNPRINTF_RET(ret, rem, offset, len);
			break;
		}
	}

	if (target->use_color && c_subsys) {
		ret = snprintf(buf + offset, rem, OSMO_LOGCOLOR_END);
		if (ret < 0)
			goto err;
		OSMO_SNPRINTF_RET(ret, rem, offset, len);
	}
err:
	len = OSMO_MIN(buf_len - 1, len);
	buf[len] = '\0';
	return len;
}

/* Format the log line for given target; use a stack buffer and call target->output */
static void _output(struct log_target *target, unsigned int subsys,
		    unsigned int level, const char *file, int line, int cont,
		    const char *format, va_list ap)
{
	char buf[MAX_LOG_SIZE];
	int rc;

	rc = _output_buf(buf, sizeof(buf), target, subsys, level, file, line, cont, format, ap);
	if (rc > 0)
		target->output(target, level, buf);
}

/* Catch internal logging category indexes as well as out-of-bounds indexes.
 * For internal categories, the ID is negative starting with -1; and internal
 * logging categories are added behind the user categories. For out-of-bounds
 * indexes, return the index of DLGLOBAL. The returned category index is
 * guaranteed to exist in osmo_log_info, otherwise the program would abort,
 * which should never happen unless even the DLGLOBAL category is missing. */
static inline int map_subsys(int subsys)
{
	/* Note: comparing signed and unsigned integers */

	if (subsys > 0 && ((unsigned int)subsys) >= osmo_log_info->num_cat_user)
		subsys = DLGLOBAL;

	if (subsys < 0)
		subsys = subsys_lib2index(subsys);

	if (subsys < 0 || subsys >= osmo_log_info->num_cat)
		subsys = subsys_lib2index(DLGLOBAL);

	OSMO_ASSERT(!(subsys < 0 || subsys >= osmo_log_info->num_cat));

	return subsys;
}

static inline bool should_log_to_target(struct log_target *tar, int subsys,
					int level)
{
	struct log_category *category;

	category = &tar->categories[subsys];

	/* subsystem is not supposed to be logged */
	if (!category->enabled)
		return false;

	/* Check the global log level */
	if (tar->loglevel != 0 && level < tar->loglevel)
		return false;

	/* Check the category log level */
	if (tar->loglevel == 0 && category->loglevel != 0 &&
	    level < category->loglevel)
		return false;

	/* Apply filters here... if that becomes messy we will
	 * need to put filters in a list and each filter will
	 * say stop, continue, output */
	if ((tar->filter_map & (1 << LOG_FLT_ALL)) != 0)
		return true;

	if (osmo_log_info->filter_fn)
		return osmo_log_info->filter_fn(&log_context, tar);

	/* TODO: Check the filter/selector too? */
	return true;
}

/*! vararg version of logging function
 *  \param[in] subsys Logging sub-system
 *  \param[in] level Log level
 *  \param[in] file name of source code file
 *  \param[in] cont continuation (1) or new line (0)
 *  \param[in] format format string
 *  \param[in] ap vararg-list containing format string arguments
 */
void osmo_vlogp(int subsys, int level, const char *file, int line,
		int cont, const char *format, va_list ap)
{
	struct log_target *tar;

	subsys = map_subsys(subsys);

	log_tgt_mutex_lock();

	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
		va_list bp;

		if (!should_log_to_target(tar, subsys, level))
			continue;

		/* According to the manpage, vsnprintf leaves the value of ap
		 * in undefined state. Since _output uses vsnprintf and it may
		 * be called several times, we have to pass a copy of ap. */
		va_copy(bp, ap);
		if (tar->raw_output)
			tar->raw_output(tar, subsys, level, file, line, cont, format, bp);
		else
			_output(tar, subsys, level, file, line, cont, format, bp);
		va_end(bp);
	}

	log_tgt_mutex_unlock();
}

/*! logging function used by DEBUGP() macro
 *  \param[in] subsys Logging sub-system
 *  \param[in] file name of source code file
 *  \param[in] cont continuation (1) or new line (0)
 *  \param[in] format format string
 */
void logp(int subsys, const char *file, int line, int cont,
	  const char *format, ...)
{
	va_list ap;

	va_start(ap, format);
	osmo_vlogp(subsys, LOGL_DEBUG, file, line, cont, format, ap);
	va_end(ap);
}

/*! logging function used by LOGP() macro
 *  \param[in] subsys Logging sub-system
 *  \param[in] level Log level
 *  \param[in] file name of source code file
 *  \param[in] cont continuation (1) or new line (0)
 *  \param[in] format format string
 */
void logp2(int subsys, unsigned int level, const char *file, int line, int cont, const char *format, ...)
{
	va_list ap;

	TRACE(LIBOSMOCORE_LOG_START());
	va_start(ap, format);
	osmo_vlogp(subsys, level, file, line, cont, format, ap);
	va_end(ap);
	TRACE(LIBOSMOCORE_LOG_DONE());
}

/*! Register a new log target with the logging core
 *  \param[in] target Log target to be registered
 */
void log_add_target(struct log_target *target)
{
	llist_add_tail(&target->entry, &osmo_log_target_list);
}

/*! Unregister a log target from the logging core
 *  \param[in] target Log target to be unregistered
 */
void log_del_target(struct log_target *target)
{
	llist_del(&target->entry);
}

/*! Reset (clear) the logging context */
void log_reset_context(void)
{
	memset(&log_context, 0, sizeof(log_context));
}

/*! Set the logging context
 *  \param[in] ctx_nr logging context number
 *  \param[in] value value to which the context is to be set
 *  \returns 0 in case of success; negative otherwise
 *
 * A logging context is something like the subscriber identity to which
 * the currently processed message relates, or the BTS through which it
 * was received.  As soon as this data is known, it can be set using
 * this function.  The main use of context information is for logging
 * filters.
 */
int log_set_context(uint8_t ctx_nr, void *value)
{
	if (ctx_nr > LOG_MAX_CTX)
		return -EINVAL;

	log_context.ctx[ctx_nr] = value;

	return 0;
}

/*! Enable the \ref LOG_FLT_ALL log filter
 *  \param[in] target Log target to be affected
 *  \param[in] all enable (1) or disable (0) the ALL filter
 *
 * When the \ref LOG_FLT_ALL filter is enabled, all log messages will be
 * printed.  It acts as a wildcard.  Setting it to \a 1 means there is no
 * filtering.
 */
void log_set_all_filter(struct log_target *target, int all)
{
	if (all)
		target->filter_map |= (1 << LOG_FLT_ALL);
	else
		target->filter_map &= ~(1 << LOG_FLT_ALL);
}

/*! Enable or disable the use of colored output
 *  \param[in] target Log target to be affected
 *  \param[in] use_color Use color (1) or don't use color (0)
 */
void log_set_use_color(struct log_target *target, int use_color)
{
	target->use_color = use_color;
}

/*! Enable or disable printing of timestamps while logging
 *  \param[in] target Log target to be affected
 *  \param[in] print_timestamp Enable (1) or disable (0) timestamps
 */
void log_set_print_timestamp(struct log_target *target, int print_timestamp)
{
	target->print_timestamp = print_timestamp;
}

/*! Enable or disable printing of extended timestamps while logging
 *  \param[in] target Log target to be affected
 *  \param[in] print_timestamp Enable (1) or disable (0) timestamps
 *
 * When both timestamp and extended timestamp is enabled then only
 * the extended timestamp will be used. The format of the timestamp
 * is YYYYMMDDhhmmssnnn.
 */
void log_set_print_extended_timestamp(struct log_target *target, int print_timestamp)
{
	target->print_ext_timestamp = print_timestamp;
}

/*! Enable or disable printing of timestamps while logging
 *  \param[in] target Log target to be affected
 *  \param[in] print_tid Enable (1) or disable (0) Thread ID logging
 */
void log_set_print_tid(struct log_target *target, int print_tid)
{
	target->print_tid = print_tid;
}

/*! Use log_set_print_filename2() instead.
 * Call log_set_print_filename2() with LOG_FILENAME_PATH or LOG_FILENAME_NONE, *as well as* call
 * log_set_print_category_hex() with the argument passed to this function. This is to mirror legacy
 * behavior, which combined the category in hex with the filename. For example, if the category-hex
 * output were no longer affected by log_set_print_filename(), many unit tests (in libosmocore as well as
 * dependent projects) would fail since they expect the category to disappear along with the filename.
 *  \param[in] target Log target to be affected
 *  \param[in] print_filename Enable (1) or disable (0) filenames
 */
void log_set_print_filename(struct log_target *target, int print_filename)
{
	log_set_print_filename2(target, print_filename ? LOG_FILENAME_PATH : LOG_FILENAME_NONE);
	log_set_print_category_hex(target, print_filename);
}

/*! Enable or disable printing of the filename while logging.
 *  \param[in] target Log target to be affected.
 *  \param[in] lft An LOG_FILENAME_* enum value.
 * LOG_FILENAME_NONE omits the source file and line information from logs.
 * LOG_FILENAME_PATH prints the entire source file path as passed to LOGP macros.
 */
void log_set_print_filename2(struct log_target *target, enum log_filename_type lft)
{
	target->print_filename2 = lft;
}

/*! Set the position where on a log line the source file info should be logged.
 *  \param[in] target Log target to be affected.
 *  \param[in] pos A LOG_FILENAME_POS_* enum value.
 * LOG_FILENAME_POS_DEFAULT logs just before the caller supplied log message.
 * LOG_FILENAME_POS_LAST logs only at the end of a log line, where the caller issued an '\n' to end the
 */
void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos)
{
	target->print_filename_pos = pos;
}

/*! Enable or disable printing of the category name
 *  \param[in] target Log target to be affected
 *  \param[in] print_category Enable (1) or disable (0) filenames
 *
 *  Print the category/subsys name in front of every log message.
 */
void log_set_print_category(struct log_target *target, int print_category)
{
	target->print_category = print_category;
}

/*! Enable or disable printing of the category number in hex ('<000b>').
 *  \param[in] target Log target to be affected.
 *  \param[in] print_category_hex Enable (1) or disable (0) hex category.
 */
void log_set_print_category_hex(struct log_target *target, int print_category_hex)
{
	target->print_category_hex = print_category_hex;
}

/*! Enable or disable printing of the log level name.
 *  \param[in] target Log target to be affected
 *  \param[in] print_level Enable (1) or disable (0) log level name
 *
 *  Print the log level name in front of every log message.
 */
void log_set_print_level(struct log_target *target, int print_level)
{
	target->print_level = (bool)print_level;
}

/*! Set the global log level for a given log target
 *  \param[in] target Log target to be affected
 *  \param[in] log_level New global log level
 */
void log_set_log_level(struct log_target *target, int log_level)
{
	target->loglevel = log_level;
}

/*! Set a category filter on a given log target
 *  \param[in] target Log target to be affected
 *  \param[in] category Log category to be affected
 *  \param[in] enable whether to enable or disable the filter
 *  \param[in] level Log level of the filter
 */
void log_set_category_filter(struct log_target *target, int category,
			       int enable, int level)
{
	if (!target)
		return;
	category = map_subsys(category);
	target->categories[category].enabled = !!enable;
	target->categories[category].loglevel = level;
}

#if (!EMBEDDED)
/* write-queue tells us we should write another msgb (log line) to the output fd */
static int _file_wq_write_cb(struct osmo_fd *ofd, struct msgb *msg)
{
	int rc;

	rc = write(ofd->fd, msgb_data(msg), msgb_length(msg));
	if (rc < 0)
		return rc;
	if (rc != msgb_length(msg)) {
		/* pull the number of bytes we have already written */
		msgb_pull(msg, rc);
		/* ask write_queue to re-insert the msgb at the head of the queue */
		return -EAGAIN;
	}
	return 0;
}

/* output via buffered, blocking stdio streams */
static void _file_output_stream(struct log_target *target, unsigned int level,
			 const char *log)
{
	OSMO_ASSERT(target->tgt_file.out);
	fputs(log, target->tgt_file.out);
	fflush(target->tgt_file.out);
}

/* output via non-blocking write_queue, doing internal buffering */
static void _file_raw_output(struct log_target *target, int subsys, unsigned int level, const char *file,
			     int line, int cont, const char *format, va_list ap)
{
	struct msgb *msg;
	int rc;

	OSMO_ASSERT(target->tgt_file.wqueue);
	msg = msgb_alloc_c(target->tgt_file.wqueue, MAX_LOG_SIZE, "log_file_msg");
	if (!msg)
		return;

	/* we simply enqueue the log message to a write queue here, to avoid any blocking
	 * writes on the output file.  The write queue will tell us once the file is writable
	 * and call _file_wq_write_cb() */
	rc = _output_buf((char *)msgb_data(msg), msgb_tailroom(msg), target, subsys, level, file, line, cont, format, ap);
	msgb_put(msg, rc);

	/* attempt a synchronous, non-blocking write, if the write queue is empty */
	if (target->tgt_file.wqueue->current_length == 0) {
		rc = _file_wq_write_cb(&target->tgt_file.wqueue->bfd, msg);
		if (rc == 0) {
			/* the write was complete, we can exit early */
			msgb_free(msg);
			return;
		}
	}
	/* if we reach here, either we already had elements in the write_queue, or the synchronous write
	 * failed: enqueue the message to the write_queue (backlog) */
	if (osmo_wqueue_enqueue_quiet(target->tgt_file.wqueue, msg) < 0) {
		msgb_free(msg);
		/* TODO: increment some counter so we can see that messages were dropped */
	}
}
#endif

/*! Create a new log target skeleton
 *  \returns dynamically-allocated log target
 *  This funcition allocates a \ref log_target and initializes it
 *  with some default values.  The newly created target is not
 *  registered yet.
 */
struct log_target *log_target_create(void)
{
	struct log_target *target;
	unsigned int i;

	assert_loginfo(__func__);

	target = talloc_zero(tall_log_ctx, struct log_target);
	if (!target)
		return NULL;

	target->categories = talloc_zero_array(target,
						struct log_category,
						osmo_log_info->num_cat);
	if (!target->categories) {
		talloc_free(target);
		return NULL;
	}

	INIT_LLIST_HEAD(&target->entry);

	/* initialize the per-category enabled/loglevel from defaults */
	for (i = 0; i < osmo_log_info->num_cat; i++) {
		struct log_category *cat = &target->categories[i];
		cat->enabled = osmo_log_info->cat[i].enabled;
		cat->loglevel = osmo_log_info->cat[i].loglevel;
	}

	/* global settings */
	target->use_color = 1;
	target->print_timestamp = 0;
	target->print_tid = 0;
	target->print_filename2 = LOG_FILENAME_PATH;
	target->print_category_hex = true;

	/* global log level */
	target->loglevel = 0;
	return target;
}

/*! Create the STDERR log target
 *  \returns dynamically-allocated \ref log_target for STDERR */
struct log_target *log_target_create_stderr(void)
{
/* since C89/C99 says stderr is a macro, we can safely do this! */
#if !EMBEDDED && defined(stderr)
	struct log_target *target;

	target = log_target_create();
	if (!target)
		return NULL;

	target->type = LOG_TGT_TYPE_STDERR;
	target->tgt_file.out = stderr;
	target->output = _file_output_stream;
	return target;
#else
	return NULL;
#endif /* stderr */
}

#if (!EMBEDDED)
/*! Create a new file-based log target using buffered, blocking stream output
 *  \param[in] fname File name of the new log file
 *  \returns Log target in case of success, NULL otherwise
 */
struct log_target *log_target_create_file_stream(const char *fname)
{
	struct log_target *target;

	target = log_target_create();
	if (!target)
		return NULL;

	target->type = LOG_TGT_TYPE_FILE;
	target->tgt_file.out = fopen(fname, "a");
	if (!target->tgt_file.out) {
		log_target_destroy(target);
		return NULL;
	}
	target->output = _file_output_stream;
	target->tgt_file.fname = talloc_strdup(target, fname);

	return target;
}

/*! switch from non-blocking/write-queue to blocking + buffered stream output
 *  \param[in] target log target which we should switch
 *  \return 0 on success; 1 if already switched before; negative on error
 *  Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.
 */
int log_target_file_switch_to_stream(struct log_target *target)
{
	struct osmo_wqueue *wq;

	if (!target)
		return -ENODEV;

	if (target->tgt_file.out) {
		/* target has already been switched over */
		return 1;
	}

	wq = target->tgt_file.wqueue;
	OSMO_ASSERT(wq);

	/* re-open output as stream */
	if (target->type == LOG_TGT_TYPE_STDERR)
		target->tgt_file.out = stderr;
	else
		target->tgt_file.out = fopen(target->tgt_file.fname, "a");
	if (!target->tgt_file.out) {
		return -EIO;
	}

	/* synchronously write anything left in the queue */
	while (!llist_empty(&wq->msg_queue)) {
		struct msgb *msg = msgb_dequeue(&wq->msg_queue);
		fwrite(msgb_data(msg), msgb_length(msg), 1, target->tgt_file.out);
		msgb_free(msg);
	}

	/* now that everything succeeded, we can finally close the old output fd */
	if (target->type == LOG_TGT_TYPE_FILE) {
		osmo_fd_unregister(&wq->bfd);
		close(wq->bfd.fd);
	}

	/* release the queue itself */
	talloc_free(wq);
	target->tgt_file.wqueue = NULL;
	target->output = _file_output_stream;
	target->raw_output = NULL;

	return 0;
}

/*! switch from blocking + buffered file output to non-blocking write-queue based output.
 *  \param[in] target log target which we should switch
 *  \return 0 on success; 1 if already switched before; negative on error
 *  Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.
 */
int log_target_file_switch_to_wqueue(struct log_target *target)
{
	struct osmo_wqueue *wq;
	int rc;

	if (!target)
		return -ENODEV;

	if (!target->tgt_file.out) {
		/* target has already been switched over */
		return 1;
	}

	/* we create a ~640kB sized talloc pool within the write-queue to ensure individual
	 * log lines (stored as msgbs) will not put result in malloc() calls, and also to
	 * reduce the OOM probability within logging, as the pool is already allocated */
	wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,
				  LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));
	if (!wq)
		return -ENOMEM;
	osmo_wqueue_init(wq, LOG_WQUEUE_LEN);

	fflush(target->tgt_file.out);
	if (target->type == LOG_TGT_TYPE_FILE) {
		rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
		if (rc < 0) {
			talloc_free(wq);
			return -errno;
		}
	} else {
		rc = STDERR_FILENO;
	}
	wq->bfd.fd = rc;
	wq->bfd.when = OSMO_FD_WRITE;
	wq->write_cb = _file_wq_write_cb;

	rc = osmo_fd_register(&wq->bfd);
	if (rc < 0) {
		talloc_free(wq);
		return -EIO;
	}
	target->tgt_file.wqueue = wq;
	target->raw_output = _file_raw_output;
	target->output = NULL;

	/* now that everything succeeded, we can finally close the old output stream */
	if (target->type == LOG_TGT_TYPE_FILE)
		fclose(target->tgt_file.out);
	target->tgt_file.out = NULL;

	return 0;
}

/*! Create a new file-based log target using non-blocking write_queue
 *  \param[in] fname File name of the new log file
 *  \returns Log target in case of success, NULL otherwise
 */
struct log_target *log_target_create_file(const char *fname)
{
	struct log_target *target;
	struct osmo_wqueue *wq;
	int rc;

	target = log_target_create();
	if (!target)
		return NULL;

	target->type = LOG_TGT_TYPE_FILE;
	/* we create a ~640kB sized talloc pool within the write-queue to ensure individual
	 * log lines (stored as msgbs) will not put result in malloc() calls, and also to
	 * reduce the OOM probability within logging, as the pool is already allocated */
	wq = talloc_pooled_object(target, struct osmo_wqueue, LOG_WQUEUE_LEN,
				  LOG_WQUEUE_LEN*(sizeof(struct msgb)+MAX_LOG_SIZE));
	if (!wq) {
		log_target_destroy(target);
		return NULL;
	}
	osmo_wqueue_init(wq, LOG_WQUEUE_LEN);
	wq->bfd.fd = open(fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
	if (wq->bfd.fd < 0) {
		talloc_free(wq);
		log_target_destroy(target);
		return NULL;
	}
	wq->bfd.when = OSMO_FD_WRITE;
	wq->write_cb = _file_wq_write_cb;

	rc = osmo_fd_register(&wq->bfd);
	if (rc < 0) {
		talloc_free(wq);
		log_target_destroy(target);
		return NULL;
	}

	target->tgt_file.wqueue = wq;
	target->raw_output = _file_raw_output;
	target->tgt_file.fname = talloc_strdup(target, fname);

	return target;
}
#endif

/*! Find a registered log target
 *  \param[in] type Log target type
 *  \param[in] fname File name
 *  \returns Log target (if found), NULL otherwise
 *  Must be called with mutex osmo_log_tgt_mutex held, see log_tgt_mutex_lock.
 */
struct log_target *log_target_find(int type, const char *fname)
{
	struct log_target *tgt;

	llist_for_each_entry(tgt, &osmo_log_target_list, entry) {
		if (tgt->type != type)
			continue;
		switch (tgt->type) {
		case LOG_TGT_TYPE_FILE:
			if (!strcmp(fname, tgt->tgt_file.fname))
				return tgt;
			break;
		case LOG_TGT_TYPE_GSMTAP:
			if (!strcmp(fname, tgt->tgt_gsmtap.hostname))
				return tgt;
			break;
		default:
			return tgt;
		}
	}
	return NULL;
}

/*! Unregister, close and delete a log target
 *  \param[in] target log target to unregister, close and delete */
void log_target_destroy(struct log_target *target)
{
	/* just in case, to make sure we don't have any references */
	log_del_target(target);

#if (!EMBEDDED)
	struct osmo_wqueue *wq;
	switch (target->type) {
	case LOG_TGT_TYPE_FILE:
	case LOG_TGT_TYPE_STDERR:
		if (target->tgt_file.out) {
			if (target->type == LOG_TGT_TYPE_FILE)
				fclose(target->tgt_file.out);
			target->tgt_file.out = NULL;
		}
		wq = target->tgt_file.wqueue;
		if (wq) {
			if (wq->bfd.fd >= 0) {
				if (target->type == LOG_TGT_TYPE_FILE)
					close(wq->bfd.fd);
				wq->bfd.fd = -1;
			}
			osmo_fd_unregister(&wq->bfd);
			osmo_wqueue_clear(wq);
			talloc_free(wq);
			target->tgt_file.wqueue = NULL;
		}
		talloc_free((void *)target->tgt_file.fname);
		target->tgt_file.fname = NULL;
		break;
#ifdef HAVE_SYSLOG_H
	case LOG_TGT_TYPE_SYSLOG:
		closelog();
		break;
#endif /* HAVE_SYSLOG_H */
	default:
		/* make GCC happy */
		break;
	}
#endif

	talloc_free(target);
}

/*! close and re-open a log file (for log file rotation)
 *  \param[in] target log target to re-open
 *  \returns 0 in case of success; negative otherwise */
int log_target_file_reopen(struct log_target *target)
{
	struct osmo_wqueue *wq;
	int rc;

	OSMO_ASSERT(target->type == LOG_TGT_TYPE_FILE || target->type == LOG_TGT_TYPE_STDERR);
	OSMO_ASSERT(target->tgt_file.out || target->tgt_file.wqueue);

	if (target->tgt_file.out) {
		fclose(target->tgt_file.out);
		target->tgt_file.out = fopen(target->tgt_file.fname, "a");
		if (!target->tgt_file.out)
			return -errno;
	} else {
		wq = target->tgt_file.wqueue;
		osmo_fd_unregister(&wq->bfd);
		if (wq->bfd.fd >= 0) {
			close(wq->bfd.fd);
			wq->bfd.fd = -1;
		}

		rc = open(target->tgt_file.fname, O_WRONLY|O_APPEND|O_CREAT|O_NONBLOCK, 0660);
		if (rc < 0)
			return -errno;
		wq->bfd.fd = rc;
		rc = osmo_fd_register(&wq->bfd);
		if (rc < 0)
			return rc;
	}

	return 0;
}

/*! close and re-open all log files (for log file rotation)
 *  \returns 0 in case of success; negative otherwise */
int log_targets_reopen(void)
{
	struct log_target *tar;
	int rc = 0;

	log_tgt_mutex_lock();

	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
		switch (tar->type) {
		case LOG_TGT_TYPE_FILE:
			if (log_target_file_reopen(tar) < 0)
				rc = -1;
			break;
		default:
			break;
		}
	}

	log_tgt_mutex_unlock();

	return rc;
}

/*! Initialize the Osmocom logging core
 *  \param[in] inf Information regarding logging categories, could be NULL
 *  \param[in] ctx talloc context for logging allocations
 *  \returns 0 in case of success, negative in case of error
 *
 *  If inf is NULL then only library-internal categories are initialized.
 */
int log_init(const struct log_info *inf, void *ctx)
{
	int i;
	struct log_info_cat *cat_ptr;

	/* Ensure that log_init is not called multiple times */
	OSMO_ASSERT(tall_log_ctx == NULL)

	tall_log_ctx = talloc_named_const(ctx, 1, "logging");
	if (!tall_log_ctx)
		return -ENOMEM;

	osmo_log_info = talloc_zero(tall_log_ctx, struct log_info);
	if (!osmo_log_info)
		return -ENOMEM;

	osmo_log_info->num_cat = ARRAY_SIZE(internal_cat);

	if (inf) {
		osmo_log_info->filter_fn = inf->filter_fn;
		osmo_log_info->num_cat_user = inf->num_cat;
		osmo_log_info->num_cat += inf->num_cat;
	}

	cat_ptr = talloc_zero_array(osmo_log_info, struct log_info_cat,
				    osmo_log_info->num_cat);
	if (!cat_ptr) {
		talloc_free(osmo_log_info);
		osmo_log_info = NULL;
		return -ENOMEM;
	}

	/* copy over the user part and sanitize loglevel */
	if (inf) {
		for (i = 0; i < inf->num_cat; i++) {
			memcpy(&cat_ptr[i], &inf->cat[i],
			       sizeof(struct log_info_cat));

			/* Make sure that the loglevel is set to NOTICE in case
			 * no loglevel has been preset. */
			if (!cat_ptr[i].loglevel) {
				cat_ptr[i].loglevel = LOGL_NOTICE;
			}
		}
	}

	/* copy over the library part */
	for (i = 0; i < ARRAY_SIZE(internal_cat); i++) {
		unsigned int cn = osmo_log_info->num_cat_user + i;
		memcpy(&cat_ptr[cn], &internal_cat[i], sizeof(struct log_info_cat));
	}

	osmo_log_info->cat = cat_ptr;

	return 0;
}

/* De-initialize the Osmocom logging core
 * This function destroys all targets and releases associated memory */
void log_fini(void)
{
	struct log_target *tar, *tar2;

	log_tgt_mutex_lock();

	llist_for_each_entry_safe(tar, tar2, &osmo_log_target_list, entry)
		log_target_destroy(tar);

	talloc_free(osmo_log_info);
	osmo_log_info = NULL;
	talloc_free(tall_log_ctx);
	tall_log_ctx = NULL;

	log_tgt_mutex_unlock();
}

/*! Check whether a log entry will be generated.
 *  \returns != 0 if a log entry might get generated by at least one target */
int log_check_level(int subsys, unsigned int level)
{
	struct log_target *tar;

	assert_loginfo(__func__);

	subsys = map_subsys(subsys);

	/* TODO: The following could/should be cached (update on config) */

	log_tgt_mutex_lock();

	llist_for_each_entry(tar, &osmo_log_target_list, entry) {
		if (!should_log_to_target(tar, subsys, level))
			continue;

		/* This might get logged (ignoring filters) */
		log_tgt_mutex_unlock();
		return 1;
	}

	/* We are sure, that this will not be logged. */
	log_tgt_mutex_unlock();
	return 0;
}

/*! @} */