path: root/src/lua/lua_logger.c

/*-
 * Copyright 2016 Vsevolod Stakhov
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *   http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
#include "lua_common.h"
#include "libutil/map.h"
#include "libutil/map_private.h"

/***
 * @module rspamd_logger
 * Rspamd logger module is used to log messages from LUA API to the main rspamd logger.
 * It supports legacy and modern interfaces allowing highly customized an convenient log functions.
 * Here is an example of logger usage:
 * @example
local rspamd_logger = require "rspamd_logger"

local a = 'string'
local b = 1.5
local c = 1
local d = {
	'aa',
	1,
	'bb'
}
local e = {
	key = 'value',
	key2 = 1.0
}

-- New extended interface
-- %<number> means numeric arguments and %s means the next argument
-- for example %1, %2, %s: %s would mean the third argument

rspamd_logger.infox('a=%1, b=%2, c=%3, d=%4, e=%s', a, b, c, d, e)
-- Output: a=string, b=1.50000, c=1, d={[1] = aa, [2] = 1, [3] = bb} e={[key]=value, [key2]=1.0}

-- Legacy interface (can handle merely strings)
rspamd_logger.info('Old stupid API')

-- Create string using logger API
local str = rspamd_logger.slog('a=%1, b=%2, c=%3, d=%4, e=%5', a, b, c, d, e)

print(str)
-- Output: a=string, b=1.50000, c=1, d={[1] = aa, [2] = 1, [3] = bb} e={[key]=value, [key2]=1.0}
 */

/* Logger methods */
/***
 * @function logger.err(msg)
 * Log message as an error
 * @param {string} msg string to be logged
 */
LUA_FUNCTION_DEF (logger, err);
/***
 * @function logger.warn(msg)
 * Log message as a warning
 * @param {string} msg string to be logged
 */
LUA_FUNCTION_DEF (logger, warn);
/***
 * @function logger.info(msg)
 * Log message as an informational message
 * @param {string} msg string to be logged
 */
LUA_FUNCTION_DEF (logger, info);
/***
 * @function logger.debug(msg)
 * Log message as a debug message
 * @param {string} msg string to be logged
 */
LUA_FUNCTION_DEF (logger, debug);
/***
 * @function logger.errx(fmt[, args)
 * Extended interface to make an error log message
 * @param {string} fmt format string, arguments are encoded as %<number>
 * @param {any} args list of arguments to be replaced in %<number> positions
 */
LUA_FUNCTION_DEF (logger, errx);
/***
 * @function logger.warn(fmt[, args)
 * Extended interface to make a warning log message
 * @param {string} fmt format string, arguments are encoded as %<number>
 * @param {any} args list of arguments to be replaced in %<number> positions
 */
LUA_FUNCTION_DEF (logger, warnx);
/***
 * @function logger.infox(fmt[, args)
 * Extended interface to make an informational log message
 * @param {string} fmt format string, arguments are encoded as %<number>
 * @param {any} args list of arguments to be replaced in %<number> positions
 */
LUA_FUNCTION_DEF (logger, infox);
/***
 * @function logger.debugx(fmt[, args)
 * Extended interface to make a debug log message
 * @param {string} fmt format string, arguments are encoded as %<number>
 * @param {any} args list of arguments to be replaced in %<number> positions
 */
LUA_FUNCTION_DEF (logger, debugx);
/***
 * @function logger.slog(fmt[, args)
 * Create string replacing percent params with corresponding arguments
 * @param {string} fmt format string, arguments are encoded as %<number>
 * @param {any} args list of arguments to be replaced in %<number> positions
 * @return {string} string with percent parameters substituted
 */
LUA_FUNCTION_DEF (logger, slog);

static const struct luaL_reg loggerlib_f[] = {
		LUA_INTERFACE_DEF (logger, err),
		LUA_INTERFACE_DEF (logger, warn),
		LUA_INTERFACE_DEF (logger, info),
		LUA_INTERFACE_DEF (logger, debug),
		LUA_INTERFACE_DEF (logger, errx),
		LUA_INTERFACE_DEF (logger, warnx),
		LUA_INTERFACE_DEF (logger, infox),
		LUA_INTERFACE_DEF (logger, debugx),
		LUA_INTERFACE_DEF (logger, slog),
		{"__tostring", rspamd_lua_class_tostring},
		{NULL, NULL}
};

