Commit 3d38bf1c authored by Karel Koci's avatar Karel Koci 🤘

Add trace log level

Some messages are debug messages were more like trace logs than real
debug messages. So all messages dumping data send in program to
terminal are now set to level TRACE (lower level than debug).
parent 34be10c9
......@@ -18,7 +18,7 @@ along with Updater. If not, see <http://www.gnu.org/licenses/>.
]]--
-- Generate appropriate logging functions
for _, name in ipairs({ 'ERROR', 'WARN', 'INFO', 'DBG' }) do
for _, name in ipairs({ 'ERROR', 'WARN', 'INFO', 'DBG', 'TRACE' }) do
_G[name] = function(...)
log(name, 1, ...)
end
......
......@@ -41,7 +41,7 @@ local download = download
local run_command = run_command
local run_util = run_util
local utils = require "utils"
local DBG = DBG
local TRACE = TRACE
local uri_internal_get = uri_internal_get
local sha256 = sha256
......@@ -274,7 +274,7 @@ local function hashed_file(content)
end
function new(context, uri, verification)
DBG("Creating new URI: ", uri)
TRACE("Creating new URI: ", uri)
local handler = parse(context, uri)
-- Prepare verification
verification = verification or {}
......
......@@ -34,7 +34,7 @@ local error = error
local unpack = unpack
local assert = assert
local next = next
local DBG = DBG
local TRACE = TRACE
local WARN = WARN
local run_command = run_command
local events_wait = events_wait
......@@ -123,12 +123,12 @@ function morpher(func, ...)
params[i + index_pos] = v
end
index_pos = index_pos + #new_params
DBG("Added ", #new_params, " parameters to ", name)
TRACE("Added ", #new_params, " parameters to ", name)
-- Pass the morpher further, to allow more calls
return table
end
local function morph(result)
DBG("Morphing ", name)
TRACE("Morphing ", name)
-- The morpher is no longer active
active_morpher = nil
-- Get rid of the old meta table
......@@ -167,7 +167,7 @@ function morpher(func, ...)
return tostring(table)
end
}
DBG("Creating morpher ", name, " with ", #params, " parameters")
TRACE("Creating morpher ", name, " with ", #params, " parameters")
active_morpher = result
return setmetatable(result, meta)
end
......@@ -194,7 +194,8 @@ local rest_available_funcs = {
"ERROR",
"WARN",
"INFO",
"DBG"
"DBG",
"TRACE"
}
state_vars = nil
......
......@@ -28,6 +28,7 @@ local unpack = unpack
local table = table
local DIE = DIE
local DBG = DBG
local TRACE = TRACE
local WARN = WARN
local picosat = picosat
local utils = require "utils"
......@@ -83,7 +84,7 @@ function sat_penalize(state, var, penalty_group, lastpen)
return 0 -- skip first one, it isn't penalized.
end
local penalty = state.sat:var()
DBG("SAT add penalty variable " .. tostring(penalty) .. " for variable " .. tostring(var))
TRACE("SAT add penalty variable " .. tostring(penalty) .. " for variable " .. tostring(var))
-- penalty => not pen
state.sat:clause(-penalty, -var)
if lastpen ~= 0 then
......@@ -101,7 +102,7 @@ function sat_pkg_group(state, name)
end
-- Create new variable for this package
local pkg_var = state.sat:var()
DBG("SAT add package " .. name .. " with var: " .. tostring(pkg_var))
TRACE("SAT add package " .. name .. " with var: " .. tostring(pkg_var))
state.pkg2sat[name] = pkg_var
local pkg = state.pkgs[name]
-- Add candidates for this package group
......@@ -115,7 +116,7 @@ function sat_pkg_group(state, name)
-- Candidate might exists if it provides some other package
if not state.candidate2sat[candidate] then
cand = state.sat:var()
DBG("SAT add candidate " .. candidate.Package .. " for group: " .. name .. " version:" .. (candidate.Version or "") .. " var:" .. tostring(cand))
TRACE("SAT add candidate " .. candidate.Package .. " for group: " .. name .. " version:" .. (candidate.Version or "") .. " var:" .. tostring(cand))
state.candidate2sat[candidate] = cand
else
cand = state.candidate2sat[candidate]
......@@ -143,7 +144,7 @@ function sat_pkg_group(state, name)
state.sat:clause(-pkg_var, unpack(sat_candidates)) -- package group implies that at least one candidate is chosen
else
if not utils.multi_index(pkg, "modifier", "virtual") then -- For virtual package, no candidates is correct state
DBG("SAT group " .. name .. " has no candidate")
TRACE("SAT group " .. name .. " has no candidate")
state.missing[name] = pkg_var -- store that this package group has no candidates
end
end
......@@ -165,7 +166,7 @@ function sat_dep(state, pkg, version, repository)
if version or repository then
assert(type(pkg) == 'table') -- If version specified than we should have package not just package group name
local var = state.sat:var()
DBG("SAT add candidate selection " .. name .. " var:" .. tostring(var))
TRACE("SAT add candidate selection " .. name .. " var:" .. tostring(var))
if state.pkgs[name].modifier.virtual then
WARN('Package ' .. name .. ' requested with version or repository, but it is virtual. Resolved as missing.')
state.missing[pkg] = var
......@@ -180,7 +181,7 @@ function sat_dep(state, pkg, version, repository)
end)
state.sat:clause(-var, unpack(vars)) -- imply that at least one of the possible candidates is chosen
else
DBG("SAT candidate selection empty")
TRACE("SAT candidate selection empty")
state.missing[pkg] = var -- store that this package (as object not group) points to no candidate
end
-- Also imply group it self. If we have some candidates, then its just
......@@ -212,7 +213,7 @@ function sat_dep_traverse(state, deps, reqpenalty)
pvar = state.sat:var()
end
if deps.tp == 'dep-and' then
DBG("SAT dep and var: " .. tostring(wvar) .. " penvar: " .. tostring(pvar))
TRACE("SAT dep and var: " .. tostring(wvar) .. " penvar: " .. tostring(pvar))
-- wid => var for every variable. Result is that they are all in and statement.
local pens = {}
for _, sub in ipairs(deps.sub or deps) do
......@@ -222,7 +223,7 @@ function sat_dep_traverse(state, deps, reqpenalty)
end
if pvar then state.sat:clause(pvar, unpack(pens)) end -- (pen and pen and ...) => pvar
elseif deps.tp == 'dep-or' then
DBG("SAT dep or var: " .. tostring(wvar) .. " penvar: " .. tostring(pvar))
TRACE("SAT dep or var: " .. tostring(wvar) .. " penvar: " .. tostring(pvar))
-- If wvar is true, at least one of sat variables must also be true, so vwar => vars...
local vars = {}
local lastpen = nil
......@@ -272,7 +273,7 @@ local function sat_build(sat, pkgs, requests)
error(utils.exception('inconsistent', "Requested package " .. req.package.name .. " doesn't exists."))
end
local req_var = sat:var()
DBG("SAT add request for " .. req.package.name .. " var:" .. tostring(req_var))
TRACE("SAT add request for " .. req.package.name .. " var:" .. tostring(req_var))
local target_var = sat_dep(state, req.package, req.version, req.repository)
if req.tp == 'install' then
sat:clause(-req_var, target_var) -- implies true
......
......@@ -23,20 +23,20 @@
void inject_func_n(lua_State *L, const char *module, const struct inject_func *inject, size_t count) {
// Inject the functions
for (size_t i = 0; i < count; i ++) {
DBG("Injecting function %s.%s", module, inject[i].name);
TRACE("Injecting function %s.%s", module, inject[i].name);
lua_pushcfunction(L, inject[i].func);
lua_setfield(L, -2, inject[i].name);
}
}
void inject_str_const(lua_State *L, const char *module, const char *name, const char *value) {
DBG("Injecting constant %s.%s", module, name);
TRACE("Injecting constant %s.%s", module, name);
lua_pushstring(L, value);
lua_setfield(L, -2, name);
}
void inject_module(lua_State *L, const char *module) {
DBG("Injecting module %s", module);
TRACE("Injecting module %s", module);
// package.loaded[module] = _M
lua_getglobal(L, "package");
lua_getfield(L, -1, "loaded");
......
......@@ -102,7 +102,7 @@ static const char *interpreter_error_result(lua_State *L) {
lua_getfield(L, -1, "trace");
const char *trace = lua_tostring(L, -1);
if (trace) {
DBG("%s", trace);
TRACE("%s", trace);
if (!dump2file(crash_file, trace))
WARN("Crash report of stack trace dump failed.");
} // Else just print message, we are probably missing trace
......@@ -300,16 +300,25 @@ static int lua_run_generic(lua_State *L, bool utils) {
int term_timeout = luaL_checkinteger(L, 4);
int kill_timeout = luaL_checkinteger(L, 5);
const char *command = luaL_checkstring(L, 6);
if (utils) {
DBG("Util command %s", command);
} else
DBG("Command %s", command);
struct log_buffer log;
log_buffer_init(&log, LL_DBG);
// The rest of the args are args for the command ‒ get them into an array
const size_t arg_count = lua_gettop(L) - 6;
const size_t arg_count = (size_t)lua_gettop(L) - 6;
const char *args[arg_count + 1];
for (int i = 6; i < lua_gettop(L); i ++)
DBG("Arg %s", args[i - 6] = luaL_checkstring(L, i + 1));
for (int i = 6; i < lua_gettop(L); i ++) {
args[i - 6] = luaL_checkstring(L, i + 1);
if (log.f)
fprintf(log.f, "Arg %s", args[i - 6]);
}
args[arg_count] = NULL;
if (log.f) {
fclose(log.f);
if (utils) {
DBG("Util command: %s %s", command, log.char_buffer);
} else
DBG("Command: %s %s", command, log.char_buffer);
free(log.char_buffer);
}
// Data for the callbacks. It will get freed there.
struct lua_command_data *data = malloc(sizeof *data);
data->L = L;
......@@ -645,7 +654,7 @@ static int lua_lstat(lua_State *L) {
}
static int lua_sync(lua_State *L __attribute__((unused))) {
DBG("Sync");
TRACE("Sync");
sync();
return 0;
}
......@@ -824,7 +833,7 @@ struct interpreter *interpreter_create(struct events *events, const struct file_
lua_setfield(L, LUA_REGISTRYINDEX, REGISTRY_NAME);
// Insert bunch of functions
for (size_t i = 0; i < sizeof injected_funcs / sizeof *injected_funcs; i ++) {
DBG("Injecting function no %zu %s/%p", i, injected_funcs[i].name, injected_funcs[i].name);
TRACE("Injecting function no %zu %s/%p", i, injected_funcs[i].name, injected_funcs[i].name);
lua_pushcfunction(L, injected_funcs[i].func);
lua_setglobal(L, injected_funcs[i].name);
}
......@@ -930,7 +939,7 @@ const char *interpreter_autoload(struct interpreter *interpreter) {
const char *underscore = rindex(el->name, '_');
// Use the part after the last underscore as the name
const char *name = underscore ? underscore + 1 : el->name;
DBG("Including module %s", name);
TRACE("Including module %s", name);
const char *err = interpreter_include(interpreter, (const char *) el->data, el->size, name);
if (err)
return err;
......
......@@ -326,7 +326,7 @@ static const struct inject_func inject[] = {
};
void journal_mod_init(lua_State *L) {
DBG("Journal module init");
TRACE("Journal module init");
// Create _M
lua_newtable(L);
// Some variables
......
......@@ -78,13 +78,14 @@ static int lua_lock_release(lua_State *L) {
lock->locked = false;
ASSERT(close(lock->fd) == 0);
lock->fd = -1;
DBG("Released lock at %s", lock->path);
return 0;
}
static int lua_lock_gc(lua_State *L) {
struct lock *lock = luaL_checkudata(L, 1, LOCK_META);
if (lock->locked) {
WARN("Lock on %s released by garbage collector", lock->path);
TRACE("Lock on %s released by garbage collector", lock->path);
lua_lock_release(L);
}
if (lock->fd != -1) {
......@@ -103,7 +104,7 @@ static const struct inject_func lock_meta[] = {
};
void locks_mod_init(lua_State *L) {
DBG("Locks module init");
TRACE("Locks module init");
lua_newtable(L);
inject_func_n(L, "locks", funcs, sizeof funcs / sizeof *funcs);
inject_module(L, "locks");
......
......@@ -16,6 +16,7 @@ log(level, depth, msg, msg, msg, ...)::
- ERROR
- WARN
- DBG
- TRACE
The depth argument specifies how many functions on the top of the stack
are to be disregarded when printing the source file, line number and
function name to the logs. 0 means the function directly calling log,
......@@ -23,6 +24,7 @@ log(level, depth, msg, msg, msg, ...)::
ERROR(msg, msg, ...)::
WARN(msg, msg, ...)::
DBG(msg, msg, ...)::
TRACE(msg, msg, ...)::
These output a message to the logs with a given level. The messages
are concatenated together.
DIE(msg, msg, ...)::
......
......@@ -65,27 +65,24 @@ static int lua_picosat_clause(lua_State *L) {
int count = lua_gettop(L) - 1;
if (count < 1)
return luaL_error(L, "clause requires at least one argument");
FILE *dbg = NULL;
char *dbg_buff;
size_t dbg_len;
if (would_log(LL_DBG))
dbg = open_memstream(&dbg_buff, &dbg_len);
if (dbg)
fputs("clause: ", dbg);
struct log_buffer log;
log_buffer_init(&log, LL_TRACE);
if (log.f)
fputs("Picosat clause: ", log.f);
for (int i = 0; i < count; i++) {
int var = luaL_checkinteger(L, i + 2);
ASSERT(var != 0);
if (dbg)
fprintf(dbg, "%d ", var);
if (log.f)
fprintf(log.f, "%d ", var);
picosat_add(ps->sat, var);
}
picosat_add(ps->sat, 0); // close clause
if (dbg) {
fclose(dbg);
DBG("%s", dbg_buff);
free(dbg_buff);
if (log.f) {
fclose(log.f);
TRACE("%s", log.char_buffer);
free(log.char_buffer);
}
return 0;
}
......@@ -94,7 +91,7 @@ static int lua_picosat_assume(lua_State *L) {
struct picosat *ps = luaL_checkudata(L, 1, PICOSAT_META);
int assum = luaL_checkinteger(L, 2);
ASSERT(assum != 0);
DBG("assume %d", assum);
TRACE("Picosat assume %d", assum);
picosat_assume(ps->sat, assum);
return 0;
}
......@@ -104,10 +101,10 @@ static int lua_picosat_satisfiable(lua_State *L) {
int res = picosat_sat(ps->sat, -1);
ASSERT_MSG(res == PICOSAT_SATISFIABLE || res == PICOSAT_UNSATISFIABLE, "We expect only SATISFIABLE and UNSATISFIABLE from picosat.");
lua_pushboolean(L, res == PICOSAT_SATISFIABLE);
if (!would_log(LL_DBG))
if (!would_log(LL_TRACE))
return 1;
if (res == PICOSAT_SATISFIABLE) {
DBG("satisfiable");
TRACE("Picosat satisfiable");
} else {
char *buffer;
size_t len;
......@@ -116,7 +113,7 @@ static int lua_picosat_satisfiable(lua_State *L) {
picosat_write_compact_trace(ps->sat, file);
fclose(file);
buffer[len - 1] = '\0'; // Dump last char, picosat always ends this output with new line char.
DBG("unsatisfiable, trace follows\n%s", buffer);
TRACE("Picosat unsatisfiable, trace follows\n%s", buffer);
free(buffer);
}
return 1;
......@@ -126,31 +123,28 @@ static int lua_picosat_max_satisfiable(lua_State *L) {
struct picosat *ps = luaL_checkudata(L, 1, PICOSAT_META);
lua_newtable(L);
if (picosat_inconsistent(ps->sat)) {
DBG("max-assume: "); // For consistency with following code we print this not saying line.
TRACE("Picosat max-assume: "); // For consistency with following code we print this not saying line.
// If there is some empty clause, then there are no valid assumptions, return empty table.
return 1;
}
FILE *dbg = NULL;
char *dbg_buff;
size_t dbg_len;
if (would_log(LL_DBG))
dbg = open_memstream(&dbg_buff, &dbg_len);
if (dbg)
fputs("max-assume: ", dbg);
struct log_buffer log;
log_buffer_init(&log, LL_TRACE);
if (log.f)
fputs("Picosat max-assume: ", log.f);
// TODO this might be faster if we would set phase for assumptions to true. See picosat documentation for more details.
const int *assum = picosat_maximal_satisfiable_subset_of_assumptions(ps->sat);
while(*assum != 0) {
if (dbg)
fprintf(dbg, "%d ", *assum);
if (log.f)
fprintf(log.f, "%d ", *assum);
lua_pushinteger(L, *assum);
lua_pushboolean(L, true);
lua_settable(L, -3);
assum++;
}
if (dbg) {
fclose(dbg);
DBG("%s", dbg_buff);
free(dbg_buff);
if (log.f) {
fclose(log.f);
TRACE("%s", log.char_buffer);
free(log.char_buffer);
}
return 1;
}
......@@ -187,7 +181,7 @@ static int lua_picosat_index(lua_State *L) {
static int lua_picosat_gc(lua_State *L) {
struct picosat *ps = luaL_checkudata(L, 1, PICOSAT_META);
DBG("Freeing picosat");
TRACE("Freeing picosat");
picosat_reset(ps->sat);
return 0;
}
......@@ -203,7 +197,7 @@ static const struct inject_func picosat_meta[] = {
};
void picosat_mod_init(lua_State *L) {
DBG("Picosat module init");
TRACE("Picosat module init");
lua_newtable(L);
inject_func_n(L, "picosat", funcs, sizeof funcs / sizeof *funcs);
inject_module(L, "picosat");
......
......@@ -45,6 +45,7 @@ static const struct level_info levels[] = {
[LL_WARN] = { "\x1b[35mWARN\x1b[0m", "WARN", LOG_WARNING },
[LL_INFO] = { "\x1b[34mINFO\x1b[0m", "INFO", LOG_INFO },
[LL_DBG] = { "DEBUG", "DBG", LOG_DEBUG },
[LL_TRACE] = { "TRACE", "TRACE", LOG_DEBUG },
[LL_UNKNOWN] = { "????", "UNKNOWN", LOG_WARNING }
};
......@@ -113,6 +114,16 @@ bool would_log(enum log_level level) {
return (level <= syslog_level) || (level <= stderr_level);
}
void log_buffer_init(struct log_buffer *buff, enum log_level level) {
if (would_log(level)) {
buff->f = open_memstream(&buff->char_buffer, &buff->buffer_len);
if (buff->f)
return;
WARN("Message creation failed!");
}
buff->f = NULL;
}
void log_syslog_level(enum log_level level) {
syslog_level = level;
}
......
......@@ -23,6 +23,7 @@
#include "events.h"
#include <stdlib.h>
#include <stdio.h>
#include <stdbool.h>
#include <alloca.h>
......@@ -33,6 +34,7 @@ enum log_level {
LL_WARN,
LL_INFO,
LL_DBG,
LL_TRACE,
LL_UNKNOWN
};
......@@ -43,6 +45,7 @@ void log_internal(enum log_level level, const char *file, size_t line, const cha
#define WARN(...) LOG(LL_WARN, __VA_ARGS__)
#define INFO(...) LOG(LL_INFO, __VA_ARGS__)
#define DBG(...) LOG(LL_DBG, __VA_ARGS__)
#define TRACE(...) LOG(LL_TRACE, __VA_ARGS__)
#define DIE(...) do { LOG(LL_DIE, __VA_ARGS__); abort(); } while (0)
#define ASSERT_MSG(COND, ...) do { if (!(COND)) DIE(__VA_ARGS__); } while (0)
#define ASSERT(COND) do { if (!(COND)) DIE("Failed assert: " #COND); } while (0)
......@@ -52,6 +55,15 @@ bool would_log(enum log_level level);
enum log_level log_level_get(const char *str) __attribute__((nonnull));
// FILE log buffer. Initialize it and then you can build message using FILE. To print it use char_buffer.
struct log_buffer {
FILE *f; // Use this as output and before printing it close this with fclose(f).
char *char_buffer; // This contains resulting text. Don't forget to free this buffer.
size_t buffer_len;
};
// Initialize log buffer (if would_log(level)
void log_buffer_init(struct log_buffer *buf, enum log_level level) __attribute__((nonnull));
// Sets if state and error should be dumped into files in /tmp/updater-state directory
void set_state_log(bool state_log);
// In the full updater mode, dump current state into /tmp/update-state/state
......
......@@ -10,7 +10,7 @@ globals = {
-- From interpreter.c
"log", "state_log_enabled", "state_dump", "run_command", "run_util", "download", "events_wait", "mkdtemp", "chdir", "getcwd", "mkdir", "move", "ls", "stat", "lstat", "sync", "setenv", "md5", "sha256", "reexec", "uri_internal_get", "system_reboot", "get_updater_version",
-- From logging
"ERROR", "WARN", "INFO", "DBG", "DIE", "log_event", "c_pcall_error_handler",
"ERROR", "WARN", "INFO", "DBG", "TRACE", "DIE", "log_event", "c_pcall_error_handler",
-- From dumper
"DataDumper",
-- Picosat
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment