tvhlog: created a new logging system that will allow more configuration

Note: I still need to sort out the command line switches
This commit is contained in:
Adam Sutton 2013-04-09 22:39:37 +01:00
parent 4706b29f19
commit 2c502b977f
5 changed files with 320 additions and 209 deletions

View file

@ -67,6 +67,7 @@ endif
#
SRCS = src/version.c \
src/main.c \
src/tvhlog.c \
src/utils.c \
src/wrappers.c \
src/access.c \

View file

@ -145,14 +145,7 @@ pthread_mutex_t atomic_lock;
* Locals
*/
static int running;
static int log_stderr;
static int log_decorate;
static LIST_HEAD(, gtimer) gtimers;
static int log_debug_to_syslog;
static int log_debug_to_console;
static int log_debug_to_path;
static htsmsg_t* log_debug_trace;
static char* log_path;
static pthread_cond_t gtimer_cond;
static void
@ -398,15 +391,11 @@ main(int argc, char **argv)
#if ENABLE_LINUXDVB
uint32_t adapter_mask;
#endif
int log_level = LOG_INFO;
int log_options = TVHLOG_OPT_MILLIS | TVHLOG_OPT_STDERR | TVHLOG_OPT_SYSLOG;
const char *log_subsys = NULL;
/* Defaults */
log_stderr = 1;
log_decorate = isatty(2);
log_debug_to_syslog = 0;
log_debug_to_console = 0;
log_debug_to_path = 0;
log_debug_trace = NULL;
log_path = NULL;
tvheadend_webui_port = 9981;
tvheadend_webroot = NULL;
tvheadend_htsp_port = 9982;
@ -417,21 +406,24 @@ main(int argc, char **argv)
opt_version = 0,
opt_fork = 0,
opt_firstrun = 0,
opt_debug = 0,
opt_stderr = 0,
opt_syslog = 0,
opt_uidebug = 0,
opt_abort = 0,
opt_noacl = 0,
opt_trace = 0,
opt_fileline = 0,
opt_ipv6 = 0;
const char *opt_config = NULL,
*opt_user = NULL,
*opt_group = NULL,
*opt_logpath = NULL,
*opt_log_subsys = NULL,
*opt_pidpath = "/var/run/tvheadend.pid",
#if ENABLE_LINUXDVB
*opt_dvb_adapters = NULL,
*opt_dvb_raw = NULL,
#endif
*opt_trace = NULL,
*opt_rawts = NULL,
*opt_bindaddr = NULL,
*opt_subscribe = NULL;
@ -469,13 +461,15 @@ main(int argc, char **argv)
OPT_INT, &tvheadend_htsp_port_extra },
{ 0, NULL, "Debug Options", OPT_BOOL, NULL },
{ 'd', "debug", "Enable all debug", OPT_BOOL, &opt_debug },
{ 'd', "stderr", "Enable debug on stderr", OPT_BOOL, &opt_stderr },
{ 's', "syslog", "Enable debug to syslog", OPT_BOOL, &opt_syslog },
{ 0, "uidebug", "Enable webUI debug", OPT_BOOL, &opt_uidebug },
{ 'l', "log", "Log to file", OPT_STR, &log_path },
{ 'l', "logfile", "Enable debug to file", OPT_STR, &opt_logpath },
{ 0, "subsys", "Enable debug subsystems", OPT_STR, &opt_log_subsys },
{ 0, "fileline", "Add file and line numbers to debug", OPT_BOOL, &opt_fileline },
#if ENABLE_TRACE
{ 0, "trace", "Enable low level debug", OPT_STR, &opt_trace },
{ 0, "trace", "Enable low level debug", OPT_BOOL, &opt_trace },
#endif
{ 0, "uidebug", "Enable webUI debug (non-minified JS)", OPT_BOOL, &opt_uidebug },
{ 'A', "abort", "Immediately abort", OPT_BOOL, &opt_abort },
{ 0, "noacl", "Disable all access control checks",
OPT_BOOL, &opt_noacl },
@ -528,25 +522,6 @@ main(int argc, char **argv)
}
/* Additional cmdline processing */
opt_debug |= (opt_trace != NULL);
log_debug_to_console = opt_debug;
log_debug_to_syslog = opt_syslog;
log_debug_to_path = opt_debug;
tvheadend_webui_debug = opt_debug || opt_uidebug;
if (opt_trace) {
log_debug_trace = htsmsg_create_map();
htsmsg_add_u32(log_debug_trace, "START", 1);
uint32_t u32;
char *trace = strdup(opt_trace);
char *p, *r = NULL;
p = strtok_r(trace, ",", &r);
while (p) {
if (htsmsg_get_u32(log_debug_trace, p, &u32))
htsmsg_add_u32(log_debug_trace, p, 1);
p = strtok_r(NULL, ",", &r);
}
free(trace);
}
#if ENABLE_LINUXDVB
if (!opt_dvb_adapters) {
adapter_mask = ~0;
@ -587,6 +562,29 @@ main(int argc, char **argv)
tvheadend_webroot = tmp;
}
/* Setup logging */
if (isatty(2))
log_options |= TVHLOG_OPT_DECORATE;
if (opt_stderr || opt_syslog || opt_logpath) {
log_subsys = "all";
log_level = LOG_DEBUG;
if (opt_stderr)
log_options |= TVHLOG_OPT_DBG_STDERR;
if (opt_syslog)
log_options |= TVHLOG_OPT_DBG_SYSLOG;
if (opt_logpath)
log_options |= TVHLOG_OPT_DBG_FILE;
}
if (opt_fileline)
log_options |= TVHLOG_OPT_FILELINE;
if (opt_trace)
log_level = LOG_TRACE;
if (opt_log_subsys)
log_subsys = opt_log_subsys;
tvhlog_init(log_level, log_options, opt_logpath);
tvhlog_set_subsys(log_subsys);
signal(SIGPIPE, handle_sigpipe); // will be redundant later
/* Daemonise */
@ -643,11 +641,12 @@ main(int argc, char **argv)
umask(0);
}
/* Setup logging */
log_stderr = !opt_fork;
log_decorate = isatty(2);
openlog("tvheadend", LOG_PID, LOG_DAEMON);
/* Alter logging */
if (opt_fork)
tvhlog_options &= ~TVHLOG_OPT_STDERR;
if (!isatty(2))
tvhlog_options &= ~TVHLOG_OPT_DECORATE;
/* Initialise configuration */
hts_settings_init(opt_config);
@ -754,7 +753,6 @@ main(int argc, char **argv)
"running as PID:%d UID:%d GID:%d, settings located in '%s'",
tvheadend_version,
getpid(), getuid(), getgid(), hts_settings_get_root());
tvhtrace("START", "TRACE debug enabled");
if(opt_abort)
abort();
@ -780,147 +778,6 @@ main(int argc, char **argv)
}
static const char *logtxtmeta[8][2] = {
{"EMERGENCY", "\033[31m"},
{"ALERT", "\033[31m"},
{"CRITICAL", "\033[31m"},
{"ERROR", "\033[31m"},
{"WARNING", "\033[33m"},
{"NOTICE", "\033[36m"},
{"INFO", "\033[32m"},
{"DEBUG", "\033[32m"},
};
/**
* Internal log function
*/
static void
tvhlogv(int notify, int severity, const char *subsys, const char *fmt,
va_list ap)
{
char buf[2048];
char buf2[2048];
char t[64];
int l, ms;
struct tm tm;
struct timeval now;
static int log_path_fail = 0;
size_t c;
l = snprintf(buf, sizeof(buf), "%s: ", subsys);
vsnprintf(buf + l, sizeof(buf) - l, fmt, ap);
if(log_debug_to_syslog || severity < LOG_DEBUG)
syslog(severity, "%s", buf);
/**
* Get time (string)
*/
gettimeofday(&now, NULL);
localtime_r(&now.tv_sec, &tm);
ms = now.tv_usec / 1000;
c = strftime(t, sizeof(t), "%b %d %H:%M:%S", &tm);
snprintf(t+c, sizeof(t)-c, ".%03d", ms);
/**
* Send notification to Comet (Push interface to web-clients)
*/
if(notify) {
htsmsg_t *m;
snprintf(buf2, sizeof(buf2), "%s %s", t, buf);
m = htsmsg_create_map();
htsmsg_add_str(m, "notificationClass", "logmessage");
htsmsg_add_str(m, "logtxt", buf2);
comet_mailbox_add_message(m, severity == LOG_DEBUG);
htsmsg_destroy(m);
}
/**
* Write to stderr
*/
if(log_stderr && (log_debug_to_console || severity < LOG_DEBUG)) {
const char *leveltxt = logtxtmeta[severity][0];
const char *sgr = logtxtmeta[severity][1];
const char *sgroff;
if(!log_decorate) {
sgr = "";
sgroff = "";
} else {
sgroff = "\033[0m";
}
fprintf(stderr, "%s%s [%7s]:%s%s\n", sgr, t, leveltxt, buf, sgroff);
}
/**
* Write to file
*/
if (log_path && (log_debug_to_path || severity < LOG_DEBUG)) {
const char *leveltxt = logtxtmeta[severity][0];
FILE *fp = fopen(log_path, "a");
if (fp) {
log_path_fail = 0;
fprintf(fp, "%s [%7s]:%s\n", t, leveltxt, buf);
fclose(fp);
} else {
if (!log_path_fail)
syslog(LOG_WARNING, "failed to write log file %s", log_path);
log_path_fail = 1;
}
}
}
/**
*
*/
void
tvhlog(int severity, const char *subsys, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
tvhlogv(1, severity, subsys, fmt, ap);
va_end(ap);
}
/**
* TVH trace
*/
#ifdef ENABLE_TRACE
void
tvhtrace(const char *subsys, const char *fmt, ...)
{
va_list ap;
if (!log_debug_trace)
return;
if (!htsmsg_get_u32_or_default(log_debug_trace, "all", 0))
if (!htsmsg_get_u32_or_default(log_debug_trace, subsys, 0))
return;
va_start(ap, fmt);
tvhlogv(0, LOG_DEBUG, subsys, fmt, ap);
va_end(ap);
}
#endif
/**
* May be invoked from a forked process so we can't do any notification
* to comet directly.
*
* @todo Perhaps do it via a pipe?
*/
void
tvhlog_spawn(int severity, const char *subsys, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
tvhlogv(0, severity, subsys, fmt, ap);
va_end(ap);
}
/**
*
*/

