ExternalVendorCode/serval-dna
1
0
Fork 0
mirror of https://github.com/servalproject/serval-dna.git synced 2024-12-18 12:56:29 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Rewrite logging system

Browse Source 
Rename the logging primitive functions and utility functions, prefixing
all with 'serval_log', eg: logMessage() -> serval_logf() etc.

Add an XPRINTF xhexdump() function and use it to implement the
serval_log_hexdump() utility, renamed from dump().  Add macros
WHY_dump(), WARN_dump(), HINT_dump() and DEBUG_dump(), and use them
everywhere.

Remove the 'log.console.dump_config' and 'log.file.dump_config'
configuration options; configuration is now dumped in every log prolog.

The logging system now constructs the log prolog by invoking the new
'log_prolog' trigger, so that it no longer depends on the version string
and configuration system.  Any system that wants to present a message in
the log prolog can define its own trigger, which calls standard log
primitives to print the message.

Split the logging system into a front-end (log.c) that provides the
logging primitives and is independent of the configuration system, and a
set of back-end "outputters" (log_output_console.c, log_output_file.c,
log_output_android.c) that may depend on the configuration system and
are decoupled from the front-end using the 'logoutput' link section.

These log outputters are explicitly linked into executables by the
Makefile rules, but could also be linked in using USE_FEATURE().  The
USE_FEATURE() calls have _not_ been added to servald_features.c, so that
different daemon executables can be built with the same feature set but
different log outputs.
This commit is contained in:
Andrew Bettison 2017-11-30 00:04:54 +10:30
parent 71e654a615
commit 92fa6c196a
43 changed files with 1369 additions and 758 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
Makefile.in
View File

@ -302,17 +302,26 @@ libservaldaemon.a: _servald.a $(LIBSODIUM_A)
libservaldaemon.so: \
$(OBJSDIR_SERVALD)/servald_features.o \
$(OBJSDIR_SERVALD)/log_output_console.o \
$(OBJSDIR_SERVALD)/log_output_file.o \
$(SERVAL_DAEMON_JNI_OBJS) \
_servald.a \
$(LIBSODIUM_A)
@echo LINK $@
@$(CC) -Wall -shared -o $@ $(LDFLAGS) $(filter %.o, $^) $(filter %.a, $^)
servald: $(OBJSDIR_SERVALD)/servald_features.o libservaldaemon.a
# The daemon executable. There is no main.o mentioned in this link line, so
# the link brings it in from libservaldaemon.a in order to resolve the 'main'
# symbol. The servald_features.o object causes all the other .o object files
# to be pulled into the link.
servald: $(OBJSDIR_SERVALD)/servald_features.o \
$(OBJSDIR_SERVALD)/log_output_console.o \
$(OBJSDIR_SERVALD)/log_output_file.o \
libservaldaemon.a
@echo LINK $@
@$(CC) -Wall -o $@ $^ $(LDFLAGS)
servaldwrap: $(OBJSDIR_SERVALD)/servalwrap.o $(OBJSDIR_TOOLS)/version.o
servaldwrap: $(OBJSDIR_SERVALD)/servalwrap.o
@echo LINK $@
@$(CC) -Wall -o $@ $^ $(LDFLAGS)

5
commandline.h
View File

@ -22,6 +22,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#define __SERVAL_DNA__COMMANDLINE_H
#include <stdio.h> // for FILE
#include "lang.h" // for _APPEND() macro
#include "section.h"
#include "trigger.h"
#include "cli.h"
@ -30,10 +31,6 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#define KEYRING_ENTRY_PIN_OPTION ,"[--entry-pin=<pin>]"
#define KEYRING_PIN_OPTIONS KEYRING_PIN_OPTION KEYRING_ENTRY_PIN_OPTION "..."
// macros are weird sometimes ....
#define __APPEND_(X,Y) X ## Y
#define _APPEND(X,Y) __APPEND_(X,Y)
#define DEFINE_CMD(FUNC, FLAGS, HELP, WORD1, ...) \
static int FUNC(const struct cli_parsed *parsed, struct cli_context *context); \
static struct cli_schema _APPEND(FUNC, __LINE__) IN_SECTION(commands) = {\

55
conf.c
View File

@ -25,6 +25,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include "conf.h"
#include "instance.h"
#include "log.h"
#include "log_prolog.h"
#include "debug.h"
#include "str.h"
#include "mem.h"
@ -233,27 +234,28 @@ static int reload_and_parse(int permissive, int strict)
WARNF("config file %s loaded despite defects -- %s", conffile_path(), strbuf_str(b));
}
}
// Dump the log file before setting cf_limbo=0, so that:
// - if we are currently in limbo this will print no dump, then as soon as limbo goes off the
// very next log message will emit the prolog at the top of the log, which includes a dump of
// the newly loaded configuration;
// - if not currently in limbo, then will print a dump, which may differ from the dump that
// already appears in the log's prolog.
cf_dump_to_log("Configuration reloaded");
cf_limbo = 0; // let log messages out
logFlush();
serval_log_flush();
if (changed) {
CALL_TRIGGER(conf_log);
CALL_TRIGGER(conf_change);
}
return ret;
}
// Put a dummy no-op trigger callback into the "config_change" and "config_log" trigger sections,
// otherwise if no other object provides one, the link will fail with errors like:
// Put a dummy no-op trigger callback into the "config_change" trigger section, otherwise if no
// other object provides one, the link will fail with errors like:
// undefined reference to `__start_tr_config_change'
// undefined reference to `__stop_tr_config_change'
static void __dummy_on_config_log();
DEFINE_TRIGGER(conf_log, __dummy_on_config_log);
static void __dummy_on_config_log() {}
static void __dummy_on_config_change();
DEFINE_TRIGGER(conf_change, __dummy_on_config_change);
static void __dummy_on_config_change() {}
DEFINE_TRIGGER(conf_change, __dummy_on_config_change);
// The configuration API entry points.
@ -289,3 +291,36 @@ int cf_reload_permissive()
{
return reload_and_parse(1, 0);
}
void cf_dump_to_log(const char *heading)
{
if (cf_limbo)
return;
struct cf_om_node *root = NULL;
int ret = cf_fmt_config_main(&root, &config);
if (ret == CFERROR) {
WHY("cannot dump current configuration: cf_fmt_config_main() returned CFERROR");
} else {
NOWHENCE(INFOF("%s:", heading));
struct cf_om_iterator oit;
int empty = 1;
for (cf_om_iter_start(&oit, root); oit.node; cf_om_iter_next(&oit)) {
if (oit.node->text && oit.node->line_number) {
empty = 0;
NOWHENCE(INFOF(" %s=%s", oit.node->fullkey, oit.node->text));
}
}
if (empty)
NOWHENCE(INFO(" (empty)"));
}
cf_om_free_node(&root);
}
/* Dump the configuration in the prolog of every log file.
*/
static void log_prolog_dump_config() {
cf_dump_to_log("Current configuration");
}
DEFINE_TRIGGER(log_prolog, log_prolog_dump_config);

2
conf.h
View File

@ -722,8 +722,8 @@ int cf_load_permissive(void);
int cf_reload(void);
int cf_reload_strict(void);
int cf_reload_permissive(void);
void cf_dump_to_log(const char *heading);
DECLARE_TRIGGER(conf_log);
DECLARE_TRIGGER(conf_change);
#endif //__SERVAL_DNA__CONF_H

4
conf_schema.h
View File

@ -278,8 +278,7 @@ END_STRUCT
#define LOG_FORMAT_OPTIONS \
ATOM(bool_t, show_pid, 1, boolean,, "If true, all log lines contain PID of logging process") \
ATOM(bool_t, show_time, 1, boolean,, "If true, all log lines contain time stamp") \
ATOM(int, level, LOG_LEVEL_DEBUG, log_level,, "Only log messages at and above this level of severity") \
ATOM(bool_t, dump_config, 1, boolean,, "If true, current configuration is dumped into start of log")
ATOM(int, level, LOG_LEVEL_DEBUG, log_level,, "Only log messages at and above this level of severity")
STRUCT(log_format)
LOG_FORMAT_OPTIONS
@ -307,7 +306,6 @@ STRUCT_DEFAULT(log_format, console)
ATOM_DEFAULT(show_pid, 0)
ATOM_DEFAULT(show_time, 0)
ATOM_DEFAULT(level, LOG_LEVEL_HINT)
ATOM_DEFAULT(dump_config, 0)
END_STRUCT_DEFAULT
STRUCT_DEFAULT(log_format, android)

3
debug.h
View File

@ -41,7 +41,8 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#define DEBUG(FLAG,X) DEBUGF(FLAG, "%s", (X))
#define DEBUGF_perror(FLAG,F,...) do { if (IF_DEBUG(FLAG)) _DEBUGF_TAG_perror(#FLAG, F, ##__VA_ARGS__); } while (0)
#define DEBUG_perror(FLAG,X) DEBUGF_perror(FLAG, "%s", (X))
#define DEBUG_argv(FLAG,X,ARGC,ARGV) do { if (IF_DEBUG(FLAG)) _DEBUGF_TAG_argv(#FLAG, X, (ARGC), (ARGV)); } while (0)
#define DEBUG_argv(FLAG,X,ARGC,ARGV) do { if (IF_DEBUG(FLAG)) _DEBUG_TAG_argv(#FLAG, X, (ARGC), (ARGV)); } while (0)
#define DEBUG_dump(FLAG,X,ADDR,LEN) do { if (IF_DEBUG(FLAG)) _DEBUG_TAG_dump(#FLAG, X, (ADDR), (LEN)); } while (0)
#define D(FLAG) DEBUG(FLAG, "D")
#define T DEBUG(trace, "T")

2
dna_helper.c
View File