static void
lua_common_log_line (GLogLevelFlags level, lua_State *L,
	   const gchar *msg, const gchar *uid)
{
	lua_Debug d;
	gchar func_buf[128], *p;

	if (lua_getstack (L, 1, &d) == 1) {
		(void) lua_getinfo (L, "Sl", &d);
		if ((p = strrchr (d.short_src, '/')) == NULL) {
			p = d.short_src;
		}
		else {
			p++;
		}

		if (strlen (p) > 20) {
			rspamd_snprintf (func_buf, sizeof (func_buf), "%10s...]:%d", p,
					d.currentline);
		}
		else {
			rspamd_snprintf (func_buf, sizeof (func_buf), "%s:%d", p,
					d.currentline);
		}

		if (level == G_LOG_LEVEL_DEBUG) {
			rspamd_conditional_debug (NULL,
					NULL,
					"lua",
					uid,
					func_buf,
					"%s",
					msg);
		}
		else {
			rspamd_common_log_function (NULL,
					level,
					"lua",
					uid,
					func_buf,
					"%s",
					msg);
		}
	}
	else {
		if (level == G_LOG_LEVEL_DEBUG) {
			rspamd_conditional_debug (NULL,
					NULL,
					"lua",
					uid,
					G_STRFUNC,
					"%s",
					msg);
		}
		else {
			rspamd_common_log_function (NULL,
					level,
					"lua",
					uid,
					G_STRFUNC,
					"%s",
					msg);
		}
	}
}

/*** Logger interface ***/
static gint
lua_logger_err (lua_State *L)
{
	const gchar *msg;
	msg = luaL_checkstring (L, 1);
	lua_common_log_line (G_LOG_LEVEL_CRITICAL, L, msg, NULL);
	return 0;
}

static gint
lua_logger_warn (lua_State *L)
{
	const gchar *msg;
	msg = luaL_checkstring (L, 1);
	lua_common_log_line (G_LOG_LEVEL_WARNING, L, msg, NULL);
	return 0;
}

static gint
lua_logger_info (lua_State *L)
{
	const gchar *msg;
	msg = luaL_checkstring (L, 1);
	lua_common_log_line (G_LOG_LEVEL_INFO, L, msg, NULL);
	return 0;
}

static gint
lua_logger_debug (lua_State *L)
{
	const gchar *msg;
	msg = luaL_checkstring (L, 1);
	lua_common_log_line (G_LOG_LEVEL_DEBUG, L, msg, NULL);
	return 0;
}

static gsize
lua_logger_out_str (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	const gchar *str = lua_tostring (L, pos);
	gsize r = 0;

	if (str) {
		r = rspamd_strlcpy (outbuf, str, len + 1);
	}

	return r;
}

static gsize
lua_logger_out_num (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	gdouble num = lua_tonumber (L, pos);
	glong inum;
	gsize r = 0;

	if ((gdouble) (glong) num == num) {
		inum = num;
		r = rspamd_snprintf (outbuf, len + 1, "%l", inum);
	}
	else {
		r = rspamd_snprintf (outbuf, len + 1, "%f", num);
	}

	return r;
}

static gsize
lua_logger_out_boolean (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	gboolean val = lua_toboolean (L, pos);
	gsize r = 0;

	r = rspamd_strlcpy (outbuf, val ? "true" : "false", len + 1);

	return r;
}

static gsize
lua_logger_out_userdata (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	gint r;
	const gchar *str = NULL;

	if (!lua_getmetatable (L, pos)) {
		return 0;
	}

	lua_pushstring (L, "__index");
	lua_gettable (L, -2);

	if (!lua_istable (L, -1)) {
		lua_pop (L, 2);
		return 0;
	}

	lua_pushstring (L, "__tostring");
	lua_gettable (L, -2);

	if (lua_isfunction (L, -1)) {
		lua_pushvalue (L, pos);

		if (lua_pcall (L, 1, 1, 0) != 0) {
			lua_pop (L, 3);
			return 0;
		}

		str = lua_tostring (L, -1);
	}
	else {
		lua_pushstring (L, "class");
		lua_gettable (L, -2);

		if (!lua_isstring (L, -1)) {
			lua_pop (L, 3);
			return 0;
		}

		str = lua_tostring (L, -1);
	}

	r = rspamd_snprintf (outbuf, len + 1, "%s(%p)", str, lua_touserdata (L, pos));
	lua_pop (L, 3);

	return r;
}

#define MOVE_BUF(d, remain, r)    \
    (d) += (r); (remain) -= (r);    \
    if ((remain) == 0) { lua_pop (L, 1); break; }

