/*- * 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 "libserver/maps/map.h" #include "libserver/maps/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 -- % 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.message(msg) * Log message as an notice message * @param {string} msg string to be logged */ LUA_FUNCTION_DEF (logger, message); /*** * @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 % * @param {any} args list of arguments to be replaced in % 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 % * @param {any} args list of arguments to be replaced in % 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 % * @param {any} args list of arguments to be replaced in % positions */ LUA_FUNCTION_DEF (logger, infox); /*** * @function logger.infox(fmt[, args) * Extended interface to make an informational log message * @param {string} fmt format string, arguments are encoded as % * @param {any} args list of arguments to be replaced in % positions */ LUA_FUNCTION_DEF (logger, messagex); /*** * @function logger.debugx(fmt[, args) * Extended interface to make a debug log message * @param {string} fmt format string, arguments are encoded as % * @param {any} args list of arguments to be replaced in % positions */ LUA_FUNCTION_DEF (logger, debugx); /*** * @function logger.debugm(module, id, fmt[, args) * Extended interface to make a debug log message * @param {string} module debug module * @param {task|cfg|pool|string} id id to log * @param {string} fmt format string, arguments are encoded as % * @param {any} args list of arguments to be replaced in % positions */ LUA_FUNCTION_DEF (logger, debugm); /*** * @function logger.slog(fmt[, args) * Create string replacing percent params with corresponding arguments * @param {string} fmt format string, arguments are encoded as % * @param {any} args list of arguments to be replaced in % positions * @return {string} string with percent parameters substituted */ LUA_FUNCTION_DEF (logger, slog); /*** * @function logger.logx(level, module, id, fmt[, args) * Extended interface to make a generic log message on any level * @param {number} log level as a number (see GLogLevelFlags enum for values) * @param {task|cfg|pool|string} id id to log * @param {string} fmt format string, arguments are encoded as % * @param {any} args list of arguments to be replaced in % positions */ LUA_FUNCTION_DEF (logger, logx); static const struct luaL_reg loggerlib_f[] = { LUA_INTERFACE_DEF (logger, err), LUA_INTERFACE_DEF (logger, warn), LUA_INTERFACE_DEF (logger, message), {"msg", lua_logger_message}, 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, messagex), {"msgx", lua_logger_messagex}, LUA_INTERFACE_DEF (logger, debugx), LUA_INTERFACE_DEF (logger, debugm), LUA_INTERFACE_DEF (logger, slog), LUA_INTERFACE_DEF (logger, logx), {"__tostring", rspamd_lua_class_tostring}, {NULL, NULL} }; static void lua_common_log_line (GLogLevelFlags level, lua_State *L, const gchar *msg, const gchar *uid, const gchar *module, gint stack_level) { lua_Debug d; gchar func_buf[128], *p; if (lua_getstack (L, stack_level, &d) == 1) { (void) lua_getinfo (L, "Sl", &d); if ((p = strrchr (d.short_src, '/')) == NULL) { p = d.short_src; } else { p++; } if (strlen (p) > 30) { rspamd_snprintf (func_buf, sizeof (func_buf), "%27s...:%d", p, d.currentline); } else { rspamd_snprintf (func_buf, sizeof (func_buf), "%s:%d", p, d.currentline); } rspamd_common_log_function (NULL, level, module, uid, func_buf, "%s", msg); } else { rspamd_common_log_function (NULL, level, module, uid, G_STRFUNC, "%s", msg); } } /*** Logger interface ***/ static gint lua_logger_err (lua_State *L) { LUA_TRACE_POINT; const gchar *msg; msg = luaL_checkstring (L, 1); lua_common_log_line (G_LOG_LEVEL_CRITICAL, L, msg, NULL, NULL, 1); return 0; } static gint lua_logger_warn (lua_State *L) { LUA_TRACE_POINT; const gchar *msg; msg = luaL_checkstring (L, 1); lua_common_log_line (G_LOG_LEVEL_WARNING, L, msg, NULL, NULL, 1); return 0; } static gint lua_logger_info (lua_State *L) { LUA_TRACE_POINT; const gchar *msg; msg = luaL_checkstring (L, 1); lua_common_log_line (G_LOG_LEVEL_INFO, L, msg, NULL, NULL, 1); return 0; } static gint lua_logger_message (lua_State *L) { LUA_TRACE_POINT; const gchar *msg; msg = luaL_checkstring (L, 1); lua_common_log_line (G_LOG_LEVEL_MESSAGE, L, msg, NULL, NULL, 1); return 0; } static gint lua_logger_debug (lua_State *L) { LUA_TRACE_POINT; const gchar *msg; msg = luaL_checkstring (L, 1); lua_common_log_line (G_LOG_LEVEL_DEBUG, L, msg, NULL, NULL, 1); return 0; } static inline bool lua_logger_char_safe (int t, unsigned int esc_type) { if (t & 0x80) { if (esc_type & LUA_ESCAPE_8BIT) { return false; } return true; } if (esc_type & LUA_ESCAPE_UNPRINTABLE) { if (!g_ascii_isprint (t) && !g_ascii_isspace (t)) { return false; } } if (esc_type & LUA_ESCAPE_NEWLINES) { if (t == '\r' || t == '\n') { return false; } } return true; } static gsize lua_logger_out_str (lua_State *L, gint pos, gchar *outbuf, gsize len, struct lua_logger_trace *trace, enum lua_logger_escape_type esc_type) { gsize slen, flen; const gchar *str = lua_tolstring (L, pos, &slen); static const gchar hexdigests[16] = "0123456789abcdef"; gsize r = 0, s; if (str) { gboolean normal = TRUE; flen = MIN (slen, len - 1); for (r = 0; r < flen; r ++) { if (!lua_logger_char_safe (str[r], esc_type)) { normal = FALSE; break; } } if (normal) { r = rspamd_strlcpy (outbuf, str, flen + 1); } else { /* Need to escape non printed characters */ r = 0; s = 0; while (slen > 0 && len > 1) { if (!lua_logger_char_safe (str[s], esc_type)) { if (len >= 3) { outbuf[r++] = '\\'; outbuf[r++] = hexdigests[((str[s] >> 4) & 0xF)]; outbuf[r++] = hexdigests[((str[s]) & 0xF)]; len -= 2; } else { outbuf[r++] = '?'; } } else { outbuf[r++] = str[s]; } s++; slen --; len --; } outbuf[r] = '\0'; } } return r; } static gsize lua_logger_out_num (lua_State *L, gint pos, gchar *outbuf, gsize len, struct lua_logger_trace *trace) { 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, struct lua_logger_trace *trace) { 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, struct lua_logger_trace *trace) { gint r, top; const gchar *str = NULL; gboolean converted_to_str = FALSE; top = lua_gettop (L); if (!lua_getmetatable (L, pos)) { return 0; } lua_pushstring (L, "__index"); lua_gettable (L, -2); if (!lua_istable (L, -1)) { lua_settop (L, top); 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_settop (L, top); return 0; } str = lua_tostring (L, -1); if (str) { converted_to_str = TRUE; } } else { lua_pop (L, 1); lua_pushstring (L, "class"); lua_gettable (L, -2); if (lua_isstring (L, -1)) { str = lua_tostring (L, -1); converted_to_str = TRUE; } } if (converted_to_str) { r = rspamd_snprintf (outbuf, len, "%s", str); } else { /* Print raw pointer */ r = rspamd_snprintf (outbuf, len, "%s(%p)", str, lua_touserdata (L, pos)); } lua_settop (L, top); 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, struct lua_logger_trace *trace, enum lua_logger_escape_type esc_type) { gchar *d = outbuf; gsize remain = len, r; gboolean first = TRUE; gconstpointer self = NULL; gint i, tpos, last_seq = -1; if (!lua_istable (L, pos) || remain == 0) { return 0; } self = lua_topointer (L, pos); /* Check if we have seen this pointer */ for (i = 0; i < TRACE_POINTS; i ++) { if (trace->traces[i] == self) { r = rspamd_snprintf (d, remain + 1, "ref(%p)", self); d += r; return (d - outbuf); } } trace->traces[trace->cur_level % TRACE_POINTS] = self; 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; } last_seq = i; 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); tpos = lua_gettop (L); if (lua_topointer (L, tpos) == self) { r = rspamd_snprintf (d, remain + 1, "__self"); } else { r = lua_logger_out_type (L, tpos, d, remain, trace, esc_type); } 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) { if (last_seq > 0) { lua_pushvalue (L, -2); if (lua_tonumber (L, -1) <= last_seq + 1) { lua_pop (L, 1); /* Already seen */ continue; } lua_pop (L, 1); } } if (!first) { r = rspamd_snprintf (d, remain + 1, ", "); MOVE_BUF(d, remain, r); } /* Preserve key */ lua_pushvalue (L, -2); r = rspamd_snprintf (d, remain + 1, "[%s] = ", lua_tostring (L, -1)); lua_pop (L, 1); /* Remove key */ MOVE_BUF(d, remain, r); tpos = lua_gettop (L); if (lua_topointer (L, tpos) == self) { r = rspamd_snprintf (d, remain + 1, "__self"); } else { r = lua_logger_out_type (L, tpos, d, remain, trace, esc_type); } 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, struct lua_logger_trace *trace, enum lua_logger_escape_type esc_type) { gint type; gsize r = 0; if (len == 0) { return 0; } type = lua_type (L, pos); trace->cur_level ++; switch (type) { case LUA_TNUMBER: r = lua_logger_out_num (L, pos, outbuf, len, trace); break; case LUA_TBOOLEAN: r = lua_logger_out_boolean (L, pos, outbuf, len, trace); break; case LUA_TTABLE: r = lua_logger_out_table (L, pos, outbuf, len, trace, esc_type); break; case LUA_TUSERDATA: r = lua_logger_out_userdata (L, pos, outbuf, len, trace); break; case LUA_TFUNCTION: r = rspamd_snprintf (outbuf, len + 1, "function"); break; case LUA_TLIGHTUSERDATA: r = rspamd_snprintf (outbuf, len + 1, "0x%p", lua_topointer (L, pos)); 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, trace, esc_type); break; } trace->cur_level --; return r; } static const gchar * lua_logger_get_id (lua_State *L, gint pos, GError **err) { const gchar *uid = NULL, *clsname; if (lua_getmetatable (L, pos) != 0) { uid = ""; 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, pos); if (task) { uid = task->task_pool->tag.uid; } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "invalid rspamd{task}"); } } else if (strcmp (clsname, "rspamd{mempool}") == 0) { rspamd_mempool_t *pool; pool = rspamd_lua_check_mempool (L, pos); if (pool) { uid = pool->tag.uid; } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "invalid rspamd{mempool}"); } } else if (strcmp (clsname, "rspamd{config}") == 0) { struct rspamd_config *cfg; cfg = lua_check_config (L, pos); if (cfg) { if (cfg->checksum) { uid = cfg->checksum; } } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "invalid rspamd{config}"); } } else if (strcmp (clsname, "rspamd{map}") == 0) { struct rspamd_lua_map *map; map = lua_check_map (L, pos); if (map) { if (map->map) { uid = map->map->tag; } else { uid = "embedded"; } } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "invalid rspamd{map}"); } } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "unknown class: %s", clsname); } /* Metatable, __index, classname */ lua_pop (L, 3); } else { g_set_error (err, g_quark_from_static_string ("lua_logger"), EINVAL, "no metatable found for userdata"); } return uid; } static gboolean lua_logger_log_format (lua_State *L, gint fmt_pos, gboolean is_string, gchar *logbuf, gsize remain) { gchar *d; const gchar *s, *c; gsize r, cpylen = 0; guint arg_num = 0, cur_arg; bool num_arg = false; struct lua_logger_trace tr; enum { copy_char = 0, got_percent, parse_arg_num } state = copy_char; d = logbuf; s = lua_tostring (L, fmt_pos); c = s; cur_arg = fmt_pos; if (s == NULL) { return FALSE; } while (remain > 0 && *s != '\0') { switch (state) { case copy_char: if (*s == '%') { state = got_percent; s++; if (cpylen > 0) { memcpy (d, c, cpylen); d += cpylen; } cpylen = 0; } else { s++; cpylen ++; remain--; } break; case got_percent: if (g_ascii_isdigit (*s) || *s == 's') { state = parse_arg_num; c = s; } else { *d++ = *s++; c = 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); return FALSE; } memset (&tr, 0, sizeof (tr)); r = lua_logger_out_type (L, arg_num + 1, d, remain, &tr, is_string ? LUA_ESCAPE_UNPRINTABLE : LUA_ESCAPE_LOG); g_assert (r <= remain); remain -= r; d += r; state = copy_char; c = s; } 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); return FALSE; } memset (&tr, 0, sizeof (tr)); r = lua_logger_out_type (L, arg_num + 1, d, remain, &tr, is_string ? LUA_ESCAPE_UNPRINTABLE : LUA_ESCAPE_LOG); g_assert (r <= remain); remain -= r; d += r; } else if (state == copy_char) { if (cpylen > 0 && remain > 0) { memcpy (d, c, cpylen); d += cpylen; } } *d = '\0'; return TRUE; } static gint lua_logger_do_log (lua_State *L, GLogLevelFlags level, gboolean is_string, gint start_pos) { gchar logbuf[RSPAMD_LOGBUF_SIZE - 128]; const gchar *uid = NULL; gint fmt_pos = start_pos; gint ret; GError *err = NULL; if (lua_type (L, start_pos) == LUA_TSTRING) { fmt_pos = start_pos; } else if (lua_type (L, start_pos) == LUA_TUSERDATA) { fmt_pos = start_pos + 1; uid = lua_logger_get_id (L, start_pos, &err); if (uid == NULL) { ret = luaL_error (L, "bad userdata for logging: %s", err ? err->message : "unknown error"); if (err) { g_error_free (err); } return ret; } } else { /* Bad argument type */ return luaL_error (L, "bad format string type: %s", lua_typename (L, lua_type (L, start_pos))); } ret = lua_logger_log_format (L, fmt_pos, is_string, logbuf, sizeof (logbuf) - 1); if (ret) { if (is_string) { lua_pushstring (L, logbuf); return 1; } else { lua_common_log_line (level, L, logbuf, uid, "lua", 1); } } else { if (is_string) { lua_pushnil (L); return 1; } } return 0; } static gint lua_logger_errx (lua_State *L) { LUA_TRACE_POINT; return lua_logger_do_log (L, G_LOG_LEVEL_CRITICAL, FALSE, 1); } static gint lua_logger_warnx (lua_State *L) { LUA_TRACE_POINT; return lua_logger_do_log (L, G_LOG_LEVEL_WARNING, FALSE, 1); } static gint lua_logger_infox (lua_State *L) { LUA_TRACE_POINT; return lua_logger_do_log (L, G_LOG_LEVEL_INFO, FALSE, 1); } static gint lua_logger_messagex (lua_State *L) { LUA_TRACE_POINT; return lua_logger_do_log (L, G_LOG_LEVEL_MESSAGE, FALSE, 1); } static gint lua_logger_debugx (lua_State *L) { LUA_TRACE_POINT; return lua_logger_do_log (L, G_LOG_LEVEL_DEBUG, FALSE, 1); } static gint lua_logger_logx (lua_State *L) { LUA_TRACE_POINT; GLogLevelFlags flags = lua_tonumber (L, 1); const gchar *modname = lua_tostring (L, 2), *uid = NULL; gchar logbuf[RSPAMD_LOGBUF_SIZE - 128]; gboolean ret; gint stack_pos = 1; if (lua_type (L, 3) == LUA_TSTRING) { uid = luaL_checkstring (L, 3); } else if (lua_type (L, 3) == LUA_TUSERDATA) { uid = lua_logger_get_id (L, 3, NULL); } else { uid = "???"; } if (uid && modname) { if (lua_type (L, 4) == LUA_TSTRING) { ret = lua_logger_log_format (L, 4, FALSE, logbuf, sizeof (logbuf) - 1); } else if (lua_type (L, 4) == LUA_TNUMBER) { stack_pos = lua_tonumber (L, 4); ret = lua_logger_log_format (L, 5, FALSE, logbuf, sizeof (logbuf) - 1); } else { return luaL_error (L, "invalid argument on pos 4"); } if (ret) { lua_common_log_line (flags, L, logbuf, uid, modname, stack_pos); } } else { return luaL_error (L, "invalid arguments"); } return 0; } static gint lua_logger_debugm (lua_State *L) { LUA_TRACE_POINT; gchar logbuf[RSPAMD_LOGBUF_SIZE - 128]; const gchar *uid = NULL, *module = NULL; gint stack_pos = 1; gboolean ret; module = luaL_checkstring (L, 1); if (lua_type (L, 2) == LUA_TSTRING) { uid = luaL_checkstring (L, 2); } else { uid = lua_logger_get_id (L, 2, NULL); } if (uid && module) { if (lua_type (L, 3) == LUA_TSTRING) { ret = lua_logger_log_format (L, 3, FALSE, logbuf, sizeof (logbuf) - 1); } else if (lua_type (L, 3) == LUA_TNUMBER) { stack_pos = lua_tonumber (L, 3); ret = lua_logger_log_format (L, 4, FALSE, logbuf, sizeof (logbuf) - 1); } else { return luaL_error (L, "invalid argument on pos 3"); } if (ret) { lua_common_log_line (G_LOG_LEVEL_DEBUG, L, logbuf, uid, module, stack_pos); } } else { return luaL_error (L, "invalid arguments"); } return 0; } static gint lua_logger_slog (lua_State *L) { return lua_logger_do_log (L, 0, TRUE, 1); } /*** 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); }