View file

@ -32,6 +32,7 @@
#include "avg.h"
#include "hts_strtab.h"
#include "htsmsg.h"
#include "tvhlog.h"
#include "redblack.h"
@ -440,29 +441,6 @@ static inline unsigned int tvh_strhash(const char *s, unsigned int mod)
void tvh_str_set(char **strp, const char *src);
int tvh_str_update(char **strp, const char *src);
void tvhlog(int severity, const char *subsys, const char *fmt, ...)
__attribute__((format(printf,3,4)));
void tvhlog_spawn(int severity, const char *subsys, const char *fmt, ...)
__attribute__((format(printf,3,4)));
#define LOG_EMERG 0 /* system is unusable */
#define LOG_ALERT 1 /* action must be taken immediately */
#define LOG_CRIT 2 /* critical conditions */
#define LOG_ERR 3 /* error conditions */
#define LOG_WARNING 4 /* warning conditions */
#define LOG_NOTICE 5 /* normal but significant condition */
#define LOG_INFO 6 /* informational */
#define LOG_DEBUG 7 /* debug-level messages */
#ifndef ENABLE_TRACE
#define tvhtrace(...) ((void)0)
#else
void tvhtrace(const char *subsys, const char *fmt, ...);
#endif
extern int log_debug;
#ifndef CLOCK_MONOTONIC_COARSE
#define CLOCK_MONOTONIC_COARSE CLOCK_MONOTONIC
#endif