static gsize
lua_logger_out_table (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	gchar *d = outbuf;
	gsize remain = len, r;
	gboolean first = TRUE;
	gint i;

	if (!lua_istable (L, pos) || remain == 0) {
		return 0;
	}

	lua_pushvalue (L, pos);
	r = rspamd_snprintf (d, remain + 1, "{");
	remain -= r;
	d += r;

	/* Get numeric keys (ipairs) */
	for (i = 1; ; i++) {
		lua_rawgeti (L, -1, i);

		if (lua_isnil (L, -1)) {
			lua_pop (L, 1);
			break;
		}

		if (!first) {
			r = rspamd_snprintf (d, remain + 1, ", ");
			MOVE_BUF(d, remain, r);
		}

		r = rspamd_snprintf (d, remain + 1, "[%d] = ", i);
		MOVE_BUF(d, remain, r);
		r = lua_logger_out_type (L, -1, d, remain);
		MOVE_BUF(d, remain, r);

		first = FALSE;
		lua_pop (L, 1);
	}

	/* Get string keys (pairs) */
	for (lua_pushnil (L); lua_next (L, -2); lua_pop (L, 1)) {
		/* 'key' is at index -2 and 'value' is at index -1 */

		if (lua_type (L, -2) == LUA_TNUMBER) {
			continue;
		}

		if (!first) {
			r = rspamd_snprintf (d, remain + 1, ", ");
			MOVE_BUF(d, remain, r);
		}

		r = rspamd_snprintf (d, remain + 1, "[%s] = ",
				lua_tostring (L, -2));
		MOVE_BUF(d, remain, r);
		r = lua_logger_out_type (L, lua_gettop (L), d, remain);
		MOVE_BUF(d, remain, r);

		first = FALSE;
	}

	lua_pop (L, 1);

	r = rspamd_snprintf (d, remain + 1, "}");
	d += r;

	return (d - outbuf);
}

#undef MOVE_BUF

gsize
lua_logger_out_type (lua_State *L, gint pos, gchar *outbuf, gsize len)
{
	gint type;
	gsize r = 0;

	if (len == 0) {
		return 0;
	}

	type = lua_type (L, pos);

	switch (type) {
		case LUA_TNUMBER:
			r = lua_logger_out_num (L, pos, outbuf, len);
			break;
		case LUA_TBOOLEAN:
			r = lua_logger_out_boolean (L, pos, outbuf, len);
			break;
		case LUA_TTABLE:
			r = lua_logger_out_table (L, pos, outbuf, len);
			break;
		case LUA_TUSERDATA:
			r = lua_logger_out_userdata (L, pos, outbuf, len);
			break;
		case LUA_TFUNCTION:
			r = rspamd_snprintf (outbuf, len + 1, "function");
			break;
		case LUA_TNIL:
			r = rspamd_snprintf (outbuf, len + 1, "nil");
			break;
		case LUA_TNONE:
			r = rspamd_snprintf (outbuf, len + 1, "no value");
			break;
		default:
			/* Try to push everything as string using tostring magic */
			r = lua_logger_out_str (L, pos, outbuf, len);
			break;
	}

	return r;
}

