kai/assaultcube-
1
1
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

thread-safe and fully buffered logging

Browse Source 
Uses own thread to actually write to logs, so the main thread can't be
blocked by a slow logfile. Log entries are buffered in two ringbuffers,
one for the main thread and one for all other threads. The main thread
will copy the second buffer to the main buffer periodically. The main
thread buffer is read from the log worker thread.

Since two buffers are kept, there are now several functions to add a log
entry:

  mlog()
    for main thread functions only: will never block

  tlog()
    other threads only: may block, until main thread copied some entries

  xlog()
    automatically determines, which thread it's been called from and
    then writes to the proper buffer (will block accordingly)

To avoid improper usage, mlog and tlog verify, if they are used correctly.
(Only for debug builds. An assert triggers, if necessary.)
This commit is contained in:
ac-stef
2017-06-27 15:15:23 +02:00
parent dd295bb54a
commit 035d7caf2f
11 changed files with 285 additions and 190 deletions
Download Patch File Download Diff File Expand all files Collapse all files
source/src/log.cpp
+126 -30
View File
@@ -32,8 +32,15 @@ static int facility = -1,
consolethreshold = ACLOG_INFO;
static bool timestamp = false, enabled = false;
enum { LOGTARGET_CONSOLE = 1, LOGTARGET_FILE = 2, LOGTARGET_SYSLOG = 4 };
static char loglevelenabled[ACLOG_NUM];
bool initlogging(const char *identity, int facility_, int consolethres, int filethres, int syslogthres, bool logtimestamp, const char *logfilepath)
{
static void *logworkerthread_id = NULL;
extern int logworkerthread(void *nop);
if(!logworkerthread_id) logworkerthread_id = sl_createthread(logworkerthread, NULL); // always start, if dedicated server
facility = facility_;
timestamp = logtimestamp;
if(consolethres >= 0) consolethreshold = min(consolethres, (int)ACLOG_NUM);
@@ -63,12 +70,14 @@ bool initlogging(const char *identity, int facility_, int consolethres, int file
if(syslogthreshold < ACLOG_NUM) concatformatstring(msg, ", \"%s\", local%d", ident, facility);
concatformatstring(msg, "), timestamp(%s)", timestamp ? "ENABLED" : "DISABLED");
enabled = consolethreshold < ACLOG_NUM || fp || syslogthreshold < ACLOG_NUM;
loopi(ACLOG_NUM) loglevelenabled[i] = (consolethreshold <= i ? LOGTARGET_CONSOLE : 0) | (fp && filethreshold <= i ? LOGTARGET_FILE : 0) | (syslogthreshold <= i ? LOGTARGET_SYSLOG : 0);
if(enabled) printf("%s\n", msg);
return enabled;
}
void exitlogging()
{
loopi(ACLOG_NUM) loglevelenabled[i] = 0;
if(fp) { fclose(fp); fp = NULL; }
#ifdef AC_USE_SYSLOG
if(enabled && syslogthreshold < ACLOG_NUM) closelog();
@@ -79,42 +88,129 @@ void exitlogging()
bool logcheck(int level)
{
return enabled && level >= 0 && level < ACLOG_NUM && (consolethreshold <= level || (fp && filethreshold <= level) || syslogthreshold <= level);
ASSERT(level >= 0 && level < ACLOG_NUM);
return loglevelenabled[level] != 0;
}
bool logline(int level, const char *msg, ...)
struct logline_s { int level; time_t t; string msg; };
static ringbuf<logline_s *, 1024> mainlog; // increase this number, if log overflows occur
static ringbuf<logline_s *, 32> threadlog;
static int mainlogoverflow = 0;
static sl_semaphore threadlogsem(1, NULL), threadlogfullsem(0, NULL), mainlogsem(0, NULL);
int logworkerthread(void *nop)
{
if(!enabled) return false;
if(level < 0 || level >= ACLOG_NUM) return false;
bool logtocon = consolethreshold <= level, logtofile = fp && filethreshold <= level, logtosyslog = syslogthreshold <= level;
if(!(logtocon || logtofile || logtosyslog)) return false;
defvformatstring(sf, msg, msg);
filtertext(sf, sf, FTXT__LOG);
const char *ts = timestamp ? timestring(true, "%b %d %H:%M:%S ") : "", *ld = levelprefix[level];
char *p, *l = sf;
do
{ // break into single lines first
if((p = strchr(l, '\n'))) *p = '\0';
if(logtocon) printf("%s%s%s\n", ts, ld, l);
if(logtofile) fprintf(fp, "%s%s%s\n", ts, ld, l);
if(logtosyslog)
string tmp;
for(;;)
{
while(mainlog.empty()) mainlogsem.wait();
logline_s *ll = mainlog.remove();
int targets = loglevelenabled[ll->level];
bool logtocon = (targets & LOGTARGET_CONSOLE) != 0, logtofile = fp && (targets & LOGTARGET_FILE) != 0, logtosyslog = (targets & LOGTARGET_SYSLOG) != 0;
const char *ts = timestamp ? timestring(ll->t, true, "%b %d %H:%M:%S ", tmp) : "", *ld = levelprefix[ll->level];
char *p, *l = ll->msg;
do
{ // break into single lines first
if((p = strchr(l, '\n'))) *p = '\0';
if(logtocon) printf("%s%s%s\n", ts, ld, l);
if(logtofile) fprintf(fp, "%s%s%s\n", ts, ld, l);
if(logtosyslog)
#ifdef AC_USE_SYSLOG
syslog(levels[level], "%s", l);
syslog(levels[ll->level], "%s", l);
#else
{
defformatstring(text)("<%d>%s: %s", (16 + facility) * 8 + levels[level], ident, l); // no TIMESTAMP, no hostname: syslog will add this
ENetBuffer buf;
buf.data = text;
buf.dataLength = strlen(text);
enet_socket_send(logsock, &logdest, &buf, 1);
{
defformatstring(text)("<%d>%s: %s", (16 + facility) * 8 + levels[ll->level], ident, l); // no TIMESTAMP, no hostname: syslog will add this
ENetBuffer buf;
buf.data = text;
buf.dataLength = strlen(text);
enet_socket_send(logsock, &logdest, &buf, 1);
}
#endif
l = p + 1;
}
#endif
l = p + 1;
}
while(p);
while(p);
#ifdef _DEBUG
if(logtocon) fflush(stdout);
if(logtofile) fflush(fp);
if(logtocon) fflush(stdout);
if(logtofile) fflush(fp);
#endif
return logtocon;
delete ll;
}
return 0;
}
void mlog(int level, const char *msg, ...) // log line from main thread (never blocks)
{
ASSERT(level >= 0 && level < ACLOG_NUM && ismainthread());
if(!loglevelenabled[level]) return;
if(mainlog.full()) { mainlogoverflow++; return; } // do. not. block.
logline_s *ll = mainlog.stage(new logline_s);
vformatstring(ll->msg, msg, msg);
filtertext(ll->msg, ll->msg, FTXT__LOG);
ll->t = time(NULL);
ll->level = level;
mainlog.commit();
if(mainlogsem.getvalue() < 1) mainlogsem.post();
}
void tlog(int level, const char *msg, ...) // log line from other-than-main thread (may block)
{
ASSERT(level >= 0 && level < ACLOG_NUM && !ismainthread());
if(!loglevelenabled[level]) return;
threadlogsem.wait(); // properly lock, so different threads can use this
while(threadlog.full()) threadlogfullsem.wait(); // wait for buffer to clear
logline_s *ll = threadlog.stage(new logline_s);
vformatstring(ll->msg, msg, msg);
filtertext(ll->msg, ll->msg, FTXT__LOG);
ll->t = time(NULL);
ll->level = level;
threadlog.commit();
threadlogsem.post();
}
void xlog(int level, const char *msg, ...) // log line from any thread (more expensive: only use for functions, that are called from main and other threads)
{
ASSERT(level >= 0 && level < ACLOG_NUM);
if(!loglevelenabled[level]) return;
bool ismain = ismainthread();
if(ismain)
{
if(mainlog.full()) { mainlogoverflow++; return; } // do. not. block.
}
else
{
threadlogsem.wait(); // properly lock, so different threads can use this
while(threadlog.full()) threadlogfullsem.wait(); // wait for buffer to clear
}
logline_s *ll = ismain ? mainlog.stage(new logline_s) : threadlog.stage(new logline_s);
vformatstring(ll->msg, msg, msg);
filtertext(ll->msg, ll->msg, FTXT__LOG);
ll->t = time(NULL);
ll->level = level;
if(ismain)
{
mainlog.commit();
if(mainlogsem.getvalue() < 1) mainlogsem.post();
}
else
{
threadlog.commit();
threadlogsem.post();
}
}
void poll_logbuffers() // just copy threadlog to mainlog and restart blocked threads, if necessary
{
while(!mainlog.full() && !threadlog.empty())
{
mainlog.stage(threadlog.remove());
mainlog.commit();
}
if(mainlogoverflow && !mainlog.full())
{
mlog(ACLOG_ERROR, "main log ringbuffer overflow, %d entries lost", mainlogoverflow);
mainlogoverflow = 0;
}
if(!threadlog.full() && threadlogfullsem.getvalue() < 1) threadlogfullsem.post();
if(!mainlog.empty() && mainlogsem.getvalue() < 1) mainlogsem.post();
}