201
src/tvhlog.c Normal file
View file

@ -0,0 +1,201 @@
/*
* Tvheadend - logging
* Copyright (C) 2012 Adam Sutton
*
* 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 3 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, see <http://www.gnu.org/licenses/>.
*/
#include "tvhlog.h"
#include <pthread.h>
#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>
#include "webui/webui.h"
int tvhlog_level;
int tvhlog_options;
char *tvhlog_path;
int tvhlog_path_fail;
htsmsg_t *tvhlog_subsys;
pthread_mutex_t tvhlog_mutex;
static const char *logtxtmeta[9][2] = {
{"EMERGENCY", "\033[31m"},
{"ALERT", "\033[31m"},
{"CRITICAL", "\033[31m"},
{"ERROR", "\033[31m"},
{"WARNING", "\033[33m"},
{"NOTICE", "\033[36m"},
{"INFO", "\033[32m"},
{"DEBUG", "\033[32m"},
{"TRACE", "\033[32m"},
};
/* Initialise */
void
tvhlog_init ( int level, int options, const char *path )
{
tvhlog_level = level;
tvhlog_options = options;
tvhlog_path = path ? strdup(path) : NULL;
tvhlog_subsys = NULL;
openlog("tvheadend", LOG_PID, LOG_DAEMON);
pthread_mutex_init(&tvhlog_mutex, NULL);
}
/* Set subsys */
void tvhlog_set_subsys ( const char *subsys )
{
uint32_t a;
char *t, *r, *s;
if (tvhlog_subsys)
htsmsg_destroy(tvhlog_subsys);
tvhlog_subsys = NULL;
if (!subsys)
return;
s = strdup(subsys);
t = strtok_r(s, ",", &r);
while ( t ) {
subsys = NULL;
a = 1;
if (t[0] == '+' || t[0] == '-') {
a = t[0] == '+';
t++;
}
if (!strcmp(t, "all")) {
if (tvhlog_subsys)
htsmsg_destroy(tvhlog_subsys);
tvhlog_subsys = NULL;
}
if (!tvhlog_subsys)
tvhlog_subsys = htsmsg_create_map();
htsmsg_set_u32(tvhlog_subsys, t, a);
t = strtok_r(NULL, ",", &r);
}
free(s);
}
/* Log */
void tvhlogv ( const char *file, int line,
int notify, int severity,
const char *subsys, const char *fmt, va_list args )
{
struct timeval now;
struct tm tm;
char t[128], buf[2048], buf2[2048];
uint32_t a;
size_t l;
int s;
/* Map down */
if (severity > LOG_DEBUG)
s = LOG_DEBUG;
else
s = severity;
/* Check debug enabled */
if (severity >= LOG_DEBUG) {
if (!tvhlog_subsys)
return;
if (severity > tvhlog_level)
return;
a = htsmsg_get_u32_or_default(tvhlog_subsys, "all", 0);
if (!htsmsg_get_u32_or_default(tvhlog_subsys, subsys, a))
return;
}
/* Get time */
gettimeofday(&now, NULL);
localtime_r(&now.tv_sec, &tm);
l = strftime(t, sizeof(t), "%b %d %H:%M:%S", &tm);
if (tvhlog_options & TVHLOG_OPT_MILLIS) {
int ms = now.tv_usec / 1000;
snprintf(t+l, sizeof(t)-l, ".%03d", ms);
}
/* Basic message */
l = snprintf(buf, sizeof(buf), "%s: ", subsys);
if (tvhlog_options & TVHLOG_OPT_FILELINE && severity >= LOG_DEBUG)
l += snprintf(buf + l, sizeof(buf) - l, "(%s:%d) ", file, line);
l += vsnprintf(buf + l, sizeof(buf) - l, fmt, args);
/* Syslog */
if (tvhlog_options & TVHLOG_OPT_SYSLOG) {
if (tvhlog_options & TVHLOG_OPT_DBG_SYSLOG || severity < LOG_DEBUG) {
syslog(s, "%s", buf);
}
}
/* Comet (debug must still be enabled??) */
if(notify && severity < LOG_TRACE) {
htsmsg_t *m = htsmsg_create_map();
snprintf(buf2, sizeof(buf2), "%s %s", t, buf);
htsmsg_add_str(m, "notificationClass", "logmessage");
htsmsg_add_str(m, "logtxt", buf2);
comet_mailbox_add_message(m, severity >= LOG_DEBUG);
htsmsg_destroy(m);
}
/* Console */
if (tvhlog_options & TVHLOG_OPT_STDERR) {
if (tvhlog_options & TVHLOG_OPT_DBG_STDERR || severity < LOG_DEBUG) {
const char *leveltxt = logtxtmeta[severity][0];
const char *sgr = logtxtmeta[severity][1];
const char *sgroff;
if (tvhlog_options & TVHLOG_OPT_DECORATE)
sgroff = "\033[0m";
else {
sgr = "";
sgroff = "";
}
fprintf(stderr, "%s%s [%7s] %s%s\n", sgr, t, leveltxt, buf, sgroff);
}
}
/* File */
if (tvhlog_path) {
if (tvhlog_options & TVHLOG_OPT_DBG_FILE || severity < LOG_DEBUG) {
const char *leveltxt = logtxtmeta[severity][0];
FILE *fp = fopen(tvhlog_path, "a");
if (fp) {
tvhlog_path_fail = 0;
fprintf(fp, "%s [%7s]:%s\n", t, leveltxt, buf);
fclose(fp);
} else {
if (!tvhlog_path_fail)
syslog(LOG_WARNING, "failed to write log file %s", tvhlog_path);
tvhlog_path_fail = 1;
}
}
}
}
/*
* Map args
*/
void _tvhlog ( const char *file, int line,
int notify, int severity,
const char *subsys, const char *fmt, ... )
{
va_list args;
va_start(args, fmt);
tvhlogv(file, line, notify, severity, subsys, fmt, args);
va_end(args);
}

