Hi,
RFC 5424 says you should add 1 to 6 digits fractions of a second
to each syslog timestamp. As we do not measure the time in syslog(3),
it takes 100 microseconds on my laptop before syslogd(8) adds the
timestamp. So I have decided to use only 3 digits with millisecond
precision. Note that this is only visible with syslogd -Z.
Here is the difference between the old an new format:
2016-10-05T20:55:26Z t430s syslogd: exiting on signal 15
2016-10-05T20:55:26.160Z t430s syslogd: start
ok?
bluhm
Index: usr.sbin/syslogd/syslogd.c
===================================================================
RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/syslogd/syslogd.c,v
retrieving revision 1.216
diff -u -p -r1.216 syslogd.c
--- usr.sbin/syslogd/syslogd.c 4 Oct 2016 22:09:21 -0000 1.216
+++ usr.sbin/syslogd/syslogd.c 5 Oct 2016 20:12:02 -0000
@@ -1577,7 +1577,7 @@ printsys(char *msg)
}
}
-time_t now;
+struct timeval now;
/*
* Log a message to the appropriate log files, users, etc. based on
@@ -1587,7 +1587,6 @@ void
logmsg(int pri, char *msg, char *from, int flags)
{
struct filed *f;
- struct tm *tm;
int fac, msglen, prilev, i;
char timestamp[33];
char prog[NAME_MAX+1];
@@ -1665,13 +1664,18 @@ logmsg(int pri, char *msg, char *from, i
flags |= ADDDATE;
}
- (void)time(&now);
+ (void)gettimeofday(&now, NULL);
if (flags & ADDDATE) {
if (ZuluTime) {
- tm = gmtime(&now);
- strftime(timestamp, sizeof(timestamp), "%FT%TZ", tm);
+ struct tm *tm;
+ size_t l;
+
+ tm = gmtime(&now.tv_sec);
+ l = strftime(timestamp, sizeof(timestamp), "%FT%T", tm);
+ snprintf(timestamp + l, sizeof(timestamp) -l, ".%03ldZ",
+ now.tv_usec / 1000);
} else
- strlcpy(timestamp, ctime(&now) + 4, 16);
+ strlcpy(timestamp, ctime(&now.tv_sec) + 4, 16);
}
/* extract facility and priority level */
@@ -1724,7 +1728,8 @@ logmsg(int pri, char *msg, char *from, i
continue;
/* don't output marks to recently written files */
- if ((flags & MARK) && (now - f->f_time) < MarkInterval / 2)
+ if ((flags & MARK) &&
+ (now.tv_sec - f->f_time) < MarkInterval / 2)
continue;
/*
@@ -1737,7 +1742,7 @@ logmsg(int pri, char *msg, char *from, i
sizeof(f->f_lasttime));
f->f_prevcount++;
logdebug("msg repeated %d times, %ld sec of %d\n",
- f->f_prevcount, (long)(now - f->f_time),
+ f->f_prevcount, (long)(now.tv_sec - f->f_time),
repeatinterval[f->f_repeatcount]);
/*
* If domark would have logged this by now,
@@ -1745,7 +1750,7 @@ logmsg(int pri, char *msg, char *from, i
* but back off so we'll flush less often
* in the future.
*/
- if (now > REPEATTIME(f)) {
+ if (now.tv_sec > REPEATTIME(f)) {
fprintlog(f, flags, (char *)NULL);
BACKOFF(f);
}
@@ -1787,7 +1792,7 @@ fprintlog(struct filed *f, int flags, ch
if (f->f_type == F_WALL) {
l = snprintf(greetings, sizeof(greetings),
"\r\n\7Message from syslogd@%s at %.24s ...\r\n",
- f->f_prevhost, ctime(&now));
+ f->f_prevhost, ctime(&now.tv_sec));
if (l < 0 || (size_t)l >= sizeof(greetings))
l = strlen(greetings);
v->iov_base = greetings;
@@ -1844,7 +1849,7 @@ fprintlog(struct filed *f, int flags, ch
v++;
logdebug("Logging to %s", TypeNames[f->f_type]);
- f->f_time = now;
+ f->f_time = now.tv_sec;
switch (f->f_type) {
case F_UNUSED:
@@ -1946,8 +1951,8 @@ fprintlog(struct filed *f, int flags, ch
/* pipe is non-blocking. log and drop message if full */
if (e == EAGAIN && f->f_type == F_PIPE) {
- if (now - f->f_lasterrtime > 120) {
- f->f_lasterrtime = now;
+ if (now.tv_sec - f->f_lasterrtime > 120) {
+ f->f_lasterrtime = now.tv_sec;
logerror(f->f_un.f_fname);
}
break;
@@ -2884,7 +2889,7 @@ markit(void)
{
struct filed *f;
- now = time(NULL);
+ (void)gettimeofday(&now, NULL);
MarkSeq += TIMERINTVL;
if (MarkSeq >= MarkInterval) {
logmsg(LOG_INFO, "-- MARK --",
@@ -2893,7 +2898,7 @@ markit(void)
}
SIMPLEQ_FOREACH(f, &Files, f_next) {
- if (f->f_prevcount && now >= REPEATTIME(f)) {
+ if (f->f_prevcount && now.tv_sec >= REPEATTIME(f)) {
logdebug("flush %s: repeated %d times, %d sec.\n",
TypeNames[f->f_type], f->f_prevcount,
repeatinterval[f->f_repeatcount]);
