> On 6 Oct 2016, at 07:07, Alexander Bluhm <[email protected]> wrote:
>
> 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?
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]);
>