static gint
lua_logger_logx (lua_State *L, GLogLevelFlags level, gboolean is_string)
{
	gchar logbuf[BUFSIZ];
	gchar *d;
	const gchar *s, *c, *clsname, *uid = NULL;
	gsize remain, r;
	guint arg_num = 0, fmt_pos, cur_arg;
	bool num_arg = false;
	enum {
		copy_char = 0,
		got_percent,
		parse_arg_num
	} state = copy_char;

	d = logbuf;
	remain = sizeof (logbuf) - 1;

	if (lua_type (L, 1) == LUA_TSTRING) {
		fmt_pos = 1;
	}
	else if (lua_type (L, 1) == LUA_TUSERDATA) {
		fmt_pos = 2;

		if (lua_getmetatable (L, 1) != 0) {
			lua_pushstring (L, "__index");
			lua_gettable (L, -2);

			lua_pushstring (L, "class");
			lua_gettable (L, -2);

			clsname = lua_tostring (L, -1);

			if (strcmp (clsname, "rspamd{task}") == 0) {
				struct rspamd_task *task = lua_check_task (L, 1);

				if (task) {
					uid = task->task_pool->tag.uid;
				}
			}
			else if (strcmp (clsname, "rspamd{mempool}") == 0) {
				rspamd_mempool_t  *pool;

				pool = rspamd_lua_check_mempool (L, 1);

				if (pool) {
					uid = pool->tag.uid;
				}
			}
			else if (strcmp (clsname, "rspamd{config}") == 0) {
				struct rspamd_config *cfg;

				cfg = lua_check_config (L, 1);

				if (cfg) {
					uid = cfg->checksum;
				}
			}
			else if (strcmp (clsname, "rspamd{map}") == 0) {
				struct rspamd_lua_map *map;

				map = lua_check_map (L, 1);

				if (map) {
					if (map->map) {
						uid = map->map->tag;
					}
					else {
						uid = "embedded";
					}
				}
			}


			/* Metatable, __index, classname */
			lua_pop (L, 3);
		}
		else {
			lua_error (L);

			return 0;
		}
	}
	else {
		/* Bad argument type */
		msg_err ("bad format string type: %s", lua_typename (L, lua_type (L,
				1)));
		lua_error (L);

		return 0;
	}

	s = lua_tostring (L, fmt_pos);
	c = s;
	cur_arg = fmt_pos;

	if (s == NULL) {
		return 0;
	}

	while (remain > 0 && *s != '\0') {
		switch (state) {
			case copy_char:
				if (*s == '%') {
					state = got_percent;
					s++;
				}
				else {
					*d++ = *s++;
					remain--;
				}
				break;
			case got_percent:
				if (g_ascii_isdigit (*s) || *s == 's') {
					state = parse_arg_num;
					c = s;
				}
				else {
					*d++ = *s++;
					state = copy_char;
				}
				break;
			case parse_arg_num:
				if (g_ascii_isdigit (*s)) {
					s++;
					num_arg = true;
				}
				else {
					if (num_arg) {
						arg_num = strtoul (c, NULL, 10);
						arg_num += fmt_pos - 1;
						/* Update the current argument */
						cur_arg = arg_num;
					}
					else {
						/* We have non numeric argument, e.g. %s */
						arg_num = cur_arg ++;
						s ++;
					}

					if (arg_num < 1 || arg_num > (guint) lua_gettop (L) + 1) {
						msg_err ("wrong argument number: %ud", arg_num);

						if (is_string) {
							lua_pushnil (L);
							return 1;
						}
						else {
							return 0;
						}
					}

					r = lua_logger_out_type (L, arg_num + 1, d, remain);
					g_assert (r <= remain);
					remain -= r;
					d += r;
					state = copy_char;
				}
				break;
		}
	}

	if (state == parse_arg_num) {
		if (num_arg) {
			arg_num = strtoul (c, NULL, 10);
			arg_num += fmt_pos - 1;
		}
		else {
			/* We have non numeric argument, e.g. %s */
			arg_num = cur_arg;
		}

		if (arg_num < 1 || arg_num > (guint) lua_gettop (L) + 1) {
			msg_err ("wrong argument number: %ud", arg_num);

			if (is_string) {
				lua_pushnil (L);
				return 1;
			}
			else {
				return 0;
			}
		}

		r = lua_logger_out_type (L, arg_num + 1, d, remain);
		g_assert (r <= remain);
		remain -= r;
		d += r;
	}

	if (is_string) {
		lua_pushlstring (L, logbuf, sizeof (logbuf) - remain - 1);
		return 1;
	}
	else {
		*d = '\0';
		lua_common_log_line (level, L, logbuf, uid);
	}

	return 0;
}

static gint
lua_logger_errx (lua_State *L)
{
	return lua_logger_logx (L, G_LOG_LEVEL_CRITICAL, FALSE);
}

static gint
lua_logger_warnx (lua_State *L)
{
	return lua_logger_logx (L, G_LOG_LEVEL_WARNING, FALSE);
}

static gint
lua_logger_infox (lua_State *L)
{
	return lua_logger_logx (L, G_LOG_LEVEL_INFO, FALSE);
}

static gint
lua_logger_debugx (lua_State *L)
{
	return lua_logger_logx (L, G_LOG_LEVEL_DEBUG, FALSE);
}

static gint
lua_logger_slog (lua_State *L)
{
	return lua_logger_logx (L, 0, TRUE);
}

/*** Init functions ***/

static gint
lua_load_logger (lua_State *L)
{
	lua_newtable (L);
	luaL_register (L, NULL, loggerlib_f);

	return 1;
}

void
luaopen_logger (lua_State *L)
{
	rspamd_lua_add_preload (L, "rspamd_logger", lua_load_logger);
}