74
src/tvhlog.h Normal file
View file

@ -0,0 +1,74 @@
/*
* Tvheadend - logging
* Copyright (C) 2012 Adam Sutton
*
* 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 3 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, see <http://www.gnu.org/licenses/>.
*/
#ifndef __TVH_LOGGING_H__
#define __TVH_LOGGING_H__
#include <sys/syslog.h>
#include <pthread.h>
#include <stdarg.h>
#include "htsmsg.h"
/* Config */
extern int tvhlog_level;
extern htsmsg_t *tvhlog_subsys;
extern char *tvhlog_path;
extern int tvhlog_options;
extern pthread_mutex_t tvhlog_mutex;
/* Initialise */
void tvhlog_init ( int level, int options, const char *path );
void tvhlog_set_subsys ( const char *subsys );
void tvhlogv ( const char *file, int line,
int notify, int severity,
const char *subsys, const char *fmt, va_list args );
void _tvhlog ( const char *file, int line,
int notify, int severity,
const char *subsys, const char *fmt, ... )
__attribute__((format(printf,6,7)));
/* Options */
#define TVHLOG_OPT_DBG_SYSLOG 0x0001
#define TVHLOG_OPT_DBG_STDERR 0x0002
#define TVHLOG_OPT_DBG_FILE 0x0004
#define TVHLOG_OPT_SYSLOG 0x0010
#define TVHLOG_OPT_STDERR 0x0020
#define TVHLOG_OPT_MILLIS 0x0100
#define TVHLOG_OPT_DECORATE 0x0200
#define TVHLOG_OPT_FILELINE 0x0400
#define TVHLOG_OPT_ALL 0xFFFF
/* Levels */
#ifndef LOG_TRACE
#define LOG_TRACE (LOG_DEBUG+1)
#endif
/* Macros */
#define tvhlog(severity, subsys, fmt, ...)\
_tvhlog(__FILE__, __LINE__, 1, severity, subsys, fmt, ##__VA_ARGS__)
#define tvhlog_spawn(severity, subsys, fmt, ...)\
_tvhlog(__FILE__, __LINE__, 0, severity, subsys, fmt, ##__VA_ARGS__)
#if ENABLE_TRACE
#define tvhtrace(subsys, fmt, ...)\
_tvhlog(__FILE__, __LINE__, 0, LOG_TRACE, subsys, fmt, ##__VA_ARGS__)
#else
#define tvhtrace(...) (void)0
#endif
#endif /* __TVH_LOGGING_H__ */