introduce logging and debugging interface; other unrelated changes including a build system fix from heck (thanks)

doxygen-3.x
positron 2 months ago
parent 4eb338597d
commit 94d3b49196
  1. 3
      src/Makefile
  2. 3
      src/echo_api.c
  3. 1
      src/message_api.c
  4. 26
      src/pEpEngine.c
  5. 2
      src/pEpEngine.h
  6. 9
      src/pEp_debug.c
  7. 250
      src/pEp_debug.h
  8. 15
      src/pEp_internal.h
  9. 796
      src/pEp_log.c
  10. 543
      src/pEp_log.h
  11. 10
      src/platform.h
  12. 51
      src/platform_unix.c
  13. 51
      src/platform_unix.h
  14. 26
      src/platform_windows.cpp
  15. 48
      src/platform_windows.h
  16. 12
      test/src/MediaKeyTest.cc

@ -23,9 +23,11 @@ else
endif
CFLAGS+= -I../asn.1 $(EXTRA_MACROS)
CFLAGS+= -I$(PREFIX)/include
CPPFLAGS+= -DSQLITE_THREADSAFE=1
LDFLAGS+= -L../asn.1
LDFLAGS+= -L$(PREFIX)/lib
ifneq ($(BUILD_ON),OS/390)
LDFLAGS+= -shared
LDLIBS+= -lc
@ -124,6 +126,7 @@ HEADERS_TO_INSTALL = \
echo_api.h distribution_api.h media_key.h \
map_asn1.h \
platform.h platform_unix.h platform_windows.h platform_zos.h \
pEp_debug.h pEp_log.h \
transport.h growing_buf.h $(wildcard ../asn.1/*.h)
# CAVEAT:

@ -31,9 +31,6 @@
/* The functions in this section actually serve to handle prepared SQL
statements, compiled once and for all from these SQL statements. */
static const char *echo_upgrade_add_echo_challange_field_text
= " ALTER TABLE Identity"
" ADD COLUMN echo_challenge BLOB;";
static const char *echo_get_challenge_text
= " SELECT echo_challenge"
" FROM Identity I"

@ -5952,7 +5952,6 @@ static PEP_STATUS _decrypt_message(
rating, msg->from, _keylist);
if (status != PEP_STATUS_OK)
goto pEp_error;
}
// Ok, one last thing - if the message didn't follow the protocol, amend rating again.

@ -12,6 +12,7 @@
#include "echo_api.h"
#include "media_key.h"
#include "engine_sql.h"
#include "pEp_log.h"
#include "status_to_string.h"
#include <time.h>
@ -94,8 +95,12 @@ DYNAMIC_API PEP_STATUS init(
_session->ensure_passphrase = ensure_passphrase;
_session->enable_echo_protocol = true;
_session->enable_echo_in_outgoing_message_rating_preview = true;
status = init_databases(_session);
status = pEp_log_initialize(_session);
if (status != PEP_STATUS_OK)
return status;
status = init_databases(_session); /* Every database except log. */
if (status != PEP_STATUS_OK)
return status;
@ -127,6 +132,15 @@ DYNAMIC_API PEP_STATUS init(
status = log_event(_session, "init", "pEp " PEP_ENGINE_VERSION, NULL, NULL);
if (status != PEP_STATUS_OK)
goto pEp_error;
#define LOG(...) PEP_LOG_EVENT("Engine", "init", __VA_ARGS__);
{PEP_SESSION session = _session; PEP_LOG_EVENT("Engine", "init", "foo!");}
{PEP_SESSION session = _session; LOG("");} // empty string
{PEP_SESSION session = _session; LOG();} // no template at all!
{PEP_SESSION session = _session; LOG("bar!");}
{PEP_SESSION session = _session; LOG("foobar!");}
{PEP_SESSION session = _session; LOG("quux! %i", 2 + 2);}
{PEP_SESSION session = _session; LOG("quux! %i", 42);}
{PEP_SESSION session = _session; LOG("quux! %i", 42);}
// runtime config
@ -222,6 +236,7 @@ DYNAMIC_API void release(PEP_SESSION session)
release_transport_system(session, out_last);
release_cryptotech(session, out_last);
pEp_log_finalize(session);
free(session);
}
fprintf(stderr, "engine release, session %p: ...end\n", session);
@ -304,6 +319,7 @@ DYNAMIC_API PEP_STATUS log_event(
const char *comment
)
{
#warning "FIXME: remove this ugly thing and replace it with my new awesome debugging facility."
if (!(session && title && entity))
return PEP_ILLEGAL_VALUE;
@ -328,7 +344,7 @@ DYNAMIC_API PEP_STATUS log_event(
#endif
session->service_log = true;
int result;
int result __attribute__ ((unused));
sql_reset_and_clear_bindings(session->log);
sqlite3_bind_text(session->log, 1, title, -1, SQLITE_STATIC);
@ -3771,6 +3787,10 @@ PEP_STATUS find_private_keys(PEP_SESSION session, const char* pattern,
keylist);
}
/* These are visible as read-only symbols in some data section of compiled
executables. */
const char *pEpEngineVersion = PEP_ENGINE_VERSION;
const char *pEpEngineProtcolVersion = PEP_VERSION;
DYNAMIC_API const char* get_engine_version() {
return PEP_ENGINE_VERSION;

@ -43,7 +43,7 @@ extern "C" {
#define PEP_ENGINE_VERSION_PATCH 0 // the last already-released or
// being-released patchlevel,
// which must always be defined
#define PEP_ENGINE_VERSION_RC 7 // the last already-released RC for this
#define PEP_ENGINE_VERSION_RC 10 // the last already-released RC for this
// patchlevel, or not defined if not an RC
#define PEP_ENGINE_VERSION_PLUS + // Only defined when the repo is in a
// non-released non-RC state.

@ -0,0 +1,9 @@
/**
* @file debug.c
* @brief pEp Engine debugging facility
* @license GNU General Public License 3.0 - see LICENSE.txt
*/
#define _EXPORT_PEP_ENGINE_DLL // FIXME: remove unless there is at least one exported *function*
#include "pEp_debug.h"

@ -0,0 +1,250 @@
/**
* @file debug.h
* @brief pEp Engine debugging facilities
* @license GNU General Public License 3.0 - see LICENSE.txt
*/
// (setq show-trailing-whitespace t indicate-empty-lines t)
#ifndef PEP_ENGINE_DEBUG_H
#define PEP_ENGINE_DEBUG_H
#ifdef __cplusplus
extern "C" {
#endif
#include <stdbool.h> // FIXME: remove unless used
#include <stdio.h>
#include "pEpEngine.h"
#include "pEp_log.h" /* We log on requirement / assertion failure. */
#include "status_to_string.h" /* for _PEP_LOG_LOCAL_FAILURE_IF_ENABLED */
/* Safety modes
* ***************************************************************** */
/* The pEp Engine can be configured to follow exactly one of the following
modes, according to the value of the macro PEP_SAFETY_MODE (see below).
The Engine safety mode determines defensiveness and fatality (see below)
for requirements and assertions. */
typedef enum {
/* This mode is intended for production. */
PEP_SAFETY_MODE_RELEASE = 0,
/* This mode is useful for debugging code which uses the Engine. */
PEP_SAFETY_MODE_DEBUG = 1,
/* This mode is useful for debugging the Engine itself. */
PEP_SAFETY_MODE_MAINTAINER = 2
} PEP_safety_mode;
/* Configuration
* ***************************************************************** */
/* If the safety mode has not been defined on the command line use a sensible
default.
Notice that PEP_SAFETY_MODE_MAINTAINER is never the default: the few Engine
developers will set that mode when needed, without inconveniencing the many
Engine users. */
#if ! defined(PEP_SAFETY_MODE)
# if defined(NDEBUG)
# define PEP_SAFETY_MODE PEP_SAFETY_MODE_RELEASE
# else
# define PEP_SAFETY_MODE PEP_SAFETY_MODE_DEBUG
# endif
#endif
/* Define defensiveness and fatality mode.
* ***************************************************************** */
/* FIXME: About this section: I am not even remotely sure that these four
definitions match what Volker wants; however I think I can satisfy
any requirement he has by combining their four values. */
/* These constant expressions evaluate to non-false when we check for
requirements or assertions at all; otherwise assertions and requirements
will be completely ignored, with the condition not even computed.
These Boolean values express *defensiveness*. */
#define PEP_CHECK_REQUIREMENTS \
true
#define PEP_CHECK_ASSERTIONS \
(PEP_SAFETY_MODE == PEP_SAFETY_MODE_MAINTAINER)
/* These constant expressions evaluate to non-false when failed checks should
cause an abort.
These Boolean values express *fatality*. */
#define PEP_ABORT_ON_VIOLATED_REQUIRE \
(PEP_SAFETY_MODE == PEP_SAFETY_MODE_MAINTAINER)
#define PEP_ABORT_ON_VIOLATED_ASSERT \
(PEP_SAFETY_MODE >= PEP_SAFETY_MODE_DEBUG)
/* Assertions and requirements
* ***************************************************************** */
/* Here a "check" is either an assertion or a requirement. */
/* Complain to the log about a violated check. */
#define _PEP_LOG_VIOLATED_CHECK(what_as_string, expression) \
PEP_LOG_CRITICAL("p≡p", "Engine", \
what_as_string " violated: " # expression)
/* Emit a logging entry about the current function being entered, level Function
-- as long as the feature is enabled via PEP_LOG_FUNCTION_ENTRY . */
#if defined (PEP_LOG_FUNCTION_ENTRY)
# define _PEP_LOG_FUNCTION_ENTRY_IF_ENABLED \
PEP_LOG_FUNCTION("p≡p", "Engine", \
"Enter" /* no need to repeat the function name. */)
#else
# define _PEP_LOG_FUNCTION_ENTRY_IF_ENABLED \
do { } while (false)
#endif
/* Same idea as LOG_FUNCTION_ENTRY, for local checks. The argument is the
expression whose evaluation failed. Notice that this uses a captured
variable of type PEP_STATUS named "status". */
#if defined (PEP_LOG_LOCAL_FAILURE)
# define _PEP_LOG_LOCAL_FAILURE_IF_ENABLED(expression) \
PEP_LOG_NONOK("p≡p", "Engine", \
"%s evaluated to %li %s", \
# expression, \
(long) status, pEp_status_to_string (status))
#else
# define _PEP_LOG_LOCAL_FAILURE_IF_ENABLED(expression) \
do { } while (false)
#endif
/* Perform a chack. In case of failure log if appropriate according to the kind
of check, and either execute the given statement or abort, as requested. */
#define _PEP_CHECK_ORELSE(what_as_string, check, abort_on_failure, \
expression, else_statement) \
do { \
if ((check) && ! (expression)) { \
_PEP_LOG_VIOLATED_CHECK(what_as_string, expression); \
if (abort_on_failure) \
abort(); \
do { \
else_statement; \
} while (false); \
} \
} while (false)
/**
* <!-- PEP_ASSERT() -->
*
* @brief Expand to an assertion on the given expression. The run-time
* behaviour depends on defensiveness and fatality mode.
*
* @param[in] expression the expression asserted to be true
*
*/
#define PEP_ASSERT(expression) \
_PEP_CHECK_ORELSE("assertion", \
PEP_CHECK_ASSERTIONS, PEP_ABORT_ON_VIOLATED_ASSERT, \
/* I cannot protect the expression with parentheses, \
because the expression is stringised with # and \
used for output: it must match the source. */ \
expression, {})
/* Expand to a requirement, executing the given statement in case of failure,
when not aborting. */
#define _PEP_REQUIRE_ORELSE(expression, else_statement) \
do { \
/* This is used at the beginning of more or less every function, so why \
not getting this log entry for free? Of course this will not be \
enabled in production because of PEP_LOG_LEVEL_MAXIMUM . */ \
_PEP_LOG_FUNCTION_ENTRY_IF_ENABLED; \
_PEP_CHECK_ORELSE("requirement", \
PEP_CHECK_REQUIREMENTS, PEP_ABORT_ON_VIOLATED_REQUIRE,\
/* See comment above*/ expression, else_statement); \
} while (false)
/* Expand to a requirement, returning the result of the evaluation of the given
expression in case of non-aborting failure. */
#define _PEP_REQUIRE_ORELSE_RETURN(expression, else_expression) \
_PEP_REQUIRE_ORELSE(/* See comment above*/ expression, \
{ return (else_expression); })
/**
* <!-- PEP_REQUIRE_ORELSE_RETURN_ILLEGAL_VALUE() -->
*
* @brief Expand to a requirement on the given expression. In case of
* non-aborting failure execute the statement
* return PEP_ILLEGAL_VALUE;
*
* @param[in] expression the expression required to be true
*
*/
#define PEP_REQUIRE_ORELSE_RETURN_ILLEGAL_VALUE(expression) \
_PEP_REQUIRE_ORELSE_RETURN(/* See comment above*/ expression, \
PEP_ILLEGAL_VALUE)
/**
* <!-- PEP_REQUIRE_ORELSE_RETURN_NULL() -->
*
* @brief Expand to a requirement on the given expression. In case of
* non-aborting failure execute the statement
* return NULL;
*
* @param[in] expression the expression required to be true
*
*/
#define PEP_REQUIRE_ORELSE_RETURN_NULL(expression) \
_PEP_REQUIRE_ORELSE_RETURN(/* See comment above*/ expression, NULL)
/**
* <!-- PEP_REQUIRE() -->
*
* @brief A convenience short alias for PEP_REQUIRE_ORELSE_RETURN_ILLEGAL_VALUE
* which is by far the most common use case of requirements.
*/
#define PEP_REQUIRE \
PEP_REQUIRE_ORELSE_RETURN_ILLEGAL_VALUE
/* Handling status checks and local failure. [TENTATIVE]
* ***************************************************************** */
/* This API is tentative. Volker does not like it and I am not very convinced
myself. It will probably go away. Nobody should use it yet. */
#define _PEP_SET_STATUS_ORELSE(expression, else_statement, \
...) \
do { \
status = (expression); \
if (status != PEP_STATUS_OK) { \
_PEP_LOG_LOCAL_FAILURE_IF_ENABLED(expression); \
do { \
__VA_ARGS__; \
} while (false); \
do { \
else_statement; \
} while (false); \
} \
} while (false)
#define PEP_SET_STATUS_ORELSE_GOTO(expression, label, ...) \
_PEP_SET_STATUS_ORELSE(expression, {goto label;}, __VA_ARGS__)
#define PEP_SET_STATUS_ORELSE_GOTO_END(expression, ...) \
PEP_SET_STATUS_ORELSE_GOTO(expression, end, __VA_ARGS__)
#define PEP_SET_STATUS_ORELSE_GOTO_ERROR(expression, ...) \
PEP_SET_STATUS_ORELSE_GOTO(expression, error, __VA_ARGS__)
#define ORELSE_GOTO PEP_SET_STATUS_ORELSE_GOTO
#define ORELSE_GOTO_END PEP_SET_STATUS_ORELSE_GOTO_END
#define ORELSE_GOTO_ERROR PEP_SET_STATUS_ORELSE_GOTO_ERROR
#define PEP_SET_STATUS_ORELSE_RETURN(expression, else_result, ...) \
_PEP_SET_STATUS_ORELSE(expression, {return (else_result);}, __VA_ARGS__)
#ifdef __cplusplus
} /* extern "C" */
#endif
#endif // #ifndef PEP_ENGINE_DEBUG_H

@ -74,6 +74,7 @@
#ifdef WIN32
#define KEYS_DB windoze_keys_db()
#define LOCAL_DB windoze_local_db()
#define LOG_DB windoze_log_db()
#define SYSTEM_DB windoze_system_db()
#else // UNIX
#ifndef __MVS__
@ -81,6 +82,7 @@
#endif
#include <dlfcn.h>
#define LOCAL_DB unix_local_db()
#define LOG_DB unix_log_db()
#ifdef ANDROID
#define SYSTEM_DB android_system_db()
#else
@ -103,6 +105,12 @@
#endif
#include "pEpEngine.h"
/* Make debugging facilities available here very early, so that they can be used
anywhere in the pEp Engine sources, whcih are supposed to include
pEp_internal.h */
#include "pEp_debug.h"
#include "key_reset.h"
#include "pEpEngine_internal.h"
@ -173,9 +181,14 @@ struct _pEpSession {
PEP_transport_t *transports;
sqlite3 *db;
sqlite3 *log_db;
sqlite3 *system_db;
sqlite3_stmt *log;
/* Prepared SQL statements (on log_db) for logging. See pEp_log.c . */
sqlite3_stmt *log_insert_prepared_statement;
sqlite3_stmt *log_delete_oldest_prepared_statement;
sqlite3_stmt *log; /* This uses the management DB, and is obsolete. */
sqlite3_stmt *trustword;
sqlite3_stmt *get_identity;
sqlite3_stmt *get_identity_without_trust_check;

@ -0,0 +1,796 @@
/**
* @file log.c
* @brief pEp logging facility
* @license GNU General Public License 3.0 - see LICENSE.txt
*/
#warning "windows: reimplement syslog using this: https://learn.microsoft.com/en-us/windows/win32/api/winbase/nf-winbase-openeventloga"
#warning "android: ask the pEp security people (maybe huss in a friendly way? ignacio?)"
#define _EXPORT_PEP_ENGINE_DLL
#include "pEp_log.h"
#include "pEp_internal.h"
#include "timestamp.h"
#include <stdio.h>
#include <assert.h>
#include <string.h>
#if defined (PEP_HAVE_SYSLOG)
# include <syslog.h>
#endif
#if defined (PEP_HAVE_ANDROID_LOG)
# include <android/log.h>
#endif
#if defined (PEP_HAVE_WINDOWS_LOG)
# include <debugapi.h>
#endif
/* GNU/BSD formatted output emulation
* ***************************************************************** */
static int pEp_vasprintf(char **string_pointer, const char *template,
va_list args)
{
/* Sanity check. */
assert(string_pointer != NULL);
/* As an extension out of defensiveness we can also accept a NULL
template. */
if (template == NULL)
template = "(null)";
/* This is not performance-critical and we can afford doing the job twice,
instead of first tentatively allocating a string that might or might not
be big enough.
So the idea is:
1. first call vsnprintf giving a limit of 0 chars to be written, just to
have its result value which is the required string size (minus one
character for the trailing '\0');
2. allocate a string with the right size;
3. call vsnprintf once more, filling the string. */
/* Since the va_list pointer (but not the pointed argument) is destroyed by
each use (See the GNU C Library manual, §{"Variable Arguments Output
Functions"}) I need a second copy of the pointer. */
va_list args_copy;
va_copy(args_copy, args);
/* 1. Compute how many chars I need. */
int needed_char_no = (vsnprintf(NULL, 0, template, args)
+ /* for the trailing '\0' */ 1);
va_end(args);
/* 2. Allocate the string. */
* string_pointer = malloc(needed_char_no);
if (* string_pointer == NULL) {
va_end(args_copy);
return -1;
}
/* 3. Do the actual printing. The string is now guaranteed to have
sufficient size. If I arrived at this point failure is no longer
possible. */
int res = vsnprintf(* string_pointer, needed_char_no, template, args_copy);
va_end(args_copy);
return res;
}
int pEp_asprintf(char **string_pointer, const char *template, ...)
{
/* This is a simple wrapper around pEp_vasprintf, which does the actual
work. */
va_list ap;
va_start(ap, template);
int res = pEp_vasprintf(string_pointer, template, ap);
va_end(ap);
return res;
}
/* Logging facility: internal functionality
* ***************************************************************** */
/* Given a log level return its printed representation */
static const char* _log_level_to_string(PEP_LOG_LEVEL level)
{
switch (level) {
case PEP_LOG_LEVEL_CRITICAL: return "CRT";
case PEP_LOG_LEVEL_ERROR: return "ERR";
case PEP_LOG_LEVEL_WARNING: return "wng";
case PEP_LOG_LEVEL_EVENT: return "evt";
case PEP_LOG_LEVEL_API: return "api";
case PEP_LOG_LEVEL_NONOK: return "nok";
case PEP_LOG_LEVEL_FUNCTION: return "fnc";
case PEP_LOG_LEVEL_TRACE: return "trc";
case PEP_LOG_LEVEL_EVERYTHING: return "[everything log level (not for entries)]";
default: return "invalid log level";
}
}
/* The template string and arguments used by every destination relying on a
printf-like API. This expands to a string literal with no trailing newline
character and no parentheses around. */
#define PEP_LOG_PRINTF_FORMAT \
"%04i-%02i-%02i %02i:%02i:%02i" /* date, time */ \
"%s" PEP_LOG_PRINTF_FORMAT_NO_DATE
/* The variadic arguments to be passed after the template PEP_LOG_PRINTF_FORMAT
. This expands to a sequence of expressions separated by commas. Notice
newline separators here, that match line separators in PEP_LOG_PRINTF_FORMAT
. */
#define PEP_LOG_PRINTF_ACTUALS \
time->tm_year + 1900, time->tm_mon + 1, time->tm_mday, \
time->tm_hour, time->tm_min, time->tm_sec, \
system_subsystem_prefix, PEP_LOG_PRINTF_ACTUALS_NO_DATE
/* Like PEP_LOG_PRINTF_FORMAT and PEP_LOG_PRINTF_ACTUALS, but with
different fields. */
#define PEP_LOG_PRINTF_FORMAT_NO_DATE \
"%s%s%s" /* system, subsystem */ \
" %li" /* pid */ \
" %s" /* log level */ \
" %s:%i%s%s" /* source location */ \
"%s%s" /* entry */
#define PEP_LOG_PRINTF_ACTUALS_NO_DATE \
system, system_subsystem_separator, \
subsystem, \
(long) pid, \
_log_level_to_string(level), \
source_file_name, source_file_line, function_prefix, \
function_name, \
entry_prefix, entry
/* Logging facility: database destination.
* ***************************************************************** */
/* SQL statements to create the Entries table and its index. This is executed
just once at start up, and does not need to be compiled into a prepared
statement. */
static const char *pEp_log_create_table_text =
" -- No need for PRAGMA foreign_keys on a single-table\n"
" -- database with no foreign keys.\n"
" PRAGMA checkpoint_fullfsync = ON;\n"
" PRAGMA auto_vacuum = INCREMENTAL;\n"
" PRAGMA incremental_vacuum = ON;\n"
" "
" CREATE TABLE IF NOT EXISTS Entries ("
" -- The id is a good approximation of a timestamp, much more efficient.\n"
" id INTEGER PRIMARY KEY AUTOINCREMENT,"
" Level INTEGER NOT NULL,"
" Timestamp INTEGER NOT NULL DEFAULT (cast(strftime('%s','now') as int)),"
" Pid INTEGER NOT NULL,"
" System TEXT,"
" Subsystem TEXT,"
" Source_file_name TEXT NOT NULL,"
" Source_file_line INTEGER NOT NULL,"
" Function_name TEXT NOT NULL,"
" Entry TEXT"
" );"
" "
" -- This makes aggregate functions such as MIN fast.\n"
" CREATE UNIQUE INDEX IF NOT EXISTS idx_Entries_Id on Entries (id);"
" "
" -- This is very convenient for interactive use.\n"
"CREATE VIEW IF NOT EXISTS UserEntries AS"
" SELECT E.id,"
" CASE E.Level WHEN 10 THEN 'CRT'"
" WHEN 20 THEN 'ERR'"
" WHEN 100 THEN 'wng'"
" WHEN 200 THEN 'evt'"
" WHEN 210 THEN 'api'"
" WHEN 300 THEN 'nok'"
" WHEN 310 THEN 'fcn'"
" WHEN 320 THEN 'trc'"
" ELSE CAST(E.Level AS TEXT)"
" END AS Lvl,"
" datetime(E.timestamp, 'unixepoch', 'localtime') AS Timestamp,"
" E.Pid,"
" CASE WHEN E.System is NULL THEN"
" CASE WHEN E.SubSystem is NULL THEN NULL"
" ELSE '/' || E.SubSystem END"
" ELSE"
" CASE WHEN E.SubSystem is NULL THEN E.System || '/'"
" ELSE E.System || '/' || E.SubSystem END"
" END AS System_SubSystem,"
" (E.Source_file_name || ':' || CAST(E.Source_file_line AS TEXT)"
" || ':' || E.Function_name) AS Location,"
" E.Entry"
" FROM Entries E"
" ORDER BY E.id;";
/* Insert a new row. */
static const char *pEp_log_insert_text =
" INSERT INTO Entries"
" (Level, Pid, System, Subsystem, Source_file_name, Source_file_line,"
" Function_name, Entry)"
" VALUES"
" (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8);";
/* Delete the oldest row, if the total number of rows is large enough. */
static const char *pEp_log_delete_oldest_text =
" DELETE FROM Entries"
" -- MAX is a faster approximation of COUNT\n"
" WHERE id = (SELECT (CASE WHEN MAX(id) <= ?1 THEN"
" -1"
" ELSE"
" MIN(id)"
" END)"
" FROM Entries);";
/* Pepare the SQL statements worth preparing. */
static PEP_STATUS _pEp_log_prepare_sql_statements(PEP_SESSION session)
{
PEP_STATUS status = PEP_STATUS_OK;
int sqlite_status = SQLITE_OK;
#define CHECK_SQL_STATUS \
do { \
if (sqlite_status != SQLITE_OK) { \
status = PEP_UNKNOWN_DB_ERROR; \
goto end; \
} \
} while (false)
sqlite_status
= sqlite3_prepare_v2(session->log_db,
pEp_log_insert_text, -1,
& session->log_insert_prepared_statement,
NULL);
CHECK_SQL_STATUS;
sqlite_status
= sqlite3_prepare_v2(session->log_db,
pEp_log_delete_oldest_text, -1,
& session->log_delete_oldest_prepared_statement,
NULL);
CHECK_SQL_STATUS;
end:
return status;
}
/* Initialise the database subsystem. Called once at session initialisation. */
static PEP_STATUS _pEp_log_initialize_database(PEP_SESSION session)
{
assert(session != NULL && session->log_db == NULL);
if (! (session != NULL && session->log_db == NULL))
return PEP_ILLEGAL_VALUE;
PEP_STATUS status = PEP_STATUS_OK;
int sqlite_status = SQLITE_OK;
char *error_message = NULL;
/* Open (creating it as needed) the log database. */
const char *database_file_path = LOG_DB;
if (database_file_path == NULL) {
status = PEP_INIT_CANNOT_OPEN_DB;
goto end;
}
sqlite_status = sqlite3_open_v2(database_file_path, & session->log_db,
SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE
| SQLITE_OPEN_FULLMUTEX,
NULL);
if (sqlite_status != SQLITE_OK) {
sqlite3_close(session->log_db);
session->log_db = NULL;
status = PEP_INIT_CANNOT_OPEN_DB;
goto end;
}
/* Create the log database single table. No need to prepare this statement
which is executed only once. */
sqlite_status = sqlite3_exec(session->log_db,
pEp_log_create_table_text, NULL, NULL,
& error_message);
if (sqlite_status != SQLITE_OK) {
fprintf(stderr, "Failed creating the log database table: %s\n",
error_message);
status = PEP_INIT_CANNOT_OPEN_DB;
}
/* Prepare SQL statements. */
status = _pEp_log_prepare_sql_statements(session);
end:
sqlite3_free(error_message);
return status;
}
/* Finalise the database subsystem. Called once at session release. */
static PEP_STATUS _pEp_log_finalize_database(PEP_SESSION session)
{
assert(session != NULL && session->log_db != NULL);
if (! (session != NULL && session->log_db != NULL))
return PEP_ILLEGAL_VALUE;
PEP_STATUS status = PEP_STATUS_OK;
int sqlite_status = SQLITE_OK;
/* Finialise prepared SQL statements. Go on even in case of failure. */
sqlite_status
= sqlite3_finalize(session->log_insert_prepared_statement);
if (sqlite_status != SQLITE_OK)
status = PEP_UNKNOWN_DB_ERROR;
sqlite_status
= sqlite3_finalize(session->log_delete_oldest_prepared_statement);
if (sqlite_status != SQLITE_OK)
status = PEP_UNKNOWN_DB_ERROR;
/* Close the database. */
sqlite_status = sqlite3_close(session->log_db);
if (sqlite_status != SQLITE_OK)
status = PEP_UNKNOWN_DB_ERROR;
/* Out of defensiveness. */
session->log_db = NULL;
return status;
}
/* Delete the oldest row, if more than PEP_LOG_DATABASE_ROW_NO_MAXIMUM rows seem
to be there already. Do nothing otherwise. */
static void _pEp_log_delete_oldest_row_when_too_many(PEP_SESSION session)
{
int sqlite_status = SQLITE_OK;
sql_reset_and_clear_bindings(session->log_delete_oldest_prepared_statement);
sqlite_status
= sqlite3_bind_int64(session->log_delete_oldest_prepared_statement,
1, PEP_LOG_DATABASE_ROW_NO_MAXIMUM);
if (sqlite_status != SQLITE_OK)
return;
sqlite_status = sqlite3_step(session->log_delete_oldest_prepared_statement);
/* Here sqlite_status will be SQLITE_DONE on success, including the case in
which no row is deleted. */
}
/* The implementation of pEp_log for the database destination. */
static PEP_STATUS _pEp_log_db(PEP_SESSION session,
PEP_LOG_LEVEL level,
const timestamp *time,
pid_t pid,
const char *system_subsystem_prefix,
const char *system,
const char *system_subsystem_separator,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_prefix,
const char *function_name,
const char *entry_prefix,
const char *entry)
{
assert(session != NULL && session->log_db != NULL);
if (! (session != NULL && session->log_db != NULL))
return PEP_ILLEGAL_VALUE;
/* If the table has become too large delete the oldest row, before inserting
the next one. */
_pEp_log_delete_oldest_row_when_too_many(session);
PEP_STATUS status = PEP_STATUS_OK;
int sqlite_status = SQLITE_OK;
#define CHECK_SQL(expected_sqlite_status) \
do { \
if (sqlite_status != (expected_sqlite_status)) { \
status = PEP_UNKNOWN_DB_ERROR; \
goto error; \
} \
} while (false)
/* Bind parameters to the compiled statement. */
sql_reset_and_clear_bindings(session->log_insert_prepared_statement);
sqlite_status = sqlite3_bind_int(session->log_insert_prepared_statement,
1, level);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_int(session->log_insert_prepared_statement,
2, pid);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_text(session->log_insert_prepared_statement,
3, system, -1, SQLITE_STATIC);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_text(session->log_insert_prepared_statement,
4, subsystem, -1, SQLITE_STATIC);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_text(session->log_insert_prepared_statement,
5, source_file_name, -1, SQLITE_STATIC);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_int(session->log_insert_prepared_statement,
6, source_file_line);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_text(session->log_insert_prepared_statement,
7, function_name, -1, SQLITE_STATIC);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_bind_text(session->log_insert_prepared_statement,
8,
(EMPTYSTR(entry) ? NULL : entry), -1,
SQLITE_STATIC);
CHECK_SQL(SQLITE_OK);
sqlite_status = sqlite3_step(session->log_insert_prepared_statement);
CHECK_SQL(SQLITE_DONE);
error:
return status;
}
/* Logging facility: FILE* destinations
* ***************************************************************** */
/* The implementation of pEp_log for FILE * destinations. */
static PEP_STATUS _pEp_log_file_star(FILE* file_star,
PEP_SESSION session,
PEP_LOG_LEVEL level,
const timestamp *time,
pid_t pid,
const char *system_subsystem_prefix,
const char *system,
const char *system_subsystem_separator,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_prefix,
const char *function_name,
const char *entry_prefix,
const char *entry)
{
int fprintf_result = fprintf(file_star,
PEP_LOG_PRINTF_FORMAT "\n",
PEP_LOG_PRINTF_ACTUALS);
if (fprintf_result < 0)
return PEP_UNKNOWN_ERROR;
else
return PEP_STATUS_OK;
}
/* Logging facility: syslog destination
* ***************************************************************** */
#if defined (PEP_HAVE_SYSLOG)
/* Given a pEp log level return its syslog equivalent, as the value to be
passed as the first argument to the syslog function. */
static int _log_level_to_syslog_facility_priority(PEP_LOG_LEVEL level)
{
int facility = LOG_USER;
#define RETURN_SYSLOG_PRIORITY(priority) \
do { return LOG_MAKEPRI(facility, (priority)); } while (false)
switch (level) {
case PEP_LOG_LEVEL_CRITICAL:
RETURN_SYSLOG_PRIORITY(LOG_CRIT);
case PEP_LOG_LEVEL_ERROR:
RETURN_SYSLOG_PRIORITY(LOG_ERR);
case PEP_LOG_LEVEL_WARNING:
RETURN_SYSLOG_PRIORITY(LOG_WARNING);
case PEP_LOG_LEVEL_EVENT:
RETURN_SYSLOG_PRIORITY(LOG_NOTICE);
case PEP_LOG_LEVEL_API:
RETURN_SYSLOG_PRIORITY(LOG_NOTICE);
case PEP_LOG_LEVEL_FUNCTION:
RETURN_SYSLOG_PRIORITY(LOG_INFO);
case PEP_LOG_LEVEL_TRACE:
RETURN_SYSLOG_PRIORITY(LOG_DEBUG);
case PEP_LOG_LEVEL_EVERYTHING:
/* This should not happen. Let us make the log entry visible. */
RETURN_SYSLOG_PRIORITY(LOG_DEBUG);
default:
/* Invalid. Let us make the log entry visible. */
RETURN_SYSLOG_PRIORITY(LOG_EMERG);
}
#undef RETURN
}
/* The implementation of pEp_log for the syslog destination. */
static PEP_STATUS _pEp_log_syslog(PEP_SESSION session,
PEP_LOG_LEVEL level,
const timestamp *time,
pid_t pid,
const char *system_subsystem_prefix,
const char *system,
const char *system_subsystem_separator,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_prefix,
const char *function_name,
const char *entry_prefix,
const char *entry)
{
int facility_priority
= _log_level_to_syslog_facility_priority(level);
syslog(facility_priority, PEP_LOG_PRINTF_FORMAT_NO_DATE,
PEP_LOG_PRINTF_ACTUALS_NO_DATE);
return PEP_STATUS_OK;
}
#endif /* #if defined (PEP_HAVE_SYSLOG) */
/* Logging facility: Android destination
* ***************************************************************** */
#if defined (PEP_HAVE_ANDROID_LOG)
/* positron: this code is completely untested. I read
https://android.googlesource.com/platform/system/core/+/jb-dev/include/android/log.h
and tried to do something reasonable, based on the (tested and working)
syslog destination. */
/* Given a pEp log level return its enum android_LogPriority equivalent, as the
value to be passed as the first argument to the __android_log_print
function. */
static enum android_LogPriority _log_level_to_android_logpriority(
PEP_LOG_LEVEL level)
{
int facility = LOG_USER;
#define RETURN_ANDROID_LOGPRIORITY(priority) \
{ return LOG_MAKEPRI(facility, (priority)); }
switch (level) {
case PEP_LOG_LEVEL_CRITICAL:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_FATAL);
case PEP_LOG_LEVEL_ERROR:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_ERROR);
case PEP_LOG_LEVEL_WARNING:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_WARN);
case PEP_LOG_LEVEL_EVENT:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_INFO);
case PEP_LOG_LEVEL_API:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_INFO);
case PEP_LOG_LEVEL_FUNCTION:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_DEBUG);
case PEP_LOG_LEVEL_TRACE:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_DEBUG);
/* This should not happen. */
case PEP_LOG_LEVEL_EVERYTHING:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_UNKNOWN);
/* Invalid. */
default:
RETURN_ANDROID_LOGPRIORITY(ANDROID_LOG_UNKNOWN);
}
#undef RETURN
}
/* The implementation of pEp_log for the android_log destination. */
static PEP_STATUS _pEp_log_android_log(PEP_SESSION session,
PEP_LOG_LEVEL level,
const timestamp *time,
pid_t pid,
const char *system_subsystem_prefix,
const char *system,
const char *system_subsystem_separator,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_prefix,
const char *function_name,
const char *entry_prefix,
const char *entry)
{
int prio = _log_level_to_android_logpriority(level);
__android_log_print(prio, (system != NULL ? system : "pEp"),
PEP_LOG_PRINTF_FORMAT,
PEP_LOG_PRINTF_ACTUALS);
return PEP_STATUS_OK;
}
#endif /* #if defined (PEP_HAVE_ANDROID_LOG) */
/* Logging facility: windows destination
* ***************************************************************** */
#if defined (PEP_HAVE_WINDOWS_LOG)
/* positron: this code is completely untested. I read
http://www.unixwiz.net/techtips/outputdebugstring.html
and the previously existing code in
platform_windows.cpp
and tried to do something reasonable, based on the other tested and working
destinations. */
/* The implementation of pEp_log for the windows_log destination. */
static PEP_STATUS _pEp_log_windows_log(PEP_SESSION session,
PEP_LOG_LEVEL level,
const timestamp *time,
pid_t pid,
const char *system_subsystem_prefix,
const char *system,
const char *system_subsystem_separator,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_prefix,
const char *function_name,
const char *entry_prefix,
const char *entry)
{
char *heap_string;
int asprintf_result = pEp_asprintf(& heap_string,
PEP_LOG_PRINTF_FORMAT,
PEP_LOG_PRINTF_ACTUALS);
if (heap_string == NULL || asprintf_result < 1) {
free(heap_string);
return PEP_OUT_OF_MEMORY;
}
OutputDebugString(heap_string);
free(heap_string);
return PEP_STATUS_OK;
}
#endif /* #if defined (PEP_HAVE_WINDOWS_LOG) */
/* Logging facility: log an entry (function API)
* ***************************************************************** */
DYNAMIC_API PEP_STATUS pEp_log(PEP_SESSION session,
PEP_LOG_LEVEL level,
const char *system,
const char *subsystem,
const char *source_file_name,
int source_file_line,
const char *function_name,
const char *entry)
{
/* Sanity checks. */
assert(session);
if (! session)
return PEP_ILLEGAL_VALUE;
/* Before doing anything, check that the log level does not exceed the
verbosity limit; if it does just return without doing anything. */
if (level > PEP_LOG_LEVEL_MAXIMUM)
return PEP_STATUS_OK;
/* Get the current time. */
time_t now_in_seconds = time(NULL);
timestamp* now = new_timestamp(now_in_seconds);
if (now == NULL)
return PEP_OUT_OF_MEMORY;
/* Get the current pid. */
pid_t pid = getpid();
/* Normalise system/subsystem strings and compute cosmetic parameters. */
const char *system_subsystem_prefix = " ";
const char *system_subsystem_separator = "/";
if (EMPTYSTR(system) && EMPTYSTR(subsystem))
system_subsystem_prefix = "";
if (EMPTYSTR(system)) {
system = "";
system_subsystem_separator = "";
}
if (EMPTYSTR(subsystem)) {
subsystem = "";
system_subsystem_separator = "";
}
/* Normalise location strings and compute cosmetic parameters. */
if (EMPTYSTR(source_file_name))
source_file_name = "UNKNOWN_FILE";
const char *function_prefix = ":";
if (EMPTYSTR(function_name)) {
function_prefix = "";
function_name = "";
}
/* Normalise entry and compute cosmetic parameters. */
const char *entry_prefix = " ";
if (EMPTYSTR(entry)) {
entry_prefix = "";
entry = "";
}
/* Now prepare for calling helper functions which will perform the actual
logging, for each destination. Since these functions have many
parameters which are always the same, it is convenient to define what the
actuals are once and for all. */
#define ACTUALS \
session, level, \
now, \
pid, \
system_subsystem_prefix, system, system_subsystem_separator, subsystem, \
source_file_name, source_file_line, function_prefix, function_name, \
entry_prefix, entry
/* Evalutate an expression returning a pEp status; combine its result with
the current status, updating the current status if the new one is "worse"
than the current value. */
#define COMBINE_STATUS(expression) \
do { \
PEP_STATUS _new_status = (expression); \
/* This assumes, somewhat crudely, that higher-valued error codes \
are "more serious". It is an acceptable approximation in the \
sense that non-zero status codes are more serious than \
PEP_STATUS_OK ; ranking different kinds of errors seems futile. */ \
if (_new_status > status) \
status = _new_status; \
} while (false)
/* Now log to each enabled destination, combining the status we obtain for
every attempt. Notice that we do not bail out on the first error. */
PEP_STATUS status = PEP_STATUS_OK;
#if defined (PEP_HAVE_STDOUT_AND_STDERR)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_STDOUT)
COMBINE_STATUS(_pEp_log_file_star(stdout, ACTUALS));
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_STDERR)
COMBINE_STATUS(_pEp_log_file_star(stderr, ACTUALS));
#endif /* #if defined (PEP_HAVE_STDOUT_AND_STDERR) */
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_DATABASE)
COMBINE_STATUS(_pEp_log_db(ACTUALS));
#if defined (PEP_HAVE_SYSLOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_SYSLOG)
COMBINE_STATUS(_pEp_log_syslog(ACTUALS));
#endif /* #if defined (PEP_HAVE_SYSLOG) */
#if defined (PEP_HAVE_ANDROID_LOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_ANDROID)
COMBINE_STATUS(_pEp_log_android_log(ACTUALS));
#endif /* #if defined (PEP_HAVE_ANDROID_LOG) */
#if defined (PEP_HAVE_WINDOWS_LOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_WINDOWS)
COMBINE_STATUS(_pEp_log_windows_log(ACTUALS));
#endif /* #if defined (PEP_HAVE_WINDOWS_LOG) */
free (now);
return status;
}
/* Initialisation and finalisation
* ***************************************************************** */
/* Print a warning about enabled but unsupported destinations. This will be
executed once at startup. */
static void warn_about_unsupported_destinations(void) {
#if ! defined (PEP_HAVE_STDOUT_AND_STDERR)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_STDOUT)
fprintf(stderr, "Warning: stdout logging selected but unavailable\n");
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_STDERR)
fprintf(stderr, "Warning: stderr logging selected but unavailable\n");
#endif
/* The database destination is always available. */
#if ! defined (PEP_HAVE_SYSLOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_SYSLOG)
fprintf(stderr, "Warning: syslog logging selected but unavailable\n");
#endif
#if ! defined (PEP_HAVE_ANDROID_LOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_ANDROID)
fprintf(stderr, "Warning: Android logging selected but unavailable\n");
#endif
#if ! defined (PEP_HAVE_WINDOWS_LOG)
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_WINDOWS)
fprintf(stderr, "Warning: windows logging selected but unavailable\n");
#endif
}
PEP_STATUS pEp_log_initialize(PEP_SESSION session)
{
PEP_STATUS status = PEP_STATUS_OK;
warn_about_unsupported_destinations();
/* The database destination is always enabled: no need for a CPP
conditional. */
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_DATABASE)
status = _pEp_log_initialize_database(session);
return status;
}
PEP_STATUS pEp_log_finalize(PEP_SESSION session)
{
PEP_STATUS status = PEP_STATUS_OK;
/* The database destination is always enabled: no need for a CPP
conditional. */
if (PEP_LOG_DESTINATIONS & PEP_LOG_DESTINATION_DATABASE)
status = _pEp_log_finalize_database(session);
return status;
}

