On Thu, Mar 18, 2021 at 05:57:45PM +0100, Alexander Bluhm wrote:
> Hi,
> 
> Since we stash log messages in the kernel, the timestamps added by
> syslogd are delayed.  The kernel could add the timestamp when it
> receives the message by sendsyslog(2).  This is more precise and
> can be expressed by more digits in the ISO timestamp.

Better timestamp accuracy would be nice here.

The obvious follow-on question is: why not grab a timestamp in
userspace during syslog(3) instead of waiting until we reach the
kernel?

I imagine it might complicate things.  Or maybe the accuracy
improvement is tiny.  Maybe both.  And then you (maybe) have the
additional round trip to the kernel in gettimeofday(2).

All of that aside, I'd like to hear your reasoning for preferring a
kernel timestamp over a userspace timestamp, if only so that there is
some record of your thinking.

> I have to copyin(9) at the beginning of sendsyslog(2) to have both
> kernel timestamp and log message in kernel space.  This makes the
> code easier, but requires a malloc(9) for each log message.
> 
> Do we want to go into this direction?
> 
> Note that old syslogd and new kernel produces ugly messages.
> Do we need an update path?

I can't speak on any of these items.  I do have other questions + nits
below.

> Index: sys/kern/subr_log.c
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/sys/kern/subr_log.c,v
> retrieving revision 1.74
> diff -u -p -r1.74 subr_log.c
> --- sys/kern/subr_log.c       18 Mar 2021 08:43:38 -0000      1.74
> +++ sys/kern/subr_log.c       18 Mar 2021 13:06:13 -0000
> @@ -108,7 +108,7 @@ const struct filterops logread_filtops =
>       .f_event        = filt_logread,
>  };
>  
> -int dosendsyslog(struct proc *, const char *, size_t, int, enum uio_seg);
> +int dosendsyslog(struct proc *, char *, size_t, int, struct timeval *);
>  void logtick(void *);
>  size_t msgbuf_getlen(struct msgbuf *);
>  void msgbuf_putchar_locked(struct msgbuf *, const char);
> @@ -468,14 +468,15 @@ logioctl(dev_t dev, u_long com, caddr_t 
>   * If syslogd is not running, temporarily store a limited amount of messages
>   * in kernel.  After log stash is full, drop messages and count them.  When
>   * syslogd is available again, next log message will flush the stashed
> - * messages and insert a message with drop count.  Calls to malloc(9) and
> - * copyin(9) may sleep, protect data structures with rwlock.
> + * messages and insert a message with drop count.  Calls to malloc(9) may
> + * sleep, protect data structures with rwlock.
>   */
>  
>  #define LOGSTASH_SIZE        100
>  struct logstash_message {
>       char    *lgs_buffer;
>       size_t   lgs_size;
> +     struct   timeval lgs_time;

Is there any reason to use a timeval here over a timespec?

My preference is that new code use nanosecond precision unless there
is a strong historical reason to a timeval.

We have timecounters with nanosecond resolution.  New syscalls will
all use timespecs or nanosecond resolution.  Etc.

The only code I've seen with said strong historical reason is in
sys/net* because the BSD networking stack predates POSIX and the
timespec.  So all networking ioctls use timevals because it's
tradition to do so.

I see that syslogd(8) is using gettimeofday(2) and is already using
timevals in various spots.  I don't know how painful it would be to
change syslogd(8) to use a timespec, but the main goal in grabbing the
timestamp in the kernel is better accuracy so I think it'd make sense
to rip the bandaid off now and switch to nanosecond resolution while
all this code is being modified to accomodate the kernel timestamp.

Or maybe not.  What do you think?

>  } logstash_messages[LOGSTASH_SIZE];
>  
>  struct       logstash_message *logstash_in = &logstash_messages[0];
> @@ -485,9 +486,9 @@ struct    rwlock logstash_rwlock = RWLOCK_I
>  
>  int  logstash_dropped, logstash_error, logstash_pid;
>  
> -int  logstash_insert(const char *, size_t, int, pid_t);
> -void logstash_remove(void);
> -int  logstash_sendsyslog(struct proc *);
> +void logstash_insert(char *, size_t, int, pid_t, struct timeval *);
> +void logstash_remove(struct timeval *);
> +int  logstash_sendsyslog(struct proc *, struct timeval *);
>  
>  static inline int
>  logstash_full(void)
> @@ -511,11 +512,10 @@ logstash_increment(struct logstash_messa
>               (*msg)++;
>  }
>  
> -int
> -logstash_insert(const char *buf, size_t nbyte, int logerror, pid_t pid)
> +void
> +logstash_insert(char *buffer, size_t nbyte, int logerror, pid_t pid,
> +    struct timeval *now)
>  {
> -     int error;
> -
>       rw_enter_write(&logstash_rwlock);
>  
>       if (logstash_full()) {
> @@ -524,29 +524,22 @@ logstash_insert(const char *buf, size_t 
>                       logstash_pid = pid;
>               }
>               logstash_dropped++;
> +             free(buffer, M_LOG, nbyte);
>  
>               rw_exit(&logstash_rwlock);
> -             return (0);
> +             return;
>       }
>  
> -     logstash_in->lgs_buffer = malloc(nbyte, M_LOG, M_WAITOK);
> -     error = copyin(buf, logstash_in->lgs_buffer, nbyte);
> -     if (error) {
> -             free(logstash_in->lgs_buffer, M_LOG, nbyte);
> -             logstash_in->lgs_buffer = NULL;
> -
> -             rw_exit(&logstash_rwlock);
> -             return (error);
> -     }
> +     logstash_in->lgs_buffer = buffer;
>       logstash_in->lgs_size = nbyte;
> +     logstash_in->lgs_time = *now;
>       logstash_increment(&logstash_in);
>  
>       rw_exit(&logstash_rwlock);
> -     return (0);
>  }
>  
>  void
> -logstash_remove(void)
> +logstash_remove(struct timeval *now)
>  {
>       rw_assert_wrlock(&logstash_rwlock);
>  
> @@ -575,12 +568,13 @@ logstash_remove(void)
>               logstash_in->lgs_buffer = malloc(nbyte, M_LOG, M_WAITOK);
>               memcpy(logstash_in->lgs_buffer, buf, nbyte);
>               logstash_in->lgs_size = nbyte;
> +             logstash_in->lgs_time = *now;
>               logstash_increment(&logstash_in);
>       }
>  }
>  
>  int
> -logstash_sendsyslog(struct proc *p)
> +logstash_sendsyslog(struct proc *p, struct timeval *now)
>  {
>       int error;
>  
> @@ -588,12 +582,12 @@ logstash_sendsyslog(struct proc *p)
>  
>       while (logstash_out->lgs_buffer != NULL) {
>               error = dosendsyslog(p, logstash_out->lgs_buffer,
> -                 logstash_out->lgs_size, 0, UIO_SYSSPACE);
> +                 logstash_out->lgs_size, 0, &logstash_out->lgs_time);
>               if (error) {
>                       rw_exit(&logstash_rwlock);
>                       return (error);
>               }
> -             logstash_remove();
> +             logstash_remove(now);
>       }
>  
>       rw_exit(&logstash_rwlock);
> @@ -615,33 +609,51 @@ sys_sendsyslog(struct proc *p, void *v, 
>               syscallarg(size_t) nbyte;
>               syscallarg(int) flags;
>       } */ *uap = v;
> +     struct timeval now;
> +     char *buffer;
>       size_t nbyte;
>       int error;
>  
> +     microtime(&now);
> +
>       nbyte = SCARG(uap, nbyte);
>       if (nbyte > LOG_MAXLINE)
>               nbyte = LOG_MAXLINE;
>  
> -     logstash_sendsyslog(p);
> -     error = dosendsyslog(p, SCARG(uap, buf), nbyte, SCARG(uap, flags),
> -         UIO_USERSPACE);
> -     if (error && error != EFAULT)
> -             logstash_insert(SCARG(uap, buf), nbyte, error, p->p_p->ps_pid);
> -     return (error);
> +     buffer = malloc(nbyte, M_LOG, M_WAITOK);
> +     error = copyin(SCARG(uap, buf), buffer, nbyte);
> +     if (error)
> +             return (error);
> +#ifdef KTRACE
> +     if (KTRPOINT(p, KTR_GENIO)) {
> +             struct iovec ktriov;
> +
> +             ktriov.iov_base = (char *)SCARG(uap, buf);

iov_base is a void pointer, I don't think you need to cast this.

> +             ktriov.iov_len = nbyte;
> +             ktrgenio(p, -1, UIO_WRITE, &ktriov, nbyte);
> +     }
> +#endif
> +
> +     logstash_sendsyslog(p, &now);
> +     error = dosendsyslog(p, buffer, nbyte, SCARG(uap, flags), &now);
> +     if (error) {
> +             /* logstash will free buffer later */
> +             logstash_insert(buffer, nbyte, error, p->p_p->ps_pid, &now);
> +             return (error);
> +     }
> +     free(buffer, M_LOG, nbyte);
> +     return (0);
>  }
>  
>  int
> -dosendsyslog(struct proc *p, const char *buf, size_t nbyte, int flags,
> -    enum uio_seg sflg)
> +dosendsyslog(struct proc *p, char *buffer, size_t nbyte, int flags,
> +    struct timeval *time)
>  {
> -#ifdef KTRACE
> -     struct iovec ktriov;
> -#endif
>       struct file *fp;
> -     char pri[6], *kbuf;
> -     struct iovec aiov;
> +     char logtime[sizeof("-9223372036854775808.123456 ")];
> +     struct iovec aiov[3];
>       struct uio auio;
> -     size_t i, len;
> +     size_t len;
>       int error;
>  
>       /* Global variable syslogf may change during sleep, use local copy. */
> @@ -651,106 +663,87 @@ dosendsyslog(struct proc *p, const char 
>               FREF(fp);
>       rw_exit(&syslogf_rwlock);
>  
> -     if (fp == NULL) {
> -             if (!ISSET(flags, LOG_CONS))
> -                     return (ENOTCONN);
> +     if (fp) {
> +             len = snprintf(logtime, sizeof(logtime), "%lld.%06ld ",
> +                 time->tv_sec, time->tv_usec);
> +             len = MIN(len, sizeof(logtime));
> +     } else if (!ISSET(flags, LOG_CONS)) {
> +             return (ENOTCONN);
> +     } else {
> +             size_t i;
> +
>               /*
>                * Strip off syslog priority when logging to console.
>                * LOG_PRIMASK | LOG_FACMASK is 0x03ff, so at most 4
>                * decimal digits may appear in priority as <1023>.
>                */
> -             len = MIN(nbyte, sizeof(pri));
> -             if (sflg == UIO_USERSPACE) {
> -                     if ((error = copyin(buf, pri, len)))
> -                             return (error);
> -             } else
> -                     memcpy(pri, buf, len);
> -             if (0 < len && pri[0] == '<') {
> +             len = MIN(nbyte, 6);
> +             if (0 < len && buffer[0] == '<') {
>                       for (i = 1; i < len; i++) {
> -                             if (pri[i] < '0' || pri[i] > '9')
> +                             if (buffer[i] < '0' || buffer[i] > '9')
>                                       break;
>                       }
> -                     if (i < len && pri[i] == '>') {
> +                     if (i < len && buffer[i] == '>') {
>                               i++;
>                               /* There must be at least one digit <0>. */
>                               if (i >= 3) {
> -                                     buf += i;
> +                                     buffer += i;
>                                       nbyte -= i;
>                               }
>                       }
>               }
> +             len = 0;
>       }
>  
> -     aiov.iov_base = (char *)buf;
> -     aiov.iov_len = nbyte;
> -     auio.uio_iov = &aiov;
> -     auio.uio_iovcnt = 1;
> -     auio.uio_segflg = sflg;
> +     aiov[0].iov_base = logtime;
> +     aiov[0].iov_len = len;
> +     aiov[1].iov_base = buffer;
> +     aiov[1].iov_len = nbyte;
> +     aiov[2].iov_base = "\r\n";
> +     aiov[2].iov_len = 2;
> +     auio.uio_segflg = UIO_SYSSPACE;
>       auio.uio_rw = UIO_WRITE;
>       auio.uio_procp = p;
>       auio.uio_offset = 0;
> -     auio.uio_resid = aiov.iov_len;
> -#ifdef KTRACE
> -     if (sflg == UIO_USERSPACE && KTRPOINT(p, KTR_GENIO))
> -             ktriov = aiov;
> -     else
> -             ktriov.iov_len = 0;
> -#endif
>  
> -     len = auio.uio_resid;
>       if (fp) {
>               int flags = (fp->f_flag & FNONBLOCK) ? MSG_DONTWAIT : 0;
> +
> +             auio.uio_iov = &aiov[0];
> +             auio.uio_iovcnt = 2;
> +             auio.uio_resid = aiov[0].iov_len + aiov[1].iov_len;
>               error = sosend(fp->f_data, NULL, &auio, NULL, NULL, flags);
> -             if (error == 0)
> -                     len -= auio.uio_resid;
>       } else {
>               KERNEL_LOCK();
>               if (constty || cn_devvp) {
> +                     auio.uio_iov = &aiov[1];
> +                     auio.uio_iovcnt = 2;
> +                     auio.uio_resid = aiov[1].iov_len + aiov[2].iov_len;
>                       error = cnwrite(0, &auio, 0);
> -                     if (error == 0)
> -                             len -= auio.uio_resid;
> -                     aiov.iov_base = "\r\n";
> -                     aiov.iov_len = 2;
> -                     auio.uio_iov = &aiov;
> -                     auio.uio_iovcnt = 1;
> -                     auio.uio_segflg = UIO_SYSSPACE;
> -                     auio.uio_rw = UIO_WRITE;
> -                     auio.uio_procp = p;
> -                     auio.uio_offset = 0;
> -                     auio.uio_resid = aiov.iov_len;
> -                     cnwrite(0, &auio, 0);
>               } else {
> +                     char *p;
> +
>                       /* XXX console redirection breaks down... */
> -                     if (sflg == UIO_USERSPACE) {
> -                             kbuf = malloc(len, M_TEMP, M_WAITOK);
> -                             error = copyin(aiov.iov_base, kbuf, len);
> -                     } else {
> -                             kbuf = aiov.iov_base;
> -                             error = 0;
> +                     auio.uio_iov = &aiov[1];
> +                     auio.uio_iovcnt = 1;
> +                     auio.uio_resid = aiov[1].iov_len;
> +                     p = auio.uio_iov[0].iov_base;
> +                     while (auio.uio_resid > 0) {
> +                             if (*p == '\0')
> +                                     break;
> +                             cnputc(*p);
> +                             p++;
> +                             auio.uio_resid--;
>                       }
> -                     if (error == 0)
> -                             for (i = 0; i < len; i++) {
> -                                     if (kbuf[i] == '\0')
> -                                             break;
> -                                     cnputc(kbuf[i]);
> -                                     auio.uio_resid--;
> -                             }
> -                     if (sflg == UIO_USERSPACE)
> -                             free(kbuf, M_TEMP, len);
> -                     if (error == 0)
> -                             len -= auio.uio_resid;
>                       cnputc('\n');
> +                     error = 0;
>               }
>               KERNEL_UNLOCK();
>       }
>  
> -#ifdef KTRACE
> -     if (error == 0 && ktriov.iov_len != 0)
> -             ktrgenio(p, -1, UIO_WRITE, &ktriov, len);
> -#endif
>       if (fp)
>               FRELE(fp, p);
> -     else if (error != EFAULT)
> +     else
>               error = ENOTCONN;
>       return (error);
>  }
> Index: usr.sbin/syslogd/syslogd.c
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/syslogd/syslogd.c,v
> retrieving revision 1.265
> diff -u -p -r1.265 syslogd.c
> --- usr.sbin/syslogd/syslogd.c        9 Mar 2021 15:08:23 -0000       1.265
> +++ usr.sbin/syslogd/syslogd.c        18 Mar 2021 16:04:22 -0000
> @@ -134,6 +134,7 @@ const char ctty[] = _PATH_CONSOLE;
>  #define SYNC_FILE    0x002   /* do fsync on file after printing */
>  #define ADDDATE              0x004   /* add a date to the message */
>  #define MARK         0x008   /* this message is a mark */
> +#define KERNDATE     0x010   /* the kernel has added log time */
> 
>  /*
>   * This structure represents the files that will have log
> @@ -289,6 +290,7 @@ size_t    ctl_reply_offset = 0;   /* Number o
>  
>  char *linebuf;
>  int   linesize;
> +struct        timeval now;
>  
>  int           fd_ctlconn, fd_udp, fd_udp6, send_udp, send_udp6;
>  struct event *ev_ctlaccept, *ev_ctlread, *ev_ctlwrite;
> @@ -305,6 +307,7 @@ char hostname_unknown[] = "???";
>  
>  void  klog_readcb(int, short, void *);
>  void  udp_readcb(int, short, void *);
> +void  sendsys_readcb(int, short, void *);
>  void  unix_readcb(int, short, void *);
>  int   reserve_accept4(int, int, struct event *,
>      void (*)(int, short, void *), struct sockaddr *, socklen_t *, int);
> @@ -339,10 +342,11 @@ void    fprintlog(struct filed *, int, char
>  void dropped_warn(int *, const char *);
>  void init(void);
>  void logevent(int, const char *);
> -void logline(int, int, char *, char *);
> +void logline(int, int, struct timeval *, char *, char *);
>  struct filed *find_dup(struct filed *);
> +size_t       parsekerntime(const char *, struct timeval *);
>  size_t       parsepriority(const char *, int *);
> -void printline(char *, char *);
> +void printline(int, char *, char *);
>  void printsys(char *);
>  void usage(void);
>  void wallmsg(struct filed *, struct iovec *);
> @@ -796,7 +800,7 @@ main(int argc, char *argv[])
>       event_set(ev_ctlwrite, fd_ctlconn, EV_WRITE|EV_PERSIST,
>           ctlconn_writecb, ev_ctlwrite);
>       event_set(ev_klog, fd_klog, EV_READ|EV_PERSIST, klog_readcb, ev_klog);
> -     event_set(ev_sendsys, fd_sendsys, EV_READ|EV_PERSIST, unix_readcb,
> +     event_set(ev_sendsys, fd_sendsys, EV_READ|EV_PERSIST, sendsys_readcb,
>           ev_sendsys);
>       event_set(ev_udp, fd_udp, EV_READ|EV_PERSIST, udp_readcb, ev_udp);
>       event_set(ev_udp6, fd_udp6, EV_READ|EV_PERSIST, udp_readcb, ev_udp6);
> @@ -1054,12 +1058,25 @@ udp_readcb(int fd, short event, void *ar
>               linebuf[n] = '\0';
>               cvthname((struct sockaddr *)&sa, resolve, sizeof(resolve));
>               log_debug("cvthname res: %s", resolve);
> -             printline(resolve, linebuf);
> +             printline(0, resolve, linebuf);
>       } else if (n == -1 && errno != EINTR && errno != EWOULDBLOCK)
>               log_warn("recvfrom udp");
>  }
>  
>  void
> +sendsys_readcb(int fd, short event, void *arg)
> +{
> +     ssize_t                  n;
> +
> +     n = recvfrom(fd, linebuf, LOG_MAXLINE, 0, NULL, 0);
> +     if (n > 0) {
> +             linebuf[n] = '\0';
> +             printline(KERNDATE, LocalHostName, linebuf);
> +     } else if (n == -1 && errno != EINTR && errno != EWOULDBLOCK)
> +             log_warn("recvfrom sendsyslog");
> +}
> +
> +void
>  unix_readcb(int fd, short event, void *arg)
>  {
>       struct sockaddr_un       sa;
> @@ -1071,7 +1088,7 @@ unix_readcb(int fd, short event, void *a
>           &salen);
>       if (n > 0) {
>               linebuf[n] = '\0';
> -             printline(LocalHostName, linebuf);
> +             printline(0, LocalHostName, linebuf);
>       } else if (n == -1 && errno != EINTR && errno != EWOULDBLOCK)
>               log_warn("recvfrom unix");
>  }
> @@ -1306,13 +1323,13 @@ tcp_readcb(struct bufferevent *bufev, vo
>                       linebuf[MINIMUM(len, LOG_MAXLINE)] = '\0';
>                       msg = linebuf;
>               }
> -             printline(p->p_hostname, msg);
> +             printline(0, p->p_hostname, msg);
>               evbuffer_drain(bufev->input, len);
>       }
>       /* Maximum frame has 5 digits, 1 space, MAXLINE chars, 1 new line. */
>       if (EVBUFFER_LENGTH(bufev->input) >= 5 + 1 + LOG_MAXLINE + 1) {
>               log_debug(", use %zu bytes", EVBUFFER_LENGTH(bufev->input));
> -             printline(p->p_hostname, EVBUFFER_DATA(bufev->input));
> +             printline(0, p->p_hostname, EVBUFFER_DATA(bufev->input));
>               evbuffer_drain(bufev->input, -1);
>       } else if (EVBUFFER_LENGTH(bufev->input) > 0)
>               log_debug(", buffer %zu bytes", EVBUFFER_LENGTH(bufev->input));
> @@ -1560,6 +1577,24 @@ usage(void)
>  }
>  
>  /*
> + * Kernel prepends microtime(9) with space in front of log messages.
> + * It is called at beginnning of sendsyslog(2) and has 6 digits precision.
> + */
> +size_t
> +parsekerntime(const char *msg, struct timeval *logtime)
> +{
> +     struct timeval time;
> +     int timelen, timenum;
> +
> +     timenum = sscanf(msg, "%lld.%06ld %n",
> +         &time.tv_sec, &time.tv_usec, &timelen);

Normally people don't use sscanf(3) in the tree.  I assume it's fine
here because you have control over the input.  But sscanf(3) sticks
out so I figured I'd check that this is an acceptable use case.

> +     if (timenum != 2)
> +             return (0);
> +     *logtime = time;
> +     return (timelen);
> +}
> +
> +/*
>   * Parse a priority code of the form "<123>" into pri, and return the
>   * length of the priority code including the surrounding angle brackets.
>   */
> @@ -1591,14 +1626,21 @@ parsepriority(const char *msg, int *pri)
>   * on the appropriate log files.
>   */
>  void
> -printline(char *hname, char *msg)
> +printline(int flags, char *hname, char *msg)
>  {
> +     struct timeval logtime;
>       int pri;
>       char *p, *q, line[LOG_MAXLINE + 4 + 1];  /* message, encoding, NUL */
>  
>       /* test for special codes */
> -     pri = DEFUPRI;
>       p = msg;
> +     timerclear(&logtime);
> +     if (flags & KERNDATE) {
> +             p += parsekerntime(p, &logtime);
> +             if (!timerisset(&logtime))
> +                     flags &=~ KERNDATE;
> +     }
> +     pri = DEFUPRI;
>       p += parsepriority(p, &pri);
>       if (pri &~ (LOG_FACMASK|LOG_PRIMASK))
>               pri = DEFUPRI;
> @@ -1619,7 +1661,7 @@ printline(char *hname, char *msg)
>       }
>       line[LOG_MAXLINE] = *q = '\0';
>  
> -     logline(pri, 0, hname, line);
> +     logline(pri, flags, &logtime, hname, line);
>  }
>  
>  /*
> @@ -1655,7 +1697,7 @@ printsys(char *msg)
>               while (*p && (c = *p++) != '\n' && q < &line[sizeof(line) - 4])
>                       q = vis(q, c, 0, 0);
>  
> -             logline(pri, flags, LocalHostName, line);
> +             logline(pri, flags, NULL, LocalHostName, line);
>       }
>  }
>  
> @@ -1677,21 +1719,20 @@ vlogmsg(int pri, const char *proc, const
>               init_dropped++;
>               return;
>       }
> -     logline(pri, ADDDATE, LocalHostName, msg);
> +     logline(pri, ADDDATE, NULL, LocalHostName, msg);
>  }
>  
> -struct timeval       now;
> -
>  /*
>   * Log a message to the appropriate log files, users, etc. based on
>   * the priority.
>   */
>  void
> -logline(int pri, int flags, char *from, char *msg)
> +logline(int pri, int flags, struct timeval *kerntime, char *from, char *msg)
>  {
>       struct filed *f;
> +     struct timeval *logtime;
>       int fac, msglen, prilev, i;
> -     char timestamp[33];
> +     char timestamp[sizeof("2003-08-24T05:14:15.000003-07:00")];
>       char prog[NAME_MAX+1];
>  
>       log_debug("logline: pri 0%o, flags 0x%x, from %s, msg %s",
> @@ -1768,21 +1809,25 @@ logline(int pri, int flags, char *from, 
>       }
>  
>       (void)gettimeofday(&now, NULL);
> +     logtime = (flags & KERNDATE) ? kerntime : &now;

Do you need to call gettimeofday(2) here if KERNDATE is set?

Maybe:

        if (flags & KERNDATE)
                logtime = kerntime;
        else {
                gettimeofday(&now, NULL)
                logtime = &now;
        }

>       if (flags & ADDDATE) {
>               if (ZuluTime) {
>                       struct tm *tm;
>                       size_t l;
>  
> -                     tm = gmtime(&now.tv_sec);
> +                     tm = gmtime(&logtime->tv_sec);
>                       l = strftime(timestamp, sizeof(timestamp), "%FT%T", tm);
>                       /*
> -                      * Use only millisecond precision as some time has
> -                      * passed since syslog(3) was called.
> +                      * Use millisecond precision for gettimeofday(2) as
> +                      * some time has passed since syslog(3) was called.
> +                      * Kernel time is more precise, use microseconds.
>                        */
>                       snprintf(timestamp + l, sizeof(timestamp) - l,
> -                         ".%03ldZ", now.tv_usec / 1000);
> +                         ".%0*ldZ", (flags & KERNDATE) ? 6 : 3,
> +                         (flags & KERNDATE) ? logtime->tv_usec :
> +                         logtime->tv_usec / 1000);
>               } else
> -                     strlcpy(timestamp, ctime(&now.tv_sec) + 4, 16);
> +                     strlcpy(timestamp, ctime(&logtime->tv_sec) + 4, 16);

FWIW, the standard says ctime(3) can return NULL.

I have not experimented with it on OpenBSD to determine how to force
this to happen, so you're probably fine for all reasonable system UTC
times.  If it ever did happen we'd just fault when trying to read the
zero page.

>       }
>  
>       /* extract facility and priority level */
> @@ -2961,9 +3006,9 @@ getmsgbufsize(void)
>  
>       mib[0] = CTL_KERN;
>       mib[1] = KERN_MSGBUFSIZE;
> -     size = sizeof msgbufsize;
> +     size = sizeof(msgbufsize);
>       if (sysctl(mib, 2, &msgbufsize, &size, NULL, 0) == -1) {
> -             log_debug("couldn't get kern.msgbufsize");
> +             log_warn("sysctl kern.msgbufsize");
>               return (0);
>       }
>       return (msgbufsize);
> @@ -3000,7 +3045,8 @@ markit(void)
>       (void)gettimeofday(&now, NULL);
>       MarkSeq += TIMERINTVL;
>       if (MarkSeq >= MarkInterval) {
> -             logline(LOG_INFO, ADDDATE|MARK, LocalHostName, "-- MARK --");
> +             logline(LOG_INFO, ADDDATE|MARK, NULL, LocalHostName,
> +                 "-- MARK --");
>               MarkSeq = 0;
>       }
>  
> 

Reply via email to