@ -217,7 +217,7 @@ dna_helper_start()
switch (dna_helper_pid = fork()) {
case 0:
/* Child, should exec() to become helper after installing file descriptors. */
close_log_file();
serval_log_close();
setenv("MYSID", mysid, 1);
signal(SIGTERM, SIG_DFL);
close(stdin_fds[1]);

7
fakeradio.c
View File

@ -35,6 +35,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include <sys/time.h>
#include <unistd.h>
#include "os.h"
#include "xprintf.h"
#define PACKET_SIZE 255
int chars_per_ms=1;
@ -143,7 +144,7 @@ int read_bytes(struct radio_state *s)
return bytes;
log_time();
fprintf(stderr, "Read from %s\n", s->name);
dump(NULL,buff,bytes);
xhexdump(XPRINTF_STDIO(stderr), buff, bytes, "");
s->last_char_ms = gettime_ms();
// process incoming bytes
@ -190,7 +191,7 @@ void write_bytes(struct radio_state *s)
if (wrote != -1){
log_time();
fprintf(stderr, "Wrote to %s\n", s->name);
dump(NULL, s->rxbuffer, (size_t)wrote);
xhexdump(XPRINTF_STDIO(stderr), s->rxbuffer, (size_t)wrote, "");
if ((size_t)wrote < s->rxb_len)
bcopy(&s->rxbuffer[(size_t)wrote], s->rxbuffer, s->rxb_len - (size_t)wrote);
s->rxb_len -= (size_t)wrote;
@ -318,7 +319,7 @@ void transfer_bytes(struct radio_state *radios)
if (bytes < PACKET_SIZE && t->wait_count++ <5){
log_time();
fprintf(stderr,"Waiting for more bytes for %s\n", t->name);
dump(NULL, t->txbuffer, bytes);
xhexdump(XPRINTF_STDIO(stderr), t->txbuffer, bytes, "");
}else
send = bytes;
}

1
headerfiles.mk
View File

@ -39,6 +39,7 @@ HDRS= fifo.h \
crypto.h \
dataformats.h \
log.h \
log_output.h \
debug.h \
net.h \
fdqueue.h \

15
keyring.c
View File

@ -1258,10 +1258,8 @@ static int keyring_decrypt_pkr(keyring_file *k, const char *pin, int slot_number
/* compare hash to record */
if (memcmp(hash, &slot[PKR_SALT_BYTES], crypto_hash_sha512_BYTES)) {
DEBUGF(keyring, "slot %u is not valid (MAC mismatch)", slot_number);
if (IF_DEBUG(keyring)){
dump("computed",hash,crypto_hash_sha512_BYTES);
dump("stored",&slot[PKR_SALT_BYTES],crypto_hash_sha512_BYTES);
}
DEBUG_dump(keyring, "computed",hash,crypto_hash_sha512_BYTES);
DEBUG_dump(keyring, "stored",&slot[PKR_SALT_BYTES],crypto_hash_sha512_BYTES);
goto kdp_safeexit;
}
@ -1648,10 +1646,8 @@ int keyring_set_did_name(keyring_identity *id, const char *did, const char *name
bzero(&kp->public_key[len], kp->public_key_len - len);
}
if (IF_DEBUG(keyring)) {
dump("{keyring} storing DID",&kp->private_key[0],32);
dump("{keyring} storing Name",&kp->public_key[0],64);
}
DEBUG_dump(keyring, "storing DID",&kp->private_key[0],32);
DEBUG_dump(keyring, "storing Name",&kp->public_key[0],64);
return 0;
}
@ -1731,8 +1727,7 @@ int keyring_set_public_tag(keyring_identity *id, const char *name, const unsigne
if (keyring_pack_tag(kp->public_key, &kp->public_key_len, name, value, length))
return -1;
if (IF_DEBUG(keyring))
dump("{keyring} New tag", kp->public_key, kp->public_key_len);
DEBUG_dump(keyring, "New tag", kp->public_key, kp->public_key_len);
return 0;
}

10
lang.h
View File

@ -24,10 +24,20 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include "config.h"
#endif
/* Conveniences to assist readability.
*/
typedef char bool_t;
/* Useful macros not specific to Serval DNA that assist with using the C
* language.
*/
// Concatenate two preprocessor symbols, eg, _APPEND(__FUNC__, __LINE__).
#define __APPEND_(X,Y) X ## Y
#define _APPEND(X,Y) __APPEND_(X,Y)
// Number of elements in an array (Warning: does not work if A is a pointer!).
#define NELS(A) (sizeof (A) / sizeof *(A))

756
log.c
View File

@ -1,7 +1,7 @@
/*
Serval DNA logging
Copyright (C) 2013-2015 Serval Project Inc.
Copyright (C) 2016 Flinders University
Copyright (C) 2016-2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
@ -22,197 +22,77 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include <stdlib.h>
#include <stdio.h>
#include <ctype.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <sys/param.h>
#include <time.h>
#include <unistd.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <stdint.h>
#include <dirent.h>
#include <assert.h>
#include "log.h"
#include "log_output.h"
#include "log_prolog.h"
#include "version_servald.h"
#include "instance.h"
#include "log.h"
#include "net.h"
#include "os.h"
#include "conf.h"
#include "str.h"
#include "strbuf.h"
#include "strbuf_helpers.h"
#include "xprintf.h"
#include "trigger.h"
int logLevel_NoLogFileConfigured = LOG_LEVEL_INFO;
#define NO_FILE ((FILE *)1)
/* The _log_state structure records the persistent state associated with a single log output
* destination. The state is only persistent for the lifetime of the process (eg, while the daemon
* is running), and is not stored anywhere else. It is initially zerofilled.
*
* @author Andrew Bettison <andrew@servalproject.com>
/* This thread-local variable is used to support recursion, so that log output operations like
* open() that invoke log primitives will not cause infinite recursion, but instead will log only to
* the output whose iterator they are currently servicing.
*/
struct _log_state {
/* Whether the software version has been logged in the current file yet. */
bool_t version_logged;
/* The time stamp of the last logged message, used to detect when the date advances so that
* the date can be logged. */
struct tm last_tm;
/* Whether the current configuration has been logged in the current file yet. */
bool_t config_logged;
};
static __thread struct log_output_iterator *current_iterator = NULL;
/* The _log_iterator structure is a transient structure that is used to iterate over all the
* supported log output destinations. Generally, one of these is created (as an auto variable)
* every time a log message is generated, and destroyed immediately after the message has been sent
* to all the log outputs.
*
* The log iterator is controlled using various _log_iterator_xxx() functions.
*
* @author Andrew Bettison <andrew@servalproject.com>
/* By default, if there is no log file configured, this is logged as an INFO message, but a server
* can set this to log it at a higher level.
*/
typedef struct _log_iterator {
const struct config_log_format *config;
struct _log_state *state;
struct timeval tv;
struct tm tm;
XPRINTF xpf;
time_t file_start_time;
} _log_iterator;
int serval_log_level_NoLogFileConfigured = LOG_LEVEL_INFO;
/* Static variables for sending log output to a file.
*
* The _log_file_strbuf is used to accumulate log messages before the log file is open and ready for
* writing.
*/
const char *_log_file_path;
char _log_file_path_buf[400];
static FILE *_log_file = NULL;
static void _open_log_file(_log_iterator *);
static void _rotate_log_file(_log_iterator *it);
static void _flush_log_file();
static struct _log_state state_file;
static struct config_log_format config_file;
static struct { size_t len; mode_t mode; } mkdir_trace[10];
static mode_t mkdir_trace_latest_mode;
static unsigned mkdir_count;
static time_t _log_file_start_time;
static char _log_file_buf[8192];
static struct strbuf _log_file_strbuf = STRUCT_STRBUF_EMPTY;
#ifdef ANDROID
/* Static variables for sending log output to the Android log.
*
* The _android_strbuf is used to accumulate a single log line before printing to Android's logging
* API.
*/
#include <android/log.h>
struct _log_state state_android;
static char _log_android_buf[1024];
static struct strbuf _android_strbuf;
#endif // ANDROID
/* Static variables for sending log output to standard error.
*/
static FILE *logfile_stderr = NULL;
struct _log_state state_stderr;
static void _open_log_stderr();
static void _flush_log_stderr();
/* Primitive operations for _log_iterator structures.
/* Primitive operations for log_output_iterator.
*/
static void _log_iterator_start(_log_iterator *it)
static void log_iterator_start(struct log_output_iterator *it)
{
it->output = NULL;
memset(it, 0, sizeof *it);
gettimeofday(&it->tv, NULL);
localtime_r(&it->tv.tv_sec, &it->tm);
it->xpf = XPRINTF_NULL;
}
static void _log_iterator_rewind(_log_iterator *it)
static int log_iterator_advance(struct log_output_iterator *it)
{
it->config = NULL;
it->state = NULL;
assert(it->output != SECTION_END(logoutput));
do {
it->output = it->output ? it->output + 1 : SECTION_START(logoutput);
} while (it->output != SECTION_END(logoutput) && !*it->output); // skip NULL entries
return it->output != SECTION_END(logoutput);
}
static void _log_iterator_advance_to_file(_log_iterator *it)
{
cf_dfl_config_log_format(&config_file);
cf_cpy_config_log_format(&config_file, &config.log.file);
it->config = &config_file;
it->state = &state_file;
}
/* In case no outputters are linked, ensure that the logoutput section exists, by adding a NULL
* entry to it. Otherwise you get link errors like:
* log.c:193: error: undefined reference to '__stop_logoutput'
*/
#ifdef ANDROID
static void _log_iterator_advance_to_android(_log_iterator *it)
{
it->config = &config.log.android;
it->state = &state_android;
}
#endif // ANDROID
DEFINE_LOG_OUTPUT(NULL);
static void _log_iterator_advance_to_stderr(_log_iterator *it)
{
it->config = &config.log.console;
it->state = &state_stderr;
}
/* Functions for formatting log messages.
*/
static int _log_iterator_advance(_log_iterator *it)
static void print_line_prefix(struct log_output_iterator *it)
{
if (it->config == NULL) {
_log_iterator_advance_to_file(it);
return 1;
}
if (it->config == &config_file) {
#ifdef ANDROID
_log_iterator_advance_to_android(it);
return 1;
}
if (it->config == &config.log.android) {
#endif // ANDROID
_log_iterator_advance_to_stderr(it);
return 1;
}
return 0;
}
assert(it->output);
struct log_output *out = *it->output;
assert(out);
static int _log_enabled(_log_iterator *it)
{
if (it->config == &config_file) {
_open_log_file(it); // puts initial INFO message(s) at head of log file
if (_log_file == NO_FILE)
return 0;
}
else if (it->config == &config.log.console) {
_open_log_stderr();
if (logfile_stderr == NULL || logfile_stderr == NO_FILE)
return 0;
}
return 1;
}
static void _log_prefix_level(_log_iterator *it, int level)
{
const char *levelstr = "UNKWN:";
switch (level) {
case LOG_LEVEL_FATAL: levelstr = "FATAL:"; break;
case LOG_LEVEL_ERROR: levelstr = "ERROR:"; break;
case LOG_LEVEL_WARN: levelstr = "WARN:"; break;
case LOG_LEVEL_HINT: levelstr = "HINT:"; break;
case LOG_LEVEL_INFO: levelstr = "INFO:"; break;
case LOG_LEVEL_DEBUG: levelstr = "DEBUG:"; break;
}
xprintf(it->xpf, "%-6.6s", levelstr);
}
static void _log_prefix_context(_log_iterator *it)
{
if (it->config->show_pid)
if (out->show_pid(out))
xprintf(it->xpf, "[%5u] ", getpid());
if (it->config->show_time) {
if (out->show_time(out)) {
if (it->tv.tv_sec == 0) {
xputs("NOTIME______ ", it->xpf);
} else {
@ -223,6 +103,7 @@ static void _log_prefix_context(_log_iterator *it)
xprintf(it->xpf, "%s.%03u ", buf, (unsigned int)it->tv.tv_usec / 1000);
}
}
if (strbuf_len(&log_context)) {
xputs("[", it->xpf);
xputs(strbuf_str(&log_context), it->xpf);
@ -230,354 +111,198 @@ static void _log_prefix_context(_log_iterator *it)
}
}
static void _log_prefix(_log_iterator *it, int level)
{
if (it->config == &config_file) {
if (strbuf_is_empty(&_log_file_strbuf))
strbuf_init(&_log_file_strbuf, _log_file_buf, sizeof _log_file_buf);
else if (strbuf_len(&_log_file_strbuf))
strbuf_putc(&_log_file_strbuf, '\n');
it->xpf = XPRINTF_STRBUF(&_log_file_strbuf);
_log_prefix_level(it, level);
}
#ifdef ANDROID
else if (it->config == &config.log.android) {
strbuf_init(&_android_strbuf, _log_android_buf, sizeof _log_android_buf);
it->xpf = XPRINTF_STRBUF(&_android_strbuf);
}
#endif // ANDROID
else if (it->config == &config.log.console) {
it->xpf = XPRINTF_STDIO(logfile_stderr);
_log_prefix_level(it, level);
}
else
abort();
_log_prefix_context(it);
}
static void _log_prefix_whence(_log_iterator *it, struct __sourceloc whence)
static void whence_prefix(struct log_output_iterator *it, struct __sourceloc whence)
{
assert(!XPRINTF_IS_NULL(it->xpf));
if ((whence.file && whence.file[0]) || (whence.function && whence.function[0])) {
xprint_sourceloc(it->xpf, whence);
xputs(" ", it->xpf);
}
}
static void _log_end_line(_log_iterator *it, int UNUSED(level))
/* Log output operations.
*/
static void log_open(struct log_output_iterator *it)
{
#ifdef ANDROID
if (it->config == &config.log.android) {
int alevel = ANDROID_LOG_UNKNOWN;
switch (level) {
case LOG_LEVEL_FATAL: alevel = ANDROID_LOG_FATAL; break;
case LOG_LEVEL_ERROR: alevel = ANDROID_LOG_ERROR; break;
case LOG_LEVEL_WARN: alevel = ANDROID_LOG_WARN; break;
case LOG_LEVEL_HINT:
case LOG_LEVEL_INFO: alevel = ANDROID_LOG_INFO; break;
case LOG_LEVEL_DEBUG: alevel = ANDROID_LOG_DEBUG; break;
default: abort();
}
__android_log_print(alevel, "servald", "%s", _log_android_buf);
}
else
#endif // ANDROID
if (it->config == &config.log.console) {
fputc('\n', logfile_stderr);
}
assert(it->output);
assert(*it->output);
if ((*it->output)->open)
(*it->output)->open(it);
}
static void _log_flush(_log_iterator *it)
static bool_t is_log_available(struct log_output_iterator *it)
{
if (it->config == &config_file) {
_flush_log_file();
}
else if (it->config == &config.log.console) {
_flush_log_stderr();
}
assert(it->output);
assert(*it->output);
return !(*it->output)->is_available || (*it->output)->is_available(it);
}
static void _log_vprintf_nl(_log_iterator *it, int level, const char *fmt, va_list ap)
{
_log_prefix(it, level);
vxprintf(it->xpf, fmt, ap);
_log_end_line(it, level);
}
static void _log_printf_nl(_log_iterator *it, int level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
_log_vprintf_nl(it, level, fmt, ap);
va_end(ap);
}
static void _log_current_datetime(_log_iterator *it, int level)
{
char buf[50];
if (strftime(buf, sizeof buf, "%F %T %z", &it->tm)) {
_log_printf_nl(it, level, "Local date/time: %s", buf);
it->state->last_tm = it->tm;
}
}
static void _log_software_version(_log_iterator *it, int level)
{
_log_printf_nl(it, level, "Serval DNA version: %s", version_servald);
it->state->version_logged = 1;
}
static int _log_current_config(_log_iterator *it, int level)
{
if (!cf_limbo) {
// if formatting config causes anything else to be logged, ignore it.
cf_limbo=1;
struct cf_om_node *root = NULL;
int ret = cf_fmt_config_main(&root, &config);
if (ret == CFERROR) {
_log_printf_nl(it, level, "Cannot dump current configuration: cf_fmt_config_main() returned CFERROR");
} else {
_log_printf_nl(it, level, "Current configuration:");
struct cf_om_iterator oit;
int empty = 1;
for (cf_om_iter_start(&oit, root); oit.node; cf_om_iter_next(&oit)) {
if (oit.node->text && oit.node->line_number) {
empty = 0;
_log_printf_nl(it, level, " %s=%s", oit.node->fullkey, oit.node->text);
}
}
if (empty)
_log_printf_nl(it, level, " (empty)");
}
cf_om_free_node(&root);
it->state->config_logged = 1;
cf_limbo=0;
}
return 1;
}
static void _log_update(_log_iterator *it)
{
if ( it->tm.tm_mday != it->state->last_tm.tm_mday
|| it->tm.tm_mon != it->state->last_tm.tm_mon
|| it->tm.tm_year != it->state->last_tm.tm_year
)
_log_current_datetime(it, LOG_LEVEL_INFO);
if (!it->state->version_logged)
_log_software_version(it, LOG_LEVEL_INFO);
if (it->config->dump_config && !it->state->config_logged)
_log_current_config(it, LOG_LEVEL_INFO);
}
static int _log_iterator_next(_log_iterator *it, int level)
static void log_start_line(struct log_output_iterator *it, int level)
{
assert(level >= LOG_LEVEL_SILENT);
assert(level <= LOG_LEVEL_FATAL);
_log_end_line(it, level);
_log_flush(it);
while (_log_iterator_advance(it)) {
if (level >= it->config->level && _log_enabled(it)) {
_log_update(it);
_log_prefix(it, level);
return 1;
}
}
return 0;
assert(XPRINTF_IS_NULL(it->xpf));
assert(it->output);
assert(*it->output);
assert((*it->output)->start_line);
(*it->output)->start_line(it, level);
assert(!XPRINTF_IS_NULL(it->xpf));
print_line_prefix(it);
}
static void _log_iterator_vprintf_nl(_log_iterator *it, int level, struct __sourceloc whence, const char *fmt, va_list ap)
static void log_end_line(struct log_output_iterator *it, int level)
{
_log_iterator_rewind(it);
while (_log_iterator_next(it, level)) {
_log_prefix_whence(it, whence);
va_list ap1;
va_copy(ap1, ap);
vxprintf(it->xpf, fmt, ap1);
va_end(ap1);
assert(level >= LOG_LEVEL_SILENT);
assert(level <= LOG_LEVEL_FATAL);
assert(!XPRINTF_IS_NULL(it->xpf));
assert(it->output);
assert(*it->output);
if ((*it->output)->end_line)
(*it->output)->end_line(it, level);
it->xpf = XPRINTF_NULL;
}
static void log_flush(struct log_output_iterator *it)
{
assert(it->output);
assert(*it->output);
if ((*it->output)->flush)
(*it->output)->flush(it);
}
static void log_close(struct log_output_iterator *it)
{
assert(it->output);
assert(*it->output);
if ((*it->output)->close)
(*it->output)->close(it);
}
static void log_capture_fd(struct log_output_iterator *it, int fd, bool_t *captured)
{
assert(it->output);
assert(*it->output);
if ((*it->output)->capture_fd)
(*it->output)->capture_fd(it, fd, captured);
}
/* Functions for use by log outputters. This is the "private" API of the logging system, as
* described in "log_output.h".
*/
const char *serval_log_level_prefix_string(int level)
{
switch (level) {
case LOG_LEVEL_FATAL: return "FATAL:";
case LOG_LEVEL_ERROR: return "ERROR:";
case LOG_LEVEL_WARN: return "WARN: ";
case LOG_LEVEL_HINT: return "HINT: ";
case LOG_LEVEL_INFO: return "INFO: ";
case LOG_LEVEL_DEBUG: return "DEBUG:";
default: return "UNKWN:";
}
}
static void _logs_vprintf_nl(int level, struct __sourceloc whence, const char *fmt, va_list ap)
void serval_log_output_iterator_vprintf_nl(struct log_output_iterator *it, int level, const char *fmt, va_list ap)
{
_log_iterator it;
_log_iterator_start(&it);
_log_iterator_vprintf_nl(&it, level, whence, fmt, ap);
log_start_line(it, level);
vxprintf(it->xpf, fmt, ap);
log_end_line(it, level);
}
static void _logs_printf_nl(int level, struct __sourceloc whence, const char *fmt, ...)
void serval_log_output_iterator_printf_nl(struct log_output_iterator *it, int level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
_logs_vprintf_nl(level, whence, fmt, ap);
serval_log_output_iterator_vprintf_nl(it, level, fmt, ap);
va_end(ap);
}
static void _compute_file_start_time(_log_iterator *it)
static void print_datetime(struct log_output_iterator *it, int level)
{
if (it->file_start_time == 0) {
assert(!cf_limbo);
assert(it->tv.tv_sec != 0);
it->file_start_time = it->tv.tv_sec;
if (config.log.file.duration)
it->file_start_time -= it->file_start_time % config.log.file.duration;
char buf[50];
if (strftime(buf, sizeof buf, "%F %T %z", &it->tm)) {
serval_log_output_iterator_printf_nl(it, level, "Local date/time: %s", buf);
(*it->output)->last_tm = it->tm;
}
}
static void trace_mkdir(struct __sourceloc UNUSED(whence), const char *path, mode_t mode)
static void print_newdate(struct log_output_iterator *it)
{
if (mkdir_count < NELS(mkdir_trace)) {
mkdir_trace[mkdir_count].len = strlen(path);
mkdir_trace[mkdir_count].mode = mode;
}
++mkdir_count;
mkdir_trace_latest_mode = mode;
struct log_output *out = *it->output;
if ( it->tm.tm_mday != out->last_tm.tm_mday
|| it->tm.tm_mon != out->last_tm.tm_mon
|| it->tm.tm_year != out->last_tm.tm_year
)
print_datetime(it, LOG_LEVEL_INFO);
}
static void log_mkdir_trace(const char *dir)
void serval_log_print_prolog(struct log_output_iterator *it)
{
unsigned i;
for (i = 0; i < mkdir_count && i < NELS(mkdir_trace); ++i)
_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created %s (mode %04o)", alloca_toprint(-1, dir, mkdir_trace[i].len), mkdir_trace[i].mode);
if (mkdir_count > NELS(mkdir_trace) + 1)
_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created ...");
if (mkdir_count > NELS(mkdir_trace))
_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Created %s (mode %04o)", alloca_str_toprint(dir), mkdir_trace_latest_mode);
assert(current_iterator == NULL || current_iterator == it);
struct log_output_iterator *save_current_iterator = current_iterator;
current_iterator = it;
print_datetime(it, LOG_LEVEL_INFO);
CALL_TRIGGER(log_prolog);
current_iterator = save_current_iterator;
}
static void _open_log_file(_log_iterator *it)
// Put a dummy no-op trigger callback into the "log_prolog" trigger section, otherwise if no other
// object provides one, the link will fail with errors like:
// undefined reference to `__start_tr_log_prolog'
// undefined reference to `__stop_tr_log_prolog'
static void __dummy_on_log_prolog() {}
DEFINE_TRIGGER(log_prolog, __dummy_on_log_prolog);
/* Private helper functions for formatting and emitting log messages.
*/
static void iterator_vprintf_nl(struct log_output_iterator *it, int level, struct __sourceloc whence, const char *fmt, va_list ap)
{
assert(it->state == &state_file);
if (_log_file != NO_FILE) {
if (_log_file_path == NULL)
_log_file_path = getenv("SERVALD_LOG_FILE");
if (_log_file_path == NULL && !cf_limbo) {
strbuf sbfile = strbuf_local_buf(_log_file_path_buf);
strbuf_serval_log_path(sbfile);
strbuf_path_join(sbfile, config.log.file.directory_path, "", NULL); // with trailing '/'
_compute_file_start_time(it);
if (config.log.file.path[0]) {
strbuf_path_join(sbfile, config.log.file.path, NULL);
} else {
struct tm tm;
(void)localtime_r(&it->file_start_time, &tm);
strbuf_append_strftime(sbfile, "serval-%Y%m%d%H%M%S.log", &tm);
}
if (strbuf_overrun(sbfile)) {
_log_file = NO_FILE;
_logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot form log file name - buffer overrun");
} else {
_log_file_start_time = it->file_start_time;
_log_file_path = strbuf_str(sbfile);
}
assert(current_iterator);
log_start_line(it, level);
whence_prefix(it, whence);
va_list ap1;
va_copy(ap1, ap);
vxprintf(it->xpf, fmt, ap1);
va_end(ap1);
log_end_line(it, level);
}
/* Logging primitives. This is the "public" API of the logging system, as described in "log.h".
*/
void serval_vlogf(int level, struct __sourceloc whence, const char *fmt, va_list ap)
{
if (level != LOG_LEVEL_SILENT) {
if (current_iterator) {
// This occurs if a log primitive is invoked recursively from within a log output, which is
// typically an open() operation calling serval_log_print_prolog(it). In this case, the log
// output only goes to the single output in question, not to all outputs.
iterator_vprintf_nl(current_iterator, level, whence, fmt, ap);
}
if (!_log_file) {
if (_log_file_path == NULL) {
if (cf_limbo)
return;
_log_file = NO_FILE;
_logs_printf_nl(logLevel_NoLogFileConfigured, __NOWHERE__, "No log file configured");
} else {
// Create the new log file.
size_t dirsiz = strlen(_log_file_path) + 1;
char _dir[dirsiz];
strcpy(_dir, _log_file_path);
const char *dir = dirname(_dir); // modifies _dir[]
mkdir_count = 0;
if (mkdirs_log(dir, 0700, trace_mkdir) == -1) {
_log_file = NO_FILE;
log_mkdir_trace(dir);
_logs_printf_nl(LOG_LEVEL_WARN, __HERE__, "Cannot mkdir %s - %s [errno=%d]", alloca_str_toprint(dir), strerror(errno), errno);
} else if ((_log_file = fopen(_log_file_path, "a")) == NULL) {
_log_file = NO_FILE;
log_mkdir_trace(dir);
_logs_printf_nl(LOG_LEVEL_WARN, __HERE__, "Cannot create-append %s - %s [errno=%d]", _log_file_path, strerror(errno), errno);
} else {
setlinebuf(_log_file);
memset(it->state, 0, sizeof *it->state);
// The first line in every log file must be the starting time stamp. (After that, it is up
// to _log_update() to insert other mandatory messages in any suitable order.)
_log_current_datetime(it, LOG_LEVEL_INFO);
log_mkdir_trace(dir);
_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Logging to %s (fd %d)", _log_file_path, fileno(_log_file));
// if stderr should be redirected
if (logfile_stderr == NO_FILE)
dup2(fileno(_log_file),STDERR_FILENO);
// Update the log symlink to point to the latest log file.
strbuf sbsymlink = strbuf_alloca(400);
strbuf_system_log_path(sbsymlink);
strbuf_path_join(sbsymlink, "serval.log", NULL);
if (strbuf_overrun(sbsymlink))
_logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot form log symlink name - buffer overrun");
else {
const char *f = _log_file_path;
const char *s = strbuf_str(sbsymlink);
const char *relpath = f;
for (; *f && *f == *s; ++f, ++s)
if (*f == '/')
relpath = f;
while (*relpath == '/')
++relpath;
while (*s == '/')
++s;
if (strchr(s, '/'))
relpath = _log_file_path;
// If racing with another process at this exact same point, then the symlink(2) call may
// fail with EEXIST, in which case log a warning, not an error.
unlink(strbuf_str(sbsymlink));
if (symlink(relpath, strbuf_str(sbsymlink)) == -1)
_logs_printf_nl(errno == EEXIST ? LOG_LEVEL_WARN : LOG_LEVEL_ERROR,
__HERE__,
"Cannot symlink %s -> %s - %s [errno=%d]",
strbuf_str(sbsymlink), relpath, strerror(errno), errno);
else {
struct log_output_iterator it;
log_iterator_start(&it);
while (log_iterator_advance(&it)) {
struct log_output *out = *it.output;
if (level >= out->minimum_level(out)) {
// If the open() operation recurses by invoking a log primitive directly, then print that
// message to all available outputs but avoid recursing into open() operations that are
// already being called.
if (!out->opening) {
out->opening = 1;
log_open(&it);
out->opening = 0;
}
// Expire old log files.
size_t pathsiz = strlen(_log_file_path) + 1;
char path[pathsiz];
while (1) {
strcpy(path, _log_file_path);
const char *base = basename(path); // modifies path[]
DIR *d = opendir(dir);
if (!d) {
_logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot expire log files: opendir(%s) - %s [errno=%d]", dir, strerror(errno), errno);
break;
}
struct dirent oldest;
memset(&oldest, 0, sizeof oldest);
unsigned count = 0;
while (1) {
errno = 0;
struct dirent *ent = readdir(d);
if (ent == NULL) {
if (errno)
_logs_printf_nl(LOG_LEVEL_ERROR, __HERE__, "Cannot expire log files: readdir(%s) - %s [errno=%d]", dir, strerror(errno), errno);
break;
}
const char *e;
if ( str_startswith(ent->d_name, "serval-", &e)
&& isdigit(e[0]) && isdigit(e[1]) && isdigit(e[2]) && isdigit(e[3]) // YYYY
&& isdigit(e[4]) && isdigit(e[5]) // MM
&& isdigit(e[6]) && isdigit(e[7]) // DD
&& isdigit(e[8]) && isdigit(e[9]) // HH
&& isdigit(e[10]) && isdigit(e[11]) // MM
&& isdigit(e[12]) && isdigit(e[13]) // SS
&& strcmp(&e[14], ".log") == 0
) {
++count;
if ( strcmp(ent->d_name, base) != 0
&& (!oldest.d_name[0] || strcmp(ent->d_name, oldest.d_name) < 0)
)
oldest = *ent;
}
}
closedir(d);
if (count <= config.log.file.rotate || !oldest.d_name[0])
break;
strbuf b = strbuf_local(path, pathsiz);
strbuf_path_join(b, dir, oldest.d_name, NULL);
assert(!strbuf_overrun(b));
_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Unlink %s", path);
unlink(path);
if (is_log_available(&it)) {
current_iterator = &it;
print_newdate(&it);
iterator_vprintf_nl(&it, level, whence, fmt, ap);
log_flush(&it);
current_iterator = NULL;
}
}
}
@ -585,101 +310,30 @@ static void _open_log_file(_log_iterator *it)
}
}
static void _rotate_log_file(_log_iterator *it)
void serval_log_flush()
{
if (!cf_limbo && _log_file != NO_FILE && _log_file_path == _log_file_path_buf) {
if (!config.log.file.path[0] && config.log.file.duration) {
_compute_file_start_time(it);
if (it->file_start_time != _log_file_start_time) {
// Close the current log file, which will cause _open_log_file() to open the next one.
if (_log_file)
fclose(_log_file);
_log_file = NULL;
_log_file_path = NULL;
}
}
}
assert(!current_iterator);
struct log_output_iterator it;
log_iterator_start(&it);
while (log_iterator_advance(&it))
log_flush(&it);
}
static void _flush_log_file()
void serval_log_close()
{
if (_log_file && _log_file != NO_FILE && strbuf_len(&_log_file_strbuf) != 0) {
fprintf(_log_file, "%s%s%s",
strbuf_len(&_log_file_strbuf) ? strbuf_str(&_log_file_strbuf) : "",
strbuf_len(&_log_file_strbuf) ? "\n" : "",
strbuf_overrun(&_log_file_strbuf) ? "LOG OVERRUN\n" : ""
);
strbuf_reset(&_log_file_strbuf);
}
assert(!current_iterator);
struct log_output_iterator it;
log_iterator_start(&it);
while (log_iterator_advance(&it))
log_close(&it);
}
/* Discard any unwritten log messages and close the log file immediately. This should be called in
* any child process immediately after fork() to prevent any buffered log messages from being
* written twice into the log file.
*
* @author Andrew Bettison <andrew@servalproject.com>
*/
void close_log_file()
{
strbuf_reset(&_log_file_strbuf);
if (_log_file && _log_file != NO_FILE)
fclose(_log_file);
_log_file = NULL;
}
static void _open_log_stderr()
{
if (!logfile_stderr) {
logfile_stderr = stderr;
setlinebuf(logfile_stderr);
}
}
static void _flush_log_stderr()
{
if (logfile_stderr && logfile_stderr != NO_FILE)
fflush(logfile_stderr);
}
void redirect_stderr_to_log()
{
if (logfile_stderr && logfile_stderr != NO_FILE) {
fflush(logfile_stderr);
logfile_stderr = NO_FILE;
}
}
void logFlush()
{
_log_iterator it;
_log_iterator_start(&it);
while (_log_iterator_advance(&it))
_log_flush(&it);
}
void vlogMessage(int level, struct __sourceloc whence, const char *fmt, va_list ap)
{
if (level != LOG_LEVEL_SILENT) {
_log_iterator it;
_log_iterator_start(&it);
_rotate_log_file(&it);
while (_log_iterator_next(&it, level)) {
_log_prefix_whence(&it, whence);
va_list ap1;
va_copy(ap1, ap);
vxprintf(it.xpf, fmt, ap1);
va_end(ap1);
}
}
}
static void logConfigChanged();
DEFINE_TRIGGER(conf_log, logConfigChanged);
static void logConfigChanged()
{
_log_iterator it;
_log_iterator_start(&it);
while (_log_iterator_advance(&it))
it.state->config_logged = 0;
logFlush();
bool_t serval_log_capture_fd(int fd) {
assert(!current_iterator);
struct log_output_iterator it;
log_iterator_start(&it);
bool_t captured = 0;
while (log_iterator_advance(&it))
log_capture_fd(&it, fd, &captured);
return captured;
}

120
log.h
View File

@ -49,87 +49,111 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
const char *log_level_as_string(int level);
int string_to_log_level(const char *text);
// Log output control.
extern int logLevel_NoLogFileConfigured;
void close_log_file();
void redirect_stderr_to_log();
void logFlush();
// Logging primitives:
// Logging context string.
// Log a message via all available log outputs.
void serval_vlogf(int level, struct __sourceloc whence, const char *fmt, va_list ap);
// Flush all log outputs.
void serval_log_flush();
// Close all log outputs without flushing; they will be re-opened on the next
// vLogMessage(). This is mainly used in forked child processes, to ensure
// that the child process does not share open file descriptors with the parent
// process.
void serval_log_close();
// If possible, capture all output written to the given file descriptor in a
// persistent log format, such as a file or an operating system log. Any
// output that produces a persistent log and is able to redirect the file
// descriptor into that log will do so. If any output is already writing to
// the file descriptor (eg, the console output, which writes to fd 2) then that
// output will cease writing to that file descriptor. Returns true if the file
// descriptor has been redirected successfully.
bool_t serval_log_capture_fd(int fd);
// Logging context string -- if non-empty, then is prefixed to all log messages
// inside square brackets.
struct strbuf;
extern struct strbuf log_context;
// Logging primitives.
void vlogMessage(int level, struct __sourceloc whence, const char *fmt, va_list);
int logBacktrace(int level, struct __sourceloc whence);
// The log level to use for the message that no log file output is configured.
extern int serval_log_level_NoLogFileConfigured;
__SERVAL_LOG_INLINE void logMessage(int level, struct __sourceloc whence, const char *fmt, ...)
// The following logging utilities are implemented entirely in terms of the
// above primitives.
__SERVAL_LOG_INLINE void serval_logf(int level, struct __sourceloc whence, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
vlogMessage(level, whence, fmt, ap);
serval_vlogf(level, whence, fmt, ap);
va_end(ap);
}
__SERVAL_LOG_INLINE int logErrorAndReturnNegativeOne(struct __sourceloc whence, const char *fmt, ...)
__SERVAL_LOG_INLINE int serval_logf_and_return(int retval, struct __sourceloc whence, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
vlogMessage(LOG_LEVEL_ERROR, whence, fmt, ap);
serval_vlogf(LOG_LEVEL_ERROR, whence, fmt, ap);
va_end(ap);
return -1;
return retval;
}
// Useful logging primitive macros.
#define LOGF(L,F,...) logMessage(L, __WHENCE__, F, ##__VA_ARGS__)
#define LOGF_perror(L,F,...) logMessage(L, __WHENCE__, F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define LOG_perror(L,X) LOGF_perror(L, "%s", (X))
int serval_log_backtrace(int level, struct __sourceloc whence);
void serval_log_argv(int level, struct __sourceloc whence, const char *label, int argc, const char *const *argv);
int serval_log_hexdump(int level, struct __sourceloc whence, char *name, const unsigned char *addr, size_t len);
void serval_log_multiline(int level, struct __sourceloc whence, const char *str);
#define NOWHENCE(LOGSTMT) do { const struct __sourceloc __whence = __NOWHENCE__; LOGSTMT; } while (0)
// Convenient logging macros.
#define BACKTRACE logBacktrace(LOG_LEVEL_FATAL, __WHENCE__)
#define LOGF(L,F,...) serval_logf(L, __WHENCE__, F, ##__VA_ARGS__)
#define LOGF_perror(L,F,...) serval_logf(L, __WHENCE__, F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define LOG_perror(L,X) LOGF_perror(L, "%s", (X))
#define FATALF(F,...) do { LOGF(LOG_LEVEL_FATAL, F, ##__VA_ARGS__); abort(); exit(-1); } while (1)
#define FATAL(X) FATALF("%s", (X))
#define FATALF_perror(F,...) FATALF(F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define FATAL_perror(X) FATALF_perror("%s", (X))
#define NOWHENCE(LOGSTMT) do { const struct __sourceloc __whence = __NOWHENCE__; LOGSTMT; } while (0)
#define WHYF(F,...) logErrorAndReturnNegativeOne(__WHENCE__, F, ##__VA_ARGS__)
#define WHY(X) WHYF("%s", (X))
#define WHYF_perror(F,...) WHYF(F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define WHY_perror(X) WHYF_perror("%s", (X))
#define WHY_argv(X,ARGC,ARGV) logArgv(LOG_LEVEL_ERROR, __WHENCE__, (X), (ARGC), (ARGV))
#define BACKTRACE serval_log_backtrace(LOG_LEVEL_FATAL, __WHENCE__)
#define WARNF(F,...) LOGF(LOG_LEVEL_WARN, F, ##__VA_ARGS__)
#define WARN(X) WARNF("%s", (X))
#define WARNF_perror(F,...) LOGF_perror(LOG_LEVEL_WARN, F, ##__VA_ARGS__)
#define WARN_perror(X) WARNF_perror("%s", (X))
#define FATALF(F,...) do { LOGF(LOG_LEVEL_FATAL, F, ##__VA_ARGS__); abort(); exit(-1); } while (1)
#define FATAL(X) FATALF("%s", (X))
#define FATALF_perror(F,...) FATALF(F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define FATAL_perror(X) FATALF_perror("%s", (X))
#define HINTF(F,...) LOGF(LOG_LEVEL_HINT, F, ##__VA_ARGS__)
#define HINT(X) HINTF("%s", (X))
#define HINT_argv(X,ARGC,ARGV) logArgv(LOG_LEVEL_HINT, __WHENCE__, (X), (ARGC), (ARGV))
#define WHYF(F,...) serval_logf_and_return(-1, __WHENCE__, F, ##__VA_ARGS__)
#define WHY(X) WHYF("%s", (X))
#define WHYF_perror(F,...) WHYF(F ": %s [errno=%d]", ##__VA_ARGS__, strerror(errno), errno)
#define WHY_perror(X) WHYF_perror("%s", (X))
#define WHY_argv(X,ARGC,ARGV) serval_log_argv(LOG_LEVEL_ERROR, __WHENCE__, (X), (ARGC), (ARGV))
#define WHY_dump(X,ADDR,LEN) serval_log_hexdump(LOG_LEVEL_ERROR, __WHENCE__, (X), (const unsigned char *)(ADDR), (size_t)(LEN))
#define INFOF(F,...) LOGF(LOG_LEVEL_INFO, F, ##__VA_ARGS__)
#define INFO(X) INFOF("%s", (X))
#define WARNF(F,...) LOGF(LOG_LEVEL_WARN, F, ##__VA_ARGS__)
#define WARN(X) WARNF("%s", (X))
#define WARNF_perror(F,...) LOGF_perror(LOG_LEVEL_WARN, F, ##__VA_ARGS__)
#define WARN_perror(X) WARNF_perror("%s", (X))
#define WARN_dump(X,ADDR,LEN) serval_log_hexdump(LOG_LEVEL_WARN, __WHENCE__, (X), (const unsigned char *)(ADDR), (size_t)(LEN))
// log.h provides these macros for writing messages at DEBUG level, so applications can
// define their own DEBUG() and DEBUGF() macros; see "debug.h" as the prime example.
#define HINTF(F,...) LOGF(LOG_LEVEL_HINT, F, ##__VA_ARGS__)
#define HINT(X) HINTF("%s", (X))
#define HINT_argv(X,ARGC,ARGV) serval_log_argv(LOG_LEVEL_HINT, __WHENCE__, (X), (ARGC), (ARGV))
#define HINT_dump(X,ADDR,LEN) serval_log_hexdump(LOG_LEVEL_HINT, __WHENCE__, (X), (const unsigned char *)(ADDR), (size_t)(LEN))
#define INFOF(F,...) LOGF(LOG_LEVEL_INFO, F, ##__VA_ARGS__)
#define INFO(X) INFOF("%s", (X))
// These macros are useful for implementing other macros that conditionally log
// at DEBUG level; DEBUG() and DEBUGF() in "debug.h" are the prime example.
#define _DEBUGF(F,...) LOGF(LOG_LEVEL_DEBUG, F, ##__VA_ARGS__)
#define _DEBUG(X) _DEBUGF("%s", (X))
#define _DEBUGF_perror(F,...) LOGF_perror(LOG_LEVEL_DEBUG, F, ##__VA_ARGS__)
#define _DEBUG_perror(X) _DEBUGF_perror("%s", (X))
#define _DEBUG_argv(X,ARGC,ARGV) logArgv(LOG_LEVEL_DEBUG, __WHENCE__, (X), (ARGC), (ARGV))
#define _DEBUG_argv(X,ARGC,ARGV) serval_log_argv(LOG_LEVEL_DEBUG, __WHENCE__, (X), (ARGC), (ARGV))
#define _DEBUG_dump(X,ADDR,LEN) serval_log_hexdump(LOG_LEVEL_DEBUG, __WHENCE__, (X), (const unsigned char *)(ADDR), (size_t)(LEN))
#define _DEBUGF_TAG(TAG,F,...) _DEBUGF("{%s} " F, (TAG), ##__VA_ARGS__)
#define _DEBUGF_TAG_perror(TAG,F,...) _DEBUGF_perror("{%s} " F, (TAG), ##__VA_ARGS__)
#define _DEBUG_TAG_argv(TAG,X,ARGC,ARGV) _DEBUG_argv("{" TAG "} " X, (ARGC), (ARGV))
#define dump(X,A,N) logDump(LOG_LEVEL_DEBUG, __WHENCE__, (X), (const unsigned char *)(A), (size_t)(N))
// Utility functions, defined in terms of above primitives.
void logArgv(int level, struct __sourceloc whence, const char *label, int argc, const char *const *argv);
int logDump(int level, struct __sourceloc whence, char *name, const unsigned char *addr, size_t len);
void logString(int level, struct __sourceloc whence, const char *str);
#define _DEBUG_TAG_dump(TAG,X,ADDR,LEN) _DEBUG_dump("{" TAG "} " X, (ADDR), (LEN))
#endif // __SERVAL_DNA__LOG_H

2
log_cli.c
View File

@ -37,6 +37,6 @@ static int app_log(const struct cli_parsed *parsed, struct cli_context *UNUSED(c
int level = string_to_log_level(lvl);
if (level == LOG_LEVEL_INVALID)
return WHYF("invalid log level: %s", lvl);
logMessage(level, __NOWHERE__, "%s", msg);
NOWHENCE(LOGF(level, "%s", msg));
return 0;
}

6
logMessage.c → log_inline.c
View File

@ -1,5 +1,5 @@
/*
Serval DNA logging
Serval DNA logging inline functions
Copyright 2013-2014 Serval Project Inc.
This program is free software; you can redistribute it and/or
@ -17,8 +17,8 @@ along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
// This compilation unit simply provides a statically linkable logMessage() function for those other
// units that did not inline it.
// This compilation unit simply provides statically linkable functions, eg, serval_logf(), for those
// other units that did not inline it.
#define __SERVAL_LOG_INLINE
#include "log.h"

144
log_output.h Normal file
View File

@ -0,0 +1,144 @@
/*
Serval DNA log output
Copyright (C) 2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#ifndef __SERVAL_DNA__LOG_OUTPUT_H
#define __SERVAL_DNA__LOG_OUTPUT_H
#include <sys/time.h> // for struct timeval
#include <time.h> // for struct tm
#include <stdarg.h> // for va_list
#include "lang.h" // for bool_t and _APPEND()
#include "section.h"
#include "xprintf.h"
struct log_output_iterator;
/* The log_output structure represents a single log output. The logging
* primitives defined in "log.h" iterate over these, so every log message is
* sent to all available outputs.
*
* Each log output is represented by an instance of this struct. The instance
* persists for the lifetime of the process (eg, while the daemon is running),
* and is not stored anywhere else.
*
* @author Andrew Bettison <andrew@servalproject.com>
*/
struct log_output {
// Configuration:
// the minimum level logged by this output:
int (*minimum_level)(const struct log_output *out);
// whether to include the Process ID in each output line:
bool_t (*show_pid)(const struct log_output *out);
// whether to include the time in each output line:
bool_t (*show_time)(const struct log_output *out);
// State:
// pointer to output-specific state:
void *state;
// the time stamp of the most recently logged message, used to detect when
// the date advances so that the date can be logged:
struct tm last_tm;
// a flag to prevent recursion into the open() operation
bool_t opening;
// Operations:
//
// Perform any setup necessary to commence outputting log messages, eg,
// set/update the config items above, create/rename/open files, allocate
// buffers, connect to server etc.; may invoke vlogMessage(), so must
// handle re-entry; open() gets called at the start of every call to the
// vlogMessage() primitive, before start_line() is called.
void (*open)(struct log_output_iterator *it);
// If *capture is 0 and the output is of a persistent nature (eg, a file or
// system log) and is able to redirect data written to the given file
// descriptor to its output, then do so and set *capture to 1.
void (*capture_fd)(struct log_output_iterator *it, int fd, bool_t *capture);
// Test whether output is able to handle messages; if it returns false then
// start_line() and end_line() will not be invoked.
bool_t (*is_available)(const struct log_output_iterator *it);
// Start outputting a new line at the given level, which may involve
// printing a prefix to indicate the level; return an XPRINTF which can be
// used to print the rest of the line.
void (*start_line)(struct log_output_iterator *it, int level);
// Finish outputting a line already started with start_line(), which may involve
// writing a suffix, but flushing should only be done by flush(), so that
// multi-line messages can be output with only a single flush at the end
void (*end_line)(struct log_output_iterator *it, int level);
// Ensure that any buffered log output has been output; if the process were to
// terminate after this, the last line logged would not be lost.
void (*flush)(struct log_output_iterator *it);
// Release any resources currently held by the logger without flushing, so
// that the next open() called in the child will re-acquire resources; this
// is called in a newly-forked child process to ensure that buffered log
// messages do not get output twice and that the child and parent do not
// fight over file descriptors or sockets etc.
void (*close)(struct log_output_iterator *it);
};
/* log_output_iterator is a transient structure that is used to iterate over all the
* log outputs. Generally, one of these is created (as an auto variable) every
* time a log message is generated, and destroyed immediately after the message
* has been sent to all the log outputs.
*
* @author Andrew Bettison <andrew@servalproject.com>
*/
struct log_output_iterator {
// State:
struct log_output *const *output;
// The time at which the log message is generated, in two formats:
struct timeval tv;
struct tm tm;
// The xprintf() handle used to construct the log message:
XPRINTF xpf;
};
/* Log outputters are included into an executable just by linking them in;
* "section.h" allows the logger to iterate through them all.
*
* There are several ways of linking an outputter into an executable: (1) the
* log_output_xxx.o object files can be explicitly listed on the link
* command-line, or (2) they can be put into a library and dragged into the
* executable by referencing them explicitly somehow, such as the "feature.h"
* mechanism.
*/
DECLARE_SECTION(struct log_output *, logoutput);
#define DEFINE_LOG_OUTPUT(LOG_OUTPUT) \
static struct log_output * _APPEND(__log_output, __LINE__) IN_SECTION(logoutput) = (LOG_OUTPUT)
#define LOG_OUTPUT_COUNT (SECTION_START(logoutput) - SECTION_END(logoutput))
/* Functions for use by log outputters. These form the "private" or "backend" API of
* the logging system.
*/
const char *serval_log_level_prefix_string(int level);
void serval_log_output_iterator_printf_nl(struct log_output_iterator *it, int level, const char *fmt, ...);
void serval_log_output_iterator_vprintf_nl(struct log_output_iterator *it, int level, const char *fmt, va_list ap);
void serval_log_print_prolog(struct log_output_iterator *it);
#endif // __SERVAL_DNA__LOG_OUTPUT_H

119
log_output_android.c Normal file
View File

@ -0,0 +1,119 @@
/*
Serval DNA logging output to Android log
Copyright (C) 2013-2015 Serval Project Inc.
Copyright (C) 2016-2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#include <android/log.h>
#include "log_output.h"
#include "feature.h"
#include "conf.h"
/* To enable logging to the Android system log, include USE_FEATURE(log_output_android) somewhere in
* a source file that is always linked.
*/
DEFINE_FEATURE(log_output_android);
/* Private state for Android log output.
*/
struct log_output_android_state {
char buf[1024];
struct strbuf strbuf;
};
#define DISABLED ((FILE *)1)
static struct log_output_android_state static_state = {
.strbuf = STRUCT_STRBUF_EMPTY
};
static inline struct log_output_android_state *_state(struct log_output *out)
{
assert(out->state);
return (struct log_output_android_state *)(out->state);
}
/* Functions for querying configuration.
*/
static bool_t log_android_dump_config(const struct log_output *UNUSED(out))
{
return config.log.android.dump_config;
}
static int log_android_minimum_level(const struct log_output *UNUSED(out))
{
return config.log.android.level;
}
static bool_t log_android_show_pid(const struct log_output *UNUSED(out))
{
return config.log.android.show_pid;
}
static bool_t log_android_show_time(const struct log_output *UNUSED(out))
{
return config.log.android.show_time;
}
/* Log output operations.
*/
static void log_android_start_line(struct log_output_iterator *it, int level)
{
struct log_output *out = *it->output;
struct log_output_android_state *state = _state(out);
strbuf_init(&state->strbuf, state->buf, sizeof state->buf);
it->xpf = XPRINTF_STRBUF(&state->strbuf);
}
static void log_android_end_line(struct log_output_iterator *it, int level)
{
int alevel = ANDROID_LOG_UNKNOWN;
switch (level) {
case LOG_LEVEL_FATAL: alevel = ANDROID_LOG_FATAL; break;
case LOG_LEVEL_ERROR: alevel = ANDROID_LOG_ERROR; break;
case LOG_LEVEL_WARN: alevel = ANDROID_LOG_WARN; break;
case LOG_LEVEL_HINT:
case LOG_LEVEL_INFO: alevel = ANDROID_LOG_INFO; break;
case LOG_LEVEL_DEBUG: alevel = ANDROID_LOG_DEBUG; break;
default: abort();
}
__android_log_print(alevel, "servald", "%s", _state(*it->output)->buf);
}
static struct log_output static_log_output = {
.dump_config = log_android_dump_config,
.minimum_level = log_android_minimum_level,
.show_pid = log_android_show_pid,
.show_time = log_android_show_time,
.state = &static_state,
.open = NULL,
.capture_fd = NULL,
.is_available = NULL,
.start_line = log_android_start_line,
.end_line = log_android_end_line,
.flush = NULL,
.close = NULL
};
DEFINE_LOG_OUTPUT(&static_log_output);

148
log_output_console.c Normal file
View File

@ -0,0 +1,148 @@
/*
Serval DNA logging output to console (stderr)
Copyright (C) 2013-2015 Serval Project Inc.
Copyright (C) 2016-2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#include <stdio.h> // for fopen(), fileno()
#include <assert.h>
#include "log_output.h"
#include "feature.h"
#include "conf.h"
/* To enable logging to console (standard error), include USE_FEATURE(log_output_console) somewhere
* in a source file that is always linked.
*/
DEFINE_FEATURE(log_output_console);
/* Private state for console log output.
*/
struct log_output_console_state {
FILE *fp;
};
#define DISABLED ((FILE *)1)
static struct log_output_console_state static_state = {
.fp = NULL,
};
static inline struct log_output_console_state *_state(struct log_output *out)
{
assert(out->state);
return (struct log_output_console_state *)(out->state);
}
/* Functions for querying configuration.
*/
static int log_console_minimum_level(const struct log_output *UNUSED(out))
{
return config.log.console.level;
}
static bool_t log_console_show_pid(const struct log_output *UNUSED(out))
{
return config.log.console.show_pid;
}
static bool_t log_console_show_time(const struct log_output *UNUSED(out))
{
return config.log.console.show_time;
}
/* The open() operation. This gets called once before each line is logged.
*/
static void open_log_console(struct log_output_iterator *it)
{
struct log_output_console_state *state = _state(*it->output);
if (!state->fp && state->fp != DISABLED) {
state->fp = stderr;
setlinebuf(state->fp);
serval_log_print_prolog(it);
}
}
static void capture_fd_log_console(struct log_output_iterator *it, int fd, bool_t *UNUSED(capture))
{
struct log_output_console_state *state = _state(*it->output);
if (state->fp && state->fp != DISABLED && fileno(state->fp) == fd) {
fflush(state->fp);
state->fp = DISABLED;
}
}
static bool_t is_log_console_available(const struct log_output_iterator *it)
{
return _state(*it->output)->fp != DISABLED;
}
static void log_console_start_line(struct log_output_iterator *it, int level)
{
struct log_output_console_state *state = _state(*it->output);
if (state->fp && state->fp != DISABLED) {
it->xpf = XPRINTF_STDIO(state->fp);
xputs(serval_log_level_prefix_string(level), it->xpf);
}
}
static void log_console_end_line(struct log_output_iterator *it, int UNUSED(level))
{
struct log_output_console_state *state = _state(*it->output);
if (state->fp && state->fp != DISABLED)
fputc('\n', state->fp);
}
void flush_log_console(struct log_output_iterator *it)
{
struct log_output_console_state *state = _state(*it->output);
if (state->fp && state->fp != DISABLED)
fflush(state->fp);
}
void close_log_console(struct log_output_iterator *it)
{
struct log_output_console_state *state = _state(*it->output);
if (state->fp && state->fp != DISABLED) {
// If stderr were ever made buffered, then to avoid duplicates of buffered log messages being
// flushed from a child process, the child must close file descriptor 2 before calling
// logClose(), and re-open it again afterwards.
fclose(state->fp);
state->fp = NULL;
}
}
static struct log_output static_log_output = {
.minimum_level = log_console_minimum_level,
.show_pid = log_console_show_pid,
.show_time = log_console_show_time,
.state = &static_state,
.open = open_log_console,
.capture_fd = capture_fd_log_console,
.is_available = is_log_console_available,
.start_line = log_console_start_line,
.end_line = log_console_end_line,
.flush = flush_log_console,
.close = close_log_console
};
DEFINE_LOG_OUTPUT(&static_log_output);

387
log_output_file.c Normal file
View File

@ -0,0 +1,387 @@
/*
Serval DNA logging output to files
Copyright (C) 2013-2015 Serval Project Inc.
Copyright (C) 2016-2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#include <libgen.h> // for dirname()
#include <time.h> // for time_t and struct tm
#include <fcntl.h> // for open(), O_RDWR
#include <stdio.h> // for fopen(), fileno()
#include <ctype.h> // for isdigit()
#include <dirent.h> // for readdir() etc.
#include <string.h> // for strcpy()
#include <assert.h>
//#include <unistd.h> // for dup2()
#include "log_output.h"
#include "feature.h"
#include "conf.h"
#include "instance.h"
#include "strbuf.h"
#include "strbuf_helpers.h"
/* To enable logging to files, include USE_FEATURE(log_output_file) somewhere in a source file.
*/
DEFINE_FEATURE(log_output_file);
/* Private state for file log output.
*/
struct log_output_file_state {
// The full pathname of the currently open log file:
const char *path;
char path_buf[400];
// The currently open log file:
// - NULL means open() has not been called yet, but will buffer messages until the file is opened,
// so is ready to accept messages
// - OPEN_FAILED means a prior open() failed, so is not ready to accept messages
// - otherwise, open() has created/opened a file, and is ready to accept messages
FILE *fp;
// The time that the currently open log file was started, used for file rotation logic:
time_t start_time;
// Buffer to hold log messages before the log file is open and ready for writing:
char buf[8192];
struct strbuf strbuf;
// File descriptor to redirect to the open log file.
int capture_fd;
};
#define OPEN_FAILED ((FILE *)1)
static struct log_output_file_state static_state = {
.path = NULL,
.fp = NULL,
.start_time = 0,
.strbuf = STRUCT_STRBUF_EMPTY,
.capture_fd = -1
};
static inline struct log_output_file_state *_state(struct log_output *out)
{
assert(out->state);
return (struct log_output_file_state *)(out->state);
}
/* Functions for querying configuration.
*/
static int log_file_minimum_level(const struct log_output *UNUSED(out))
{
return config.log.file.level;
}
static bool_t log_file_show_pid(const struct log_output *UNUSED(out))
{
return config.log.file.show_pid;
}
static bool_t log_file_show_time(const struct log_output *UNUSED(out))
{
return config.log.file.show_time;
}
/* Functions for tracing and then logging the actions of multi-directory mkdir().
*/
struct mkdir_trace {
struct {
size_t len;
mode_t mode;
} created[10];
size_t created_count;
mode_t latest_mode;
};
static void trace_mkdir(struct __sourceloc UNUSED(whence), const char *path, mode_t mode, void *context)
{
struct mkdir_trace *trace = context;
trace->latest_mode = mode;
if (trace->created_count < NELS(trace->created)) {
trace->created[trace->created_count].len = strlen(path);
trace->created[trace->created_count].mode = mode;
}
++trace->created_count;
}
static void log_mkdir_trace(const char *dir, struct mkdir_trace *trace)
{
unsigned i;
for (i = 0; i < trace->created_count && i < NELS(trace->created); ++i)
NOWHENCE(INFOF("Created %s (mode %04o)", alloca_toprint(-1, dir, trace->created[i].len), trace->created[i].mode));
if (trace->created_count > NELS(trace->created) + 1)
NOWHENCE(INFO("Created ..."));
if (trace->created_count > NELS(trace->created))
NOWHENCE(INFOF("Created %s (mode %04o)", alloca_str_toprint(dir), trace->latest_mode));
}
/* The open() operation. This gets called once before each line is logged.
*
* This method writes some initial INFO message(s) at head of the log, which causes it to call
* serval_vlogf(), but the logging system will not recurse back into this function, instead will
* just write the log messages by calling log_file_start_line() and log_file_end_line() in this and
* in other outputters.
*/
static void open_log_file(struct log_output_iterator *it)
{
struct log_output *out = *it->output;
struct log_output_file_state *state = _state(out);
// Once an attempt to open has failed, don't try any more.
if (state->fp == OPEN_FAILED)
return;
time_t start_time = 0;
// Use the path given by the environment variable if set, mainly to support test scripts.
// Otherwise work out the log file path from the configuration, if available.
const char *env_path = getenv("SERVALD_LOG_FILE");
if (env_path)
state->path = env_path;
else if (!cf_limbo) {
// Rotate the log file name if the configuration does not specify a fixed name.
if (!config.log.file.path[0]) {
assert(it->tv.tv_sec != 0);
start_time = it->tv.tv_sec;
if (config.log.file.duration) {
// Compute the desired start time of the log file.
start_time -= start_time % config.log.file.duration;
// If the desired start time has advanced from the current open file's start time, then
// close the current log file, which will cause the logic below to open the next one.
if (state->path == state->path_buf && start_time != state->start_time) {
if (state->fp)
fclose(state->fp);
state->fp = NULL;
state->path = NULL;
}
}
}
// (Re-)compute the file path.
if (state->path == NULL) {
strbuf sbfile = strbuf_local_buf(state->path_buf);
strbuf_serval_log_path(sbfile);
strbuf_path_join(sbfile, config.log.file.directory_path, "", NULL); // ensure trailing '/'
if (config.log.file.path[0]) {
strbuf_path_join(sbfile, config.log.file.path, NULL);
} else {
assert(start_time != 0);
struct tm tm;
(void)localtime_r(&start_time, &tm);
strbuf_append_strftime(sbfile, "serval-%Y%m%d%H%M%S.log", &tm);
}
if (strbuf_overrun(sbfile)) {
state->fp = OPEN_FAILED;
WHY("Cannot form log file name - buffer overrun");
} else {
state->path = state->path_buf;
state->start_time = start_time;
}
}
}
// Create the log file and append to it.
if (state->fp == NULL) {
if (state->path == NULL) {
if (!cf_limbo) {
state->fp = OPEN_FAILED;
NOWHENCE(LOGF(serval_log_level_NoLogFileConfigured, "No log file configured"));
}
} else {
// Create the new log file.
size_t dirsiz = strlen(state->path) + 1;
char _dir[dirsiz];
struct mkdir_trace _trace;
bzero(&_trace, sizeof _trace);
strcpy(_dir, state->path);
const char *dir = dirname(_dir); // modifies _dir[]
if (mkdirs_log(dir, 0700, trace_mkdir, &_trace) == -1) {
state->fp = OPEN_FAILED;
log_mkdir_trace(dir, &_trace);
WARNF("Cannot mkdir %s - %s [errno=%d]", alloca_str_toprint(dir), strerror(errno), errno);
} else if ((state->fp = fopen(state->path, "a")) == NULL) {
state->fp = OPEN_FAILED;
log_mkdir_trace(dir, &_trace);
WARNF("Cannot create-append %s - %s [errno=%d]", state->path, strerror(errno), errno);
} else {
setlinebuf(state->fp);
serval_log_print_prolog(it);
log_mkdir_trace(dir, &_trace);
NOWHENCE(INFOF("Logging to %s (fd %d)", state->path, fileno(state->fp)));
// If the output has been instructed to redirect a given file descriptor to its log file,
// then do so now.
if (state->capture_fd != -1)
dup2(fileno(state->fp), state->capture_fd);
// Update the log symlink to point to the latest log file.
strbuf sbsymlink = strbuf_alloca(400);
strbuf_system_log_path(sbsymlink);
strbuf_path_join(sbsymlink, "serval.log", NULL);
if (strbuf_overrun(sbsymlink))
WHY("Cannot form log symlink name - buffer overrun");
else {
const char *f = state->path;
const char *s = strbuf_str(sbsymlink);
const char *relpath = f;
for (; *f && *f == *s; ++f, ++s)
if (*f == '/')
relpath = f;
while (*relpath == '/')
++relpath;
while (*s == '/')
++s;
if (strchr(s, '/'))
relpath = state->path;
// If racing with another process at this exact same point, then the symlink(2) call may
// fail with EEXIST, in which case log a warning, not an error.
unlink(strbuf_str(sbsymlink));
if (symlink(relpath, strbuf_str(sbsymlink)) == -1)
LOGF(errno == EEXIST ? LOG_LEVEL_WARN : LOG_LEVEL_ERROR,
"Cannot symlink %s -> %s - %s [errno=%d]",
strbuf_str(sbsymlink), relpath, strerror(errno), errno);
else
NOWHENCE(INFOF("Created symlink %s -> %s", strbuf_str(sbsymlink), relpath));
}
// Expire old log files.
size_t pathsiz = strlen(state->path) + 1;
char path[pathsiz];
while (1) {
strcpy(path, state->path);
const char *base = basename(path); // modifies path[]
DIR *d = opendir(dir);
if (!d) {
WHYF("Cannot expire log files: opendir(%s) - %s [errno=%d]", dir, strerror(errno), errno);
break;
}
struct dirent oldest;
memset(&oldest, 0, sizeof oldest);
unsigned count = 0;
while (1) {
errno = 0;
struct dirent *ent = readdir(d);
if (ent == NULL) {
if (errno)
WHYF("Cannot expire log files: readdir(%s) - %s [errno=%d]", dir, strerror(errno), errno);
break;
}
const char *e;
if ( str_startswith(ent->d_name, "serval-", &e)
&& isdigit(e[0]) && isdigit(e[1]) && isdigit(e[2]) && isdigit(e[3]) // YYYY
&& isdigit(e[4]) && isdigit(e[5]) // MM
&& isdigit(e[6]) && isdigit(e[7]) // DD
&& isdigit(e[8]) && isdigit(e[9]) // HH
&& isdigit(e[10]) && isdigit(e[11]) // MM
&& isdigit(e[12]) && isdigit(e[13]) // SS
&& strcmp(&e[14], ".log") == 0
) {
++count;
if ( strcmp(ent->d_name, base) != 0
&& (!oldest.d_name[0] || strcmp(ent->d_name, oldest.d_name) < 0)
)
oldest = *ent;
}
}
closedir(d);
if (count <= config.log.file.rotate || !oldest.d_name[0])
break;
strbuf b = strbuf_local(path, pathsiz);
strbuf_path_join(b, dir, oldest.d_name, NULL);
assert(!strbuf_overrun(b));
NOWHENCE(INFOF("Delete %s", path));
unlink(path);
}
}
}
}
}
static void capture_fd_log_file(struct log_output_iterator *it, int fd, bool_t *capture)
{
if (!*capture) {
// This outputter does not connect the file descriptor to an output file until the next log
// message is output.
_state(*it->output)->capture_fd = fd;
// Ensure that the file descriptor is occupied, so that no other open() call can occupy it in
// the meantime.
int devnull;
if ((devnull = open("/dev/null", O_RDWR, 0)) == -1)
WHY_perror("open(\"/dev/null\")");
else {
if (devnull != fd && dup2(devnull, fd) == -1)
WHYF_perror("dup2(%d, %d)", devnull, fd);
else
*capture = 1;
if (devnull != fd)
close(devnull);
}
}
}
static bool_t is_log_file_available(const struct log_output_iterator *it)
{
return _state(*it->output)->fp != OPEN_FAILED;
}
static void log_file_start_line(struct log_output_iterator *it, int level)
{
struct log_output_file_state *state = _state(*it->output);
strbuf sb = &state->strbuf;
if (strbuf_is_empty(sb))
strbuf_init(sb, state->buf, sizeof state->buf);
else if (strbuf_len(sb))
strbuf_putc(sb, '\n');
it->xpf = XPRINTF_STRBUF(sb);
xputs(serval_log_level_prefix_string(level), it->xpf);
}
static void flush_log_file(struct log_output_iterator *it)
{
struct log_output_file_state *state = _state(*it->output);
FILE *fp = state->fp;
strbuf sb = &state->strbuf;
if (fp && fp != OPEN_FAILED && strbuf_len(sb) != 0) {
fprintf(fp, "%s\n%s", strbuf_str(sb), strbuf_overrun(sb) ? "LOG OVERRUN\n" : "");
strbuf_reset(sb);
}
}
void close_log_file(struct log_output_iterator *it)
{
struct log_output_file_state *state = _state(*it->output);
FILE *fp = state->fp;
strbuf_reset(&state->strbuf);
if (fp && fp != OPEN_FAILED)
fclose(fp);
state->fp = NULL; // next open() will try again
}
static struct log_output static_log_output = {
.minimum_level = log_file_minimum_level,
.show_pid = log_file_show_pid,
.show_time = log_file_show_time,
.state = &static_state,
.open = open_log_file,
.capture_fd = capture_fd_log_file,
.is_available = is_log_file_available,
.start_line = log_file_start_line,
.end_line = NULL,
.flush = flush_log_file,
.close = close_log_file
};
DEFINE_LOG_OUTPUT(&static_log_output);

42
log_prolog.h Normal file
View File

@ -0,0 +1,42 @@
/*
Serval DNA log prolog
Copyright (C) 2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#ifndef __SERVAL_DNA__LOG_PROLOG_H
#define __SERVAL_DNA__LOG_PROLOG_H
#include "trigger.h"
/* Whenever a log output starts a new log, such as opening the console for the
* first time or rotating to a new log file, or even at a regular interval, it
* emits a "prolog" that starts with the current date/time, then a series of
* log messages generated by invoking all the log_prolog triggers.
*
* The log_prolog trigger functions call the standard logging API to produce
* their output, but the logging system uses an internal trick to ensure that
* the their messages only go to the log output that invoked them, so for
* example, when a log file rotates, the prolog only gets written into the new
* file, and not into the console log as well.
*/
DECLARE_TRIGGER(log_prolog);
struct log_output_iterator;
void serval_log_print_prolog(struct log_output_iterator *it);
#endif // __SERVAL_DNA__LOG_PROLOG_H

48
log_util.c
View File

@ -29,31 +29,25 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include "str.h"
#include "net.h"
int logDump(int level, struct __sourceloc whence, char *name, const unsigned char *addr, size_t len)
int serval_log_hexdump(int level, struct __sourceloc whence, char *name, const unsigned char *addr, size_t len)
{
if (level != LOG_LEVEL_SILENT) {
char buf[100];
size_t i;
if (name)
logMessage(level, whence, "Dump of %s", name);
for(i = 0; i < len; i += 16) {
serval_logf(level, whence, "Dump of %s", name);
size_t off = 0;
while (off < len) {
char buf[100];
strbuf b = strbuf_local_buf(buf);
strbuf_sprintf(b, " %04zx :", i);
int j;
for (j = 0; j < 16 && i + j < len; j++)
strbuf_sprintf(b, " %02x", addr[i + j]);
for (; j < 16; j++)
strbuf_puts(b, " ");
strbuf_puts(b, " ");
for (j = 0; j < 16 && i + j < len; j++)
strbuf_sprintf(b, "%c", addr[i+j] >= ' ' && addr[i+j] < 0x7f ? addr[i+j] : '.');
logMessage(level, whence, "%s", strbuf_str(b));
size_t skip = xhexdump_line(XPRINTF_STRBUF(b), addr, len, off);
addr += skip;
off += skip;
serval_logf(level, whence, " %s", strbuf_str(b));
}
}
return 0;
}
void logArgv(int level, struct __sourceloc whence, const char *label, int argc, const char *const *argv)
void serval_log_argv(int level, struct __sourceloc whence, const char *label, int argc, const char *const *argv)
{
if (level != LOG_LEVEL_SILENT) {
struct strbuf b;
@ -63,25 +57,25 @@ void logArgv(int level, struct __sourceloc whence, const char *label, int argc,
strbuf_init(&b, alloca(len + 1), len + 1);
strbuf_append_argv(&b, argc, argv);
if (label)
logMessage(level, whence, "%s %s", label, strbuf_str(&b));
serval_logf(level, whence, "%s %s", label, strbuf_str(&b));
else
logMessage(level, whence, "%s", strbuf_str(&b));
serval_logf(level, whence, "%s", strbuf_str(&b));
}
}
void logString(int level, struct __sourceloc whence, const char *str)
void serval_log_multiline(int level, struct __sourceloc whence, const char *str)
{
if (level != LOG_LEVEL_SILENT) {
const char *s = str;
const char *p;
for (p = str; *p; ++p) {
if (*p == '\n') {
logMessage(level, whence, "%.*s", (int)(p - s), s);
serval_logf(level, whence, "%.*s", (int)(p - s), s);
s = p + 1;
}
}
if (p > s)
logMessage(level, whence, "%.*s", (int)(p - s), s);
serval_logf(level, whence, "%.*s", (int)(p - s), s);
}
}
@ -113,7 +107,7 @@ int string_to_log_level(const char *text)
return LOG_LEVEL_INVALID;
}
int logBacktrace(int level, struct __sourceloc whence)
int serval_log_backtrace(int level, struct __sourceloc whence)
{
#ifndef NO_BACKTRACE
char execpath[MAXPATHLEN];
@ -167,7 +161,7 @@ int logBacktrace(int level, struct __sourceloc whence)
}
// parent
close(stdout_fds[1]);
logMessage(level, whence, "GDB BACKTRACE");
serval_logf(level, whence, "GDB BACKTRACE");
char buf[1024];
char *const bufe = buf + sizeof buf;
char *linep = buf;
@ -179,14 +173,14 @@ int logBacktrace(int level, struct __sourceloc whence)
for (; p < readp; ++p)
if (*p == '\n' || *p == '\0') {
*p = '\0';
logMessage(level, __NOWHERE__, "GDB %s", linep);
serval_logf(level, __NOWHERE__, "GDB %s", linep);
linep = p + 1;
}
if (readp >= bufe && linep == buf) {
// Line does not fit into buffer.
char t = bufe[-1];
bufe[-1] = '\0';
logMessage(level, __NOWHERE__, "GDB %s", buf);
serval_logf(level, __NOWHERE__, "GDB %s", buf);
buf[0] = t;
readp = buf + 1;
} else if (readp + 120 >= bufe && linep != buf) {
@ -202,7 +196,7 @@ int logBacktrace(int level, struct __sourceloc whence)
WHY_perror("read");
if (readp > linep) {
*readp = '\0';
logMessage(level, __NOWHERE__, "GDB %s", linep);
serval_logf(level, __NOWHERE__, "GDB %s", linep);
}
close(stdout_fds[0]);
int status = 0;
@ -210,7 +204,7 @@ int logBacktrace(int level, struct __sourceloc whence)
WHY_perror("waitpid");
strbuf b = strbuf_local_buf(buf);
strbuf_append_exit_status(b, status);
logMessage(level, __NOWHERE__, "gdb %s", buf);
serval_logf(level, __NOWHERE__, "gdb %s", buf);
unlink(tempfile);
#endif
return 0;

3
monitor-cli.c
View File

@ -35,6 +35,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include "cli.h"
#include "monitor-client.h"
#include "commandline.h"
#include "xprintf.h"
DEFINE_FEATURE(cli_monitor);
@ -47,7 +48,7 @@ static int remote_print(char *cmd, int argc, char **argv, unsigned char *data, i
}
printf("\n");
if (dataLen){
dump(NULL,data,dataLen);
xhexdump(XPRINTF_STDIO(stdout), data, dataLen, "");
}
return 1;
}

9
monitor-client.c
View File

@ -107,8 +107,7 @@ int monitor_client_writeline(int fd,char *fmt, ...)
n=vsnprintf(msg, sizeof(msg), fmt, ap);
va_end(ap);
if (IF_DEBUG(monitor))
dump("{monitor} Writing to monitor", msg, n);
DEBUG_dump(monitor, "Writing to monitor", msg, n);
return write(fd,msg,n);
}
@ -131,8 +130,7 @@ int monitor_client_writeline_and_data(int fd,unsigned char *data,int bytes,char
bcopy(data,out+n,bytes);
n+=bytes;
if (IF_DEBUG(monitor))
dump("{monitor} Writing to monitor", out, n);
DEBUG_dump(monitor, "Writing to monitor", out, n);
return write(fd,out,n);
}
@ -157,8 +155,7 @@ int monitor_client_read(int fd, struct monitor_state *res, struct monitor_comman
return -1;
}
if (IF_DEBUG(monitor))
dump("{monitor} Read from monitor", res->buffer + oldOffset, bytesRead);
DEBUG_dump(monitor, "Read from monitor", res->buffer + oldOffset, bytesRead);
res->bufferBytes+=bytesRead;

26
os.c
View File

@ -38,26 +38,26 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include <mach-o/dyld.h>
#endif
void log_info_mkdir(struct __sourceloc __whence, const char *path, mode_t mode)
void log_info_mkdir(struct __sourceloc __whence, const char *path, mode_t mode, void *UNUSED(context))
{
INFOF("mkdir %s (mode %04o)", alloca_str_toprint(path), mode);
}
int _mkdirs(struct __sourceloc __whence, const char *path, mode_t mode, MKDIR_LOG_FUNC *logger)
int _mkdirs(struct __sourceloc __whence, const char *path, mode_t mode, MKDIR_LOG_FUNC *logger, void *log_context)
{
return _mkdirsn(__whence, path, strlen(path), mode, logger);
return _mkdirsn(__whence, path, strlen(path), mode, logger, log_context);
}
int _emkdirs(struct __sourceloc __whence, const char *path, mode_t mode, MKDIR_LOG_FUNC *logger)
int _emkdirs(struct __sourceloc __whence, const char *path, mode_t mode, MKDIR_LOG_FUNC *logger, void *log_context)
{
if (_mkdirs(__whence, path, mode, logger) == -1)
if (_mkdirs(__whence, path, mode, logger, log_context) == -1)
return WHYF_perror("mkdirs(%s,%o)", alloca_str_toprint(path), mode);
return 0;
}
int _emkdirsn(struct __sourceloc __whence, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *logger)
int _emkdirsn(struct __sourceloc __whence, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *logger, void *log_context)
{
if (_mkdirsn(__whence, path, len, mode, logger) == -1)
if (_mkdirsn(__whence, path, len, mode, logger, log_context) == -1)
return WHYF_perror("mkdirsn(%s,%lu,%o)", alloca_toprint(-1, path, len), (unsigned long)len, mode);
return 0;
}
@ -72,7 +72,7 @@ int _emkdirsn(struct __sourceloc __whence, const char *path, size_t len, mode_t
*
* @author Andrew Bettison <andrew@servalproject.com>
*/
int _mkdirsn(struct __sourceloc whence, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *logger)
int _mkdirsn(struct __sourceloc whence, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *logger, void *log_context)
{
if (len == 0)
errno = EINVAL;
@ -81,7 +81,7 @@ int _mkdirsn(struct __sourceloc whence, const char *path, size_t len, mode_t mod
strncpy(pathfrag, path, len)[len] = '\0';
if (mkdir(pathfrag, mode) != -1) {
if (logger)
logger(whence, pathfrag, mode);
logger(whence, pathfrag, mode, log_context);
return 0;
}
if (errno == EEXIST) {
@ -98,17 +98,15 @@ int _mkdirsn(struct __sourceloc whence, const char *path, size_t len, mode_t mod
while (lastsep != path && *--lastsep == '/')
;
if (lastsep != path) {
if (_mkdirsn(whence, path, lastsep - path + 1, mode, logger) == -1)
if (_mkdirsn(whence, path, lastsep - path + 1, mode, logger, log_context) == -1)
return -1;
if (mkdir(pathfrag, mode) == -1) {
if (errno==EEXIST)
if (errno == EEXIST)
return 0;
return -1;
}
if (logger)
logger(whence, pathfrag, mode);
logger(whence, pathfrag, mode, log_context);
return 0;
}
}

34
os.h
View File

@ -108,27 +108,27 @@ __SERVAL_DNA__OS_INLINE off64_t lseek64(int fd, off64_t offset, int whence) {
/* The "e" variants log the error before returning -1.
*/
typedef void MKDIR_LOG_FUNC(struct __sourceloc, const char *, mode_t);
typedef void MKDIR_LOG_FUNC(struct __sourceloc, const char *, mode_t, void *);
MKDIR_LOG_FUNC log_info_mkdir;
int _mkdirs(struct __sourceloc, const char *path, mode_t mode, MKDIR_LOG_FUNC *);
int _mkdirsn(struct __sourceloc, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *);
int _emkdirs(struct __sourceloc, const char *path, mode_t mode, MKDIR_LOG_FUNC *);
int _emkdirsn(struct __sourceloc, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *);
int _mkdirs(struct __sourceloc, const char *path, mode_t mode, MKDIR_LOG_FUNC *, void *);
int _mkdirsn(struct __sourceloc, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *, void *);
int _emkdirs(struct __sourceloc, const char *path, mode_t mode, MKDIR_LOG_FUNC *, void *);
int _emkdirsn(struct __sourceloc, const char *path, size_t len, mode_t mode, MKDIR_LOG_FUNC *, void *);
#define mkdirs_log(path, mode, func) _mkdirs(__WHENCE__, (path), (mode), (func))
#define mkdirsn_log(path, len, mode, func) _mkdirsn(__WHENCE__, (path), (len), (mode), (func))
#define emkdirs_log(path, mode, func) _emkdirs(__WHENCE__, (path), (mode), (func))
#define emkdirsn_log(path, len, mode, func) _emkdirsn(__WHENCE__, (path), (len), (mode), (func))
#define mkdirs_log(path, mode, func, ctx) _mkdirs(__WHENCE__, (path), (mode), (func), (ctx))
#define mkdirsn_log(path, len, mode, func, ctx) _mkdirsn(__WHENCE__, (path), (len), (mode), (func), (ctx))
#define emkdirs_log(path, mode, func, ctx) _emkdirs(__WHENCE__, (path), (mode), (func), (ctx))
#define emkdirsn_log(path, len, mode, func, ctx) _emkdirsn(__WHENCE__, (path), (len), (mode), (func), (ctx))
#define mkdirs(path, mode) mkdirs_log((path), (mode), NULL)
#define mkdirsn(path, len, mode) mkdirsn_log((path), (len), (mode), NULL)
#define emkdirs(path, mode) emkdirs_log((path), (mode), NULL)
#define emkdirsn(path, len, mode) emkdirsn_log((path), (len), (mode), NULL)
#define mkdirs(path, mode) mkdirs_log((path), (mode), NULL, NULL)
#define mkdirsn(path, len, mode) mkdirsn_log((path), (len), (mode), NULL, NULL)
#define emkdirs(path, mode) emkdirs_log((path), (mode), NULL, NULL)
#define emkdirsn(path, len, mode) emkdirsn_log((path), (len), (mode), NULL, NULL)
#define mkdirs_info(path, mode) mkdirs_log((path), (mode), log_info_mkdir)
#define mkdirsn_info(path, len, mode) mkdirsn_log((path), (len), (mode), log_info_mkdir)
#define emkdirs_info(path, mode) emkdirs_log((path), (mode), log_info_mkdir)
#define emkdirsn_info(path, len, mode) emkdirsn_log((path), (len), (mode), log_info_mkdir)
#define mkdirs_info(path, mode) mkdirs_log((path), (mode), log_info_mkdir, NULL)
#define mkdirsn_info(path, len, mode) mkdirsn_log((path), (len), (mode), log_info_mkdir, NULL)
#define emkdirs_info(path, mode) emkdirs_log((path), (mode), log_info_mkdir, NULL)
#define emkdirsn_info(path, len, mode) emkdirsn_log((path), (len), (mode), log_info_mkdir, NULL)
/* Read the symbolic link into the supplied buffer and add a terminating nul.
* Logs an ERROR and returns -1 if the buffer is too short to hold the link

7
overlay_buffer.c
View File

@ -239,8 +239,7 @@ void _ob_append_bytes(struct __sourceloc __whence, struct overlay_buffer *b, con
} else {
DEBUGF(overlaybuffer, "ob_append_bytes(b=%p, bytes=%p, count=%zu) OVERRUN position=%zu return NULL", b, bytes, count, b->position + count);
}
if (IF_DEBUG(overlaybuffer))
dump("{overlaybuffer} ob_append_bytes", bytes, count);
DEBUG_dump(overlaybuffer, "ob_append_bytes", bytes, count);
b->position += count;
}
@ -655,9 +654,9 @@ int ob_dump(struct overlay_buffer *b, char *desc)
if (b->bytes) {
if (b->sizeLimit != SIZE_MAX && b->sizeLimit > 0) {
assert(b->position <= b->sizeLimit);
dump(desc, b->bytes, b->sizeLimit);
_DEBUG_dump(desc, b->bytes, b->sizeLimit);
} else if (b->position > 0)
dump(desc, b->bytes, b->position);
_DEBUG_dump(desc, b->bytes, b->position);
}
return 0;
}

2
overlay_interface.c
View File

@ -1531,7 +1531,7 @@ void logServalPacket(int level, struct __sourceloc __whence, const char *message
else if (mb.buffer == NULL)
WHYF("serval_packetvisualise() output buffer missing, message=%s packet=%p len=%lu", alloca_toprint(-1, message, strlen(message)), packet, (long unsigned int)len);
else
logString(level, __whence, mb.buffer);
serval_log_multiline(level, __whence, mb.buffer);
if (mb.buffer)
free(mb.buffer);
}

4
overlay_mdp.c
View File

@ -878,8 +878,8 @@ int _overlay_send_frame(struct __sourceloc whence, struct internal_mdp_header *h
return -1;
}
DEBUGF(mdprequests, "Send frame %zu bytes", ob_position(plaintext));
if (IF_DEBUG(mdprequests) && IF_DEBUG(verbose))
dump("Frame plaintext", ob_ptr(plaintext), ob_position(plaintext));
if (IF_DEBUG(verbose))
DEBUG_dump(mdprequests, "Frame plaintext", ob_ptr(plaintext), ob_position(plaintext));
/* Work out the disposition of the frame-> For now we are only worried
about the crypto matters, and not compression that may be applied

6
overlay_packetformats.c
View File

@ -420,11 +420,9 @@ int packetOkOverlay(struct overlay_interface *interface,unsigned char *packet, s
payload_len = ob_get_ui16(b);
if (payload_len > ob_remaining(b)){
unsigned char *current = ob_ptr(b)+ob_position(b);
if (IF_DEBUG(overlayframes))
dump("Payload Header", header_start, current - header_start);
ret = WHYF("Payload length %zd suggests frame should be %zd bytes, but was only %zd",
DEBUG_dump(overlayframes, "Payload Header", header_start, current - header_start);
ret = WHYF("Payload length %zd suggests frame should be %zd bytes, but was only %zd",
payload_len, ob_position(b)+payload_len, len);
// TODO signal reduced MTU?
goto end;
}

4
radio_link.c
View File

@ -514,8 +514,8 @@ int radio_link_decode(struct overlay_interface *interface, uint8_t c)
// Since we know we've synced with the remote party,
// and there's nothing we can do about any earlier data
// throw away everything before the end of this packet
if (state->payload_start && IF_DEBUG(radio_link))
dump("{radio_link} Skipped", state->payload, state->payload_start);
if (state->payload_start)
DEBUG_dump(radio_link, "Skipped", state->payload, state->payload_start);
// If the packet is truncated by less than 16 bytes, RS protection should be enough to recover the packet,
// but we may need to examine the last few bytes to find the start of the next packet.

2
rhizome_database.c
View File

@ -99,7 +99,7 @@ static int sqlite_trace_callback(unsigned UNUSED(mask), void *UNUSED(context), v
break;
}
if (rendered_sql) {
logMessage(LOG_LEVEL_DEBUG, sqlite_trace_whence ? *sqlite_trace_whence : __HERE__, "%s", rendered_sql);
serval_logf(LOG_LEVEL_DEBUG, sqlite_trace_whence ? *sqlite_trace_whence : __HERE__, "%s", rendered_sql);
++sqlite_trace_done;
}
if (expanded_sql)

3
rhizome_fetch.c
View File

@ -469,8 +469,7 @@ static int rhizome_import_received_bundle(struct rhizome_manifest *m)
return 0;
DEBUGF(rhizome_rx, "manifest len=%zu has %u signatories. Associated filesize=%"PRIu64" bytes",
m->manifest_all_bytes, m->sig_count, m->filesize);
if (IF_DEBUG(rhizome_rx))
dump("manifest", m->manifestdata, m->manifest_all_bytes);
DEBUG_dump(rhizome_rx, "manifest", m->manifestdata, m->manifest_all_bytes);
enum rhizome_bundle_status status = rhizome_add_manifest_to_store(m, NULL);
switch (status) {
case RHIZOME_BUNDLE_STATUS_NEW:

7
serval_types.h
View File

@ -67,13 +67,6 @@ enum status_codes{
//CODE_CRYPTO_ERROR = 12,
};
/* Conveniences to assist readability
*/
typedef char bool_t;
/* Serval ID (aka Subscriber ID)
*/

16
server.c
View File

@ -229,7 +229,7 @@ int server_bind()
serverMode = SERVER_RUNNING;
// Warn, not merely Info, if there is no configured log file.
logLevel_NoLogFileConfigured = LOG_LEVEL_WARN;
serval_log_level_NoLogFileConfigured = LOG_LEVEL_WARN;
/* Catch SIGHUP etc so that we can respond to requests to do things, eg, shut down. */
struct sigaction sig;
@ -551,7 +551,7 @@ void server_watchdog(struct sched_ent *alarm)
switch (watchdog_pid = fork()) {
case 0:
/* Grandchild, should exec() watchdog. */
close_log_file();
serval_log_close();
signal(SIGTERM, SIG_DFL);
close(0);
close(1);
@ -882,7 +882,7 @@ static int app_server_start(const struct cli_parsed *parsed, struct cli_context
on an Android device, then we don't receive a SIGHUP when the adb shell process ends.
*/
DEBUG(verbose, "Grand-Child Process, reopening log");
close_log_file();
serval_log_close();
int fd;
if ((fd = open("/dev/null", O_RDWR, 0)) == -1)
exit(WHY_perror("open(\"/dev/null\")"));
@ -894,11 +894,15 @@ static int app_server_start(const struct cli_parsed *parsed, struct cli_context
exit(WHYF_perror("dup2(%d,stdin)", fd));
if (dup2(fd, STDOUT_FILENO) == -1)
exit(WHYF_perror("dup2(%d,stdout)", fd));
if (dup2(fd, STDERR_FILENO) == -1)
/* Redirect standard error to the current log file, so that any diagnostic messages
* printed directly to stderr by libraries or child processes will end up being captured
* in a log file. If standard error is not redirected, then simply direct it to
* /dev/null.
*/
if (!serval_log_capture_fd(STDERR_FILENO) && dup2(fd, STDERR_FILENO) == -1)
exit(WHYF_perror("dup2(%d,stderr)", fd));
if (fd > 2)
if (fd > STDERR_FILENO)
(void)close(fd);
redirect_stderr_to_log();
/* The execpath option is provided so that a JNI call to "start" can be made which
creates a new server daemon process with the correct argv[0]. Otherwise, the servald
process appears as a process with argv[0] = "org.servalproject". */

9
sourcefiles.mk
View File

@ -16,7 +16,8 @@ SERVAL_CLIENT_SOURCES = \
fdqueue.c \
instance.c \
limit.c \
logMessage.c \
log.c \
log_inline.c \
log_cli.c \
log_context.c \
log_util.c \
@ -59,7 +60,8 @@ SERVAL_DAEMON_SOURCES = \
keyring.c \
keyring_cli.c \
keyring_restful.c \
log.c \
log_output_console.c \
log_output_file.c \
lsif.c \
radio_link.c \
meshms.c \
@ -146,7 +148,8 @@ CLIENT_ONLY_SOURCES = \
log_stderr.c
ANDROID_SOURCES = \
android.c
android.c \
log_output_android.c
ALL_SOURCES = \
$(SERVAL_CLIENT_SOURCES) \

10
test_cli.c
View File

@ -138,8 +138,8 @@ static int app_crypt_test(const struct cli_parsed *parsed, struct cli_context *c
if (memcmp(&sign1_sk[32], sign1_pk, crypto_sign_PUBLICKEYBYTES)) {
WHY("Could not calculate public key from private key.\n");
dump("calculated",&pk,sizeof(pk));
dump("original",&sign1_pk,sizeof(sign1_pk));
WHY_dump("calculated",&pk,sizeof(pk));
WHY_dump("original",&sign1_pk,sizeof(sign1_pk));
} else
cli_printf(context, "Public key is contained in private key.\n");
@ -162,12 +162,12 @@ static int app_crypt_test(const struct cli_parsed *parsed, struct cli_context *c
bzero(plainText,1024);
snprintf((char *)&plainText[0],sizeof plainText,"%s","No casaba melons allowed in the lab.");
int plainLenIn=64;
dump("plaintext", plainText, 64);
WHY_dump("plaintext", plainText, 64);
if (crypto_sign_detached(sig, NULL, plainText, plainLenIn, key))
return WHY("crypto_sign_detached() failed.\n");
dump("signature", sig, sizeof sig);
WHY_dump("signature", sig, sizeof sig);
unsigned char casabamelons[crypto_sign_BYTES]={
0xa4,0xea,0xd0,0x7f,0x11,0x65,0x28,0x3f,
@ -182,7 +182,7 @@ static int app_crypt_test(const struct cli_parsed *parsed, struct cli_context *c
if (memcmp(casabamelons, sig, 64)) {
WHY("Computed signature for stored key+message does not match expected value.\n");
dump("expected signature",casabamelons,sizeof(casabamelons));
WHY_dump("expected signature",casabamelons,sizeof(casabamelons));
}
if (crypto_sign_verify_detached(sig, plainText, plainLenIn, &key[32]))

2
tests/keyring
View File

@ -268,7 +268,7 @@ test_KeyringNoAutoCreate() {
wait_until has_sent_mdp_tick_to "dummy1/$instance_name"
executeOk_servald keyring list
assert_keyring_list 0
executeOk_servald id self
executeOk_servald --stderr id self
assertStdoutLineCount == 3
}
finally_KeyringNoAutoCreate() {

34
tests/logging
View File

@ -131,31 +131,37 @@ test_LogFileStderrFile() {
}
doc_LogFileRotation="Log file rotation and deletion"
setup_LogFileRotation() {
setup
executeOk_servald config set log.console.level debug \
set log.console.show_pid true \
set log.file.level warn
}
test_LogFileRotation() {
executeOk_servald config \
set log.file.directory_path "$PWD" \
set log.file.rotate 3 \
set log.file.duration 2s
assert --message="no log files yet" [ $(ls *.log | wc -l) -eq 0 ]
executeOk_servald log info one
assert --message="one log file" [ $(ls *.log | wc -l) -eq 1 ]
log1=*.log
assert --stderr --message="no log files yet" [ $(ls *.log 2>/dev/null | wc -l) -eq 0 ]
executeOk_servald log warn one
assert --stderr --message="one log file" [ $(ls *.log | wc -l) -eq 1 ]
log1=$(ls *.log | tail -n 1)
sleep 2.1
executeOk_servald log info two
assert --message="two log files" [ $(ls *.log | wc -l) -eq 2 ]
executeOk_servald log warn two
assert --stderr --message="two log files" [ $(ls *.log | wc -l) -eq 2 ]
log2=$(ls *.log | tail -n 1)
assert --message="ascending log file name" [ "$log2" != "$log1" ]
assert --stderr --message="ascending log file name" [ "$log2" != "$log1" ]
sleep 2.1
executeOk_servald log info three
assert --message="three log files" [ $(ls *.log | wc -l) -eq 3 ]
executeOk_servald log warn three
assert --stderr --message="three log files" [ $(ls *.log | wc -l) -eq 3 ]
log3=$(ls *.log | tail -n 1)
assert --message="ascending log file name" [ "$log3" != "$log1" -a "$log3" != "$log2" ]
assert --stderr --message="ascending log file name" [ "$log3" != "$log1" -a "$log3" != "$log2" ]
sleep 2.1
executeOk_servald log info four
assert --message="three log files" [ $(ls *.log | wc -l) -eq 3 ]
assert --message="first log file gone" ! [ -e $log1 ]
executeOk_servald log warn four
assert --stderr --message="three log files" [ $(ls *.log | wc -l) -eq 3 ]
assert --stderr --message="first log file gone" ! [ -e $log1 ]
log4=$(ls *.log | tail -n 1)
assert --message="ascending log file name" [ "$log4" != "$log2" -a "$log4" != "$log3" -a "$log4" != "$log1" ]
assert --stderr --message="ascending log file name" [ "$log4" != "$log2" -a "$log4" != "$log3" -a "$log4" != "$log1" ]
}
doc_LogFileDirectoryAbsolute="Absolute log file directory path"

13
version_servald.c
View File

@ -1,6 +1,7 @@
/*
Serval DNA version and copyright strings
Copyright (C) 2013 Serval Project Inc.
Copyright (C) 2017 Flinders University
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
@ -18,6 +19,8 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
#include "version_servald.h"
#include "log_prolog.h"
#include "debug.h"
#ifndef SERVALD_VERSION
#error "SERVALD_VERSION is not defined"
@ -29,3 +32,13 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
const char version_servald[] = SERVALD_VERSION;
const char copyright_servald[] = SERVALD_COPYRIGHT;
/* Print the version in the prolog of every log file.
*/
static void log_version()
{
NOWHENCE(INFOF("Serval DNA version: %s", version_servald));
}
DEFINE_TRIGGER(log_prolog, log_version);

3
vomp_console.c
View File

@ -69,6 +69,7 @@
#include "strbuf.h"
#include "strbuf_helpers.h"
#include "commandline.h"
#include "xprintf.h"
static int console_dial(const struct cli_parsed *parsed, struct cli_context *context);
static int console_answer(const struct cli_parsed *parsed, struct cli_context *context);
@ -256,7 +257,7 @@ static int remote_print(char *cmd, int argc, char **argv, unsigned char *data, i
}
printf("\n");
if (dataLen){
dump(NULL,data,dataLen);
xhexdump(XPRINTF_STDIO(stdout), data, dataLen, "");
}
fflush(stdout);
return 1;

4
whence.h
View File

@ -26,12 +26,12 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
/*
* Every log message identifies the location in the source code at which the
* message was produced. This location is represented by a struct __sourceloc,
* which is passed by value to the logMessage() function and its ilk.
* which is passed by value to the serval_logf() function and its ilk.
*
* A struct __sourceloc value is generated by the __HERE__ macro, which uses
* the cpp(1) built-in macros __FILE__, __LINE__ and __FUNCTION__ to generate
* its elements. The __NOWHERE__ macro creates a struct __sourceloc with NULL
* and zero fields. If you pass __NOWHERE__ to logMessage(), it will omit
* and zero fields. If you pass __NOWHERE__ to serval_logf(), it will omit
* location information from the log line. The __NOWHENCE__ macro creates a
* special source __sourceloc that logging primitives should interpret to
* suppress the output of the usual source-code location information.

34
xprintf.c
View File

@ -22,6 +22,9 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
#include "strbuf.h"
#include "xprintf.h"
/* Primitives.
*/
void xprintf(XPRINTF xfp, const char *fmt, ...)
{
va_list ap;
@ -45,6 +48,37 @@ void xputc(char c, XPRINTF xpf)
xprintf(xpf, "%c", c);
}
size_t xhexdump_line(XPRINTF xpf, const unsigned char *addr, const size_t len, const size_t off)
{
xprintf(xpf, "%04zx :", off);
size_t i;
for (i = 0; i < 16 && off + i < len; i++)
xprintf(xpf, " %02x", addr[off + i]);
for (; i < 16; i++)
xputs(" ", xpf);
xputs(" ", xpf);
for (i = 0; i < 16 && off + i < len; ++i) {
unsigned char c = addr[off + i];
xprintf(xpf, "%c", c >= ' ' && c < 0x7f ? c : '.');
}
return i;
}
void xhexdump(XPRINTF xpf, const unsigned char *addr, const size_t len, const char *line_prefix)
{
size_t off = 0;
while (off < len) {
xputs(line_prefix, xpf);
size_t skip = xhexdump_line(xpf, addr, len, off);
off += skip;
addr += skip;
xputc('\n', xpf);
}
}
/* Implementations for various destinations.
*/
void _cx_vprintf_stdio(void *context, const char *fmt, va_list ap)
{
vfprintf((FILE *)context, fmt, ap);

6
xprintf.h
View File

@ -73,6 +73,7 @@ typedef struct _xprintf {
void *context;
} XPRINTF;
#define XPRINTF_IS_NULL(X) ((X).func == NULL)
#define _XPRINTF(F,C) ((XPRINTF){(F),(C)})
void xprintf(XPRINTF xpf, const char *fmt, ...) __attribute__ ((__ATTRIBUTE_format(printf,2,3)));
@ -80,8 +81,13 @@ void vxprintf(XPRINTF xpf, const char *fmt, va_list);
void xputs(const char *str, XPRINTF xpf);
void xputc(char c, XPRINTF xpf);
size_t xhexdump_line(XPRINTF xpf, const unsigned char *addr, const size_t len, const size_t off);
void xhexdump(XPRINTF xpf, const unsigned char *addr, size_t len, const char *line_prefix);
#define XPRINTF_GEN(F,C) _XPRINTF((F),(void *)(C))
#define XPRINTF_NULL _XPRINTF(NULL, NULL)
/* Standard i/o adapter. An XPRINTF constructed with XPRINTF_STDIO(stream)
* will write all its output to stream using fprintf(stream,...).
*/