diff options
| -rw-r--r-- | ChangeLog | 5 | ||||
| -rw-r--r-- | plugins/imklog/bsd.c | 6 | ||||
| -rw-r--r-- | plugins/imklog/imklog.c | 30 | ||||
| -rw-r--r-- | plugins/imklog/imklog.h | 4 | ||||
| -rw-r--r-- | plugins/imklog/linux.c | 116 | ||||
| -rw-r--r-- | plugins/imklog/solaris.c | 68 |
6 files changed, 130 insertions, 99 deletions
@@ -1,5 +1,10 @@ --------------------------------------------------------------------------- Version 5.9.1 [V5-DEVEL] (rgerhards), 2011-06-?? +- added support for obtaining timestamp for kernel message from message + If the kernel time-stamps messages, time is now take from that + timestamp instead of the system time when the message was read. This + provides much better accuracy. Thanks to Lennart Poettering for + suggesting this feature and his help during implementation. - added support for obtaining timestamp from system for imuxsock This permits to read the time a message was submitted to the system log socket. Most importantly, this is provided in microsecond resolution. diff --git a/plugins/imklog/bsd.c b/plugins/imklog/bsd.c index 0a4c7cd4..930bbd11 100644 --- a/plugins/imklog/bsd.c +++ b/plugins/imklog/bsd.c @@ -155,18 +155,18 @@ readklog(void) for (p = (char*)pRcv; (q = strchr(p, '\n')) != NULL; p = q + 1) { *q = '\0'; - Syslog(LOG_INFO, (uchar*) p); + Syslog(LOG_INFO, (uchar*) p, NULL); } len = strlen(p); if (len >= iMaxLine - 1) { - Syslog(LOG_INFO, (uchar*)p); + Syslog(LOG_INFO, (uchar*)p, NULL); len = 0; } if (len > 0) memmove(pRcv, p, len + 1); } if (len > 0) - Syslog(LOG_INFO, pRcv); + Syslog(LOG_INFO, pRcv, NULL); if(pRcv != NULL && (size_t) iMaxLine >= sizeof(bufRcv) - 1) free(pRcv); diff --git a/plugins/imklog/imklog.c b/plugins/imklog/imklog.c index c09fa4d8..cb28e68e 100644 --- a/plugins/imklog/imklog.c +++ b/plugins/imklog/imklog.c @@ -18,7 +18,10 @@ * Please note that this file replaces the klogd daemon that was * also present in pre-v3 versions of rsyslog. * - * Copyright (C) 2008, 2009 by Rainer Gerhards and Adiscon GmbH + * To test under Linux: + * echo test1 > /dev/kmsg + * + * Copyright (C) 2008-2011 by Rainer Gerhards and Adiscon GmbH * * This file is part of rsyslog. * @@ -93,15 +96,21 @@ static prop_t *pLocalHostIP = NULL; /* a pseudo-constant propterty for 127.0.0.1 * rgerhards, 2008-04-12 */ static rsRetVal -enqMsg(uchar *msg, uchar* pszTag, int iFacility, int iSeverity) +enqMsg(uchar *msg, uchar* pszTag, int iFacility, int iSeverity, struct timeval *tp) { - DEFiRet; + struct syslogTime st; msg_t *pMsg; + DEFiRet; assert(msg != NULL); assert(pszTag != NULL); - CHKiRet(msgConstruct(&pMsg)); + if(tp == NULL) { + CHKiRet(msgConstruct(&pMsg)); + } else { + datetime.timeval2syslogTime(tp, &st); + CHKiRet(msgConstructWithTime(&pMsg, &st, tp->tv_sec)); + } MsgSetFlowControlType(pMsg, eFLOWCTL_LIGHT_DELAY); MsgSetInputName(pMsg, pInputName); MsgSetRawMsgWOSize(pMsg, (char*)msg); @@ -174,22 +183,23 @@ rsRetVal imklogLogIntMsg(int priority, char *fmt, ...) va_end(ap); iRet = enqMsg((uchar*)pLogMsg, (uchar*) ((iFacilIntMsg == LOG_KERN) ? "kernel:" : "imklog:"), - iFacilIntMsg, LOG_PRI(priority)); + iFacilIntMsg, LOG_PRI(priority), NULL); RETiRet; } -/* log a kernel message +/* log a kernel message. If tp is non-NULL, it contains the message creation + * time to use. * rgerhards, 2008-04-14 */ -rsRetVal Syslog(int priority, uchar *pMsg) +rsRetVal Syslog(int priority, uchar *pMsg, struct timeval *tp) { - DEFiRet; int pri = -1; rsRetVal localRet; + DEFiRet; - /* first check if we have two PRIs. This can happen in case of systemd, + /* then check if we have two PRIs. This can happen in case of systemd, * in which case the second PRI is the rigth one. * TODO: added kernel timestamp support to this PoC. -- rgerhards, 2011-03-18 */ @@ -214,7 +224,7 @@ rsRetVal Syslog(int priority, uchar *pMsg) if(bPermitNonKernel == 0 && LOG_FAC(priority) != LOG_KERN) FINALIZE; /* silently ignore */ - iRet = enqMsg((uchar*)pMsg, (uchar*) "kernel:", LOG_FAC(priority), LOG_PRI(priority)); + iRet = enqMsg((uchar*)pMsg, (uchar*) "kernel:", LOG_FAC(priority), LOG_PRI(priority), tp); finalize_it: RETiRet; diff --git a/plugins/imklog/imklog.h b/plugins/imklog/imklog.h index c183026d..39bdeb5c 100644 --- a/plugins/imklog/imklog.h +++ b/plugins/imklog/imklog.h @@ -5,7 +5,7 @@ * Major change: 2008-04-09: switched to a driver interface for * several platforms * - * Copyright 2007-2008 Rainer Gerhards and Adiscon GmbH. + * Copyright 2007-2011 Rainer Gerhards and Adiscon GmbH. * * This file is part of rsyslog. * @@ -56,7 +56,7 @@ extern uchar *pszPath; /* the functions below may be called by the drivers */ rsRetVal imklogLogIntMsg(int priority, char *fmt, ...) __attribute__((format(printf,2, 3))); -rsRetVal Syslog(int priority, uchar *msg); +rsRetVal Syslog(int priority, uchar *msg, struct timeval *tp); /* prototypes */ extern int klog_getMaxLine(void); /* work-around for klog drivers to get configured max line size */ diff --git a/plugins/imklog/linux.c b/plugins/imklog/linux.c index 727708a5..8d9c8ad7 100644 --- a/plugins/imklog/linux.c +++ b/plugins/imklog/linux.c @@ -28,6 +28,8 @@ #include "rsyslog.h" #include <stdlib.h> #include <stdio.h> +#include <ctype.h> +#include <time.h> #include <assert.h> #include <signal.h> #include <string.h> @@ -181,6 +183,96 @@ static int copyin( uchar *line, int space, return(i); } + +/* submit a message to imklog Syslog() API. In this function, we check if + * a kernel timestamp is present and, if so, extract and strip it. + * Note: this is an extra processing step. We should revisit the whole + * idea in v6 and remove all that old stuff that we do not longer need + * (like symbol resolution). <-- TODO + * Special thanks to Lennart Poettering for suggesting on how to convert + * the kernel timestamp to a realtime timestamp. This method depends on + * the fact the the kernel timestamp is written using the monotonic clock. + * Shall that change (very unlikely), this code must be changed as well. Note + * that due to the way we generate the delta, we are unable to write the + * absolutely correc timestamp (system call overhead of the clock calls + * prevents us from doing so). However, the difference is very minor. + * rgerhards, 201106-24 + */ +static void +submitSyslog(int pri, uchar *buf) +{ + long secs; + long nsecs; + long secOffs; + long nsecOffs; + unsigned i; + unsigned bufsize; + struct timespec monotonic, realtime; + struct timeval tv; + struct timeval *tp = NULL; + + if(buf[3] != '[') + goto done; + DBGPRINTF("imklog: kernel timestamp detected, extracting it\n"); + + /* we now try to parse the timestamp. iff it parses, we assume + * it is a timestamp. Otherwise we know for sure it is no ts ;) + */ + i = 4; /* first digit after '[' */ + secs = 0; + while(buf[i] && isdigit(buf[i])) { + secs = secs * 10 + buf[i] - '0'; + ++i; + } + if(buf[i] != '.') { + DBGPRINTF("no dot --> no kernel timestamp\n"); + goto done; /* no TS! */ + } + + ++i; /* skip dot */ + nsecs = 0; + while(buf[i] && isdigit(buf[i])) { + nsecs = nsecs * 10 + buf[i] - '0'; + ++i; + } + if(buf[i] != ']') { + DBGPRINTF("no trailing ']' --> no kernel timestamp\n"); + goto done; /* no TS! */ + } + ++i; /* skip ']' */ + + /* we have a timestamp */ + DBGPRINTF("kernel timestamp is %ld %ld\n", secs, nsecs); + bufsize= strlen((char*)buf); + memcpy(buf+3, buf+i, bufsize - i + 1); + + clock_gettime(CLOCK_MONOTONIC, &monotonic); + clock_gettime(CLOCK_REALTIME, &realtime); + secOffs = realtime.tv_sec - monotonic.tv_sec; + nsecOffs = realtime.tv_nsec - monotonic.tv_nsec; + if(nsecOffs < 0) { + secOffs--; + nsecOffs += 1000000000l; + } + monotonic.tv_sec, monotonic.tv_nsec, + realtime.tv_sec, realtime.tv_nsec, + secOffs, nsecOffs); + + nsecs +=nsecOffs; + if(nsecs > 999999999l) { + secs++; + nsecs -= 1000000000l; + } + secs += secOffs; + tv.tv_sec = secs; + tv.tv_usec = nsecs / 1000; + tp = &tv; + +done: + Syslog(pri, buf, tp); +} + + /* * Messages are separated by "\n". Messages longer than * LOG_LINE_LENGTH are broken up. @@ -235,7 +327,7 @@ static void LogLine(char *ptr, int len) //dbgprintf("Line buffer full:\n"); //dbgprintf("\tLine: %s\n", line); - Syslog(LOG_INFO, line_buff); + submitSyslog(LOG_INFO, line_buff); line = line_buff; space = sizeof(line_buff)-1; parse_state = PARSING_TEXT; @@ -254,28 +346,24 @@ static void LogLine(char *ptr, int len) space -= delta; len -= delta; - if( space == 0 || len == 0 ) - { + if( space == 0 || len == 0 ) { break; /* full line_buff or end of input buffer */ } - if( *ptr == '\0' ) /* zero byte */ - { + if( *ptr == '\0' ) /* zero byte */ { ptr++; /* skip zero byte */ space -= 1; len -= 1; - break; } - if( *ptr == '\n' ) /* newline */ - { + if( *ptr == '\n' ) /* newline */ { ptr++; /* skip newline */ space -= 1; len -= 1; *line = 0; /* force null terminator */ - Syslog(LOG_INFO, line_buff); + submitSyslog(LOG_INFO, line_buff); line = line_buff; space = sizeof(line_buff)-1; if (symbols_twice) { @@ -285,9 +373,7 @@ static void LogLine(char *ptr, int len) skip_symbol_lookup = 1; ptr = save_ptr; len = save_len; - } - else - { + } else { skip_symbol_lookup = 0; save_ptr = ptr; save_len = len; @@ -295,8 +381,7 @@ static void LogLine(char *ptr, int len) } break; } - if( *ptr == '[' ) /* possible kernel symbol */ - { + if( *ptr == '[' ) /* possible kernel symbol */ { *line++ = *ptr++; space -= 1; len -= 1; @@ -310,8 +395,7 @@ static void LogLine(char *ptr, int len) break; case PARSING_SYMSTART: - if( *ptr != '<' ) - { + if( *ptr != '<' ) { parse_state = PARSING_TEXT; /* not a symbol */ break; } diff --git a/plugins/imklog/solaris.c b/plugins/imklog/solaris.c index 8a6d5af1..0a169cdd 100644 --- a/plugins/imklog/solaris.c +++ b/plugins/imklog/solaris.c @@ -80,74 +80,6 @@ klogWillRun(void) } -#if 0 -/* Read /dev/klog while data are available, split into lines. - * Contrary to standard BSD syslogd, we do a blocking read. We can - * afford this as imklog is running on its own threads. So if we have - * a single file, it really doesn't matter if we wait inside a 1-file - * select or the read() directly. - */ -static void -readklog(void) -{ - char *p, *q; - int len, i; - int iMaxLine; - uchar bufRcv[4096+1]; - uchar *pRcv = NULL; /* receive buffer */ - - iMaxLine = klog_getMaxLine(); - - /* we optimize performance: if iMaxLine is below 4K (which it is in almost all - * cases, we use a fixed buffer on the stack. Only if it is higher, heap memory - * is used. We could use alloca() to achive a similar aspect, but there are so - * many issues with alloca() that I do not want to take that route. - * rgerhards, 2008-09-02 - */ - if((size_t) iMaxLine < sizeof(bufRcv) - 1) { - pRcv = bufRcv; - } else { - if((pRcv = (uchar*) malloc(sizeof(uchar) * (iMaxLine + 1))) == NULL) - iMaxLine = sizeof(bufRcv) - 1; /* better this than noting */ - } - - len = 0; - for (;;) { - dbgprintf("----------imklog(BSD) waiting for kernel log line\n"); - i = read(fklog, pRcv + len, iMaxLine - len); - if (i > 0) { - pRcv[i + len] = '\0'; - } else { - if (i < 0 && errno != EINTR && errno != EAGAIN) { - imklogLogIntMsg(LOG_ERR, - "imklog error %d reading kernel log - shutting down imklog", - errno); - fklog = -1; - } - break; - } - - for(p = pRcv; (q = strchr(p, '\n')) != NULL; p = q + 1) { - *q = '\0'; - Syslog(LOG_INFO, (uchar*) p); - } - len = strlen(p); - if (len >= iMaxLine - 1) { - Syslog(LOG_INFO, (uchar*)p); - len = 0; - } - if (len > 0) - memmove(pRcv, p, len + 1); - } - if (len > 0) - Syslog(LOG_INFO, pRcv); - - if(pRcv != NULL && (size_t) iMaxLine >= sizeof(bufRcv) - 1) - free(pRcv); -} -#endif - - /* to be called in the module's AfterRun entry point * rgerhards, 2008-04-09 */ |