@ -0,0 +1,543 @@
/**
* @file log.h
* @brief pEp logging facility
* @license GNU General Public License 3.0 - see LICENSE.txt
*/
// (setq show-trailing-whitespace t indicate-empty-lines t)
#ifndef PEP_LOG_H
#define PEP_LOG_H
#include "pEpEngine.h"
#include <stdbool.h>
#include <stdio.h>
#ifdef __cplusplus
extern "C" {
#endif
/* Debugging definitions for myself
* ***************************************************************** */
#define PEP_LOG_LEVEL_MAXIMUM PEP_LOG_LEVEL_EVERYTHING // FIXME: a test for myself, of course
//#define PEP_LOG_DESTINATIONS (PEP_LOG_DESTINATION_STDERR | PEP_LOG_DESTINATION_DATABASE | PEP_LOG_DESTINATION_SYSLOG)
#define PEP_LOG_DESTINATIONS (PEP_LOG_DESTINATION_STDERR | PEP_LOG_DESTINATION_DATABASE)
//#define PEP_LOG_DESTINATIONS PEP_LOG_DESTINATION_ALL
/* If this is enabled then requirements at function entry will also log a line
(level Function) about the function being entered. Since this can make the
logs very noisy I made it possible to disable the feature independently from
PEP_LOG_LEVEL_MAXIMUM , by commenting-out this line. */
#define PEP_LOG_FUNCTION_ENTRY 1
/* If this is enabled then *failed* status checkswill also log a line (level
NonOK) about the expression, usually a function call, failing. Since this
can make the logs noisy I made it possible to disable the feature
independently from PEP_LOG_LEVEL_MAXIMUM , by commenting-out this line. */
#define PEP_LOG_LOCAL_FAILURE 1
/* Every time database rows become more than this number delete the oldest one.
This is needed to prevent the database from growing to an unbounded size.
Just as a rule of thumb:
- 10000 entries take 1MB
- 1 entry takes ~100B */
#define PEP_LOG_DATABASE_ROW_NO_MAXIMUM 100000
/* Introduction
* ***************************************************************** */
/* This general-purpose log facility is used internally in the Engine, but is
also meant for adapters and applications. The pEp logging facility can
output information to any number of "destinations" among the supported ones:
databases, standard error, syslog, system-dependent outputs, and so on.
Each log entry consists of:
* a "level", describing the verbosity associated to the current entry;
* a system name;
* a sub-system name;
* a user-specified string;
* precise source location: source file name, line number, function name;
* timing information.
Global configuration allows to suppress long entries above a given verbosity.
At least when called from C this facility is meant to be used from the macro
API, which is much more convenient: in particular the macro API allows the
user to specify the entry string as a literal string template along with a
set of values to be filled in the template, following the formatted output
conventions of printf.
The function API below serves as the internal implementation of the macro
API, and possibly for calling the log facility from non-C languages. */
/* How to use
* ***************************************************************** */
/* A convenient way of using this facility for debugging prints is to define
a CPP macro with a short name and only variadic parameters directly in the
C file where it will be used; then one can add calls to the local macro in
the functions being debugged.
For example imagine a "frob" application containg a source file quux.c, with
some of the content as shown here:
98 #define LOG(...) PEP_LOG_TRACE("frob", NULL, __VA_ARGS__)
99
100 void foo(int x) {
101 LOG("About to call bar. x is %i", x);
102 bar();
103 int y = x + 2;
104 LOG("y is %i", y);
105 LOG();
106 }
107
108 void bar(void) {
109 LOG("Hello");
110 }
Notice the call at line 105, which will only show the function name and
source location. The template is completely absent in that case: one does
not even need to supply an empty string; however the template string, when
supplied, must be a literal, due to the implementation with token-level
string concatenation through CPP.
Assuming PEP_LOG_LEVEL_MAXIMUM to be at least PEP_LOG_LEVEL_TRACE the log
will contain something like:
2022-09-23 20:39:13 frob 523621 trc quux.c:101:foo About to call bar. x is 10
2022-09-23 20:39:13 frob 523621 trc quux.c:109:bar Hello
2022-09-23 20:39:13 frob 523621 trc quux.c:104:foo y is 12
2022-09-23 20:39:13 frob 523621 trc quux.c:105:foo
Here "trc" is an abbreviation of the log level name; 523621 is the process id
of the running process; (it would be useful to show a thread id as well next