From 1a874a126a54fdc188cebd0c58579851c37d1814 Mon Sep 17 00:00:00 2001 From: Ed Schouten Date: Sun, 15 Apr 2018 08:34:16 +0000 Subject: [PATCH] Add RFC 5424 syslog message output to syslogd. - Move all of the code responsible for transmitting log messages into a separate function, fprintlog_write(). - Instead of manually modifying a list of iovecs, add a structure iovlist with some helper functions. - Alter the F_FORW (UDP message forwarding) case to also use iovecs like the other cases. Use sendmsg() instead of sendto(). - In the case of F_FORW, truncate the message to a size dependent on the address family (AF_INET, AF_INET6), as proposed by RFC 5426. - Move all traditional message formatting into fprintlog_bsd(). Get rid of some of the string copying and snprintf()'ing. Simply emit more iovecs to get the job done. - Increase ttymsg()'s limit of 7 iovecs to 32. Add a definition for this limit, so it can be reused by iovlist. - Add fprintlog_rfc5424() to emit RFC 5424 formatted log entries. - Add a "-O" command line option to enable RFC 5424 formatting. It would have been nicer if we supported "-o rfc5424", just like on NetBSD. Unfortunately, the "-o" flag is already used for a different purpose on FreeBSD. - Don't truncate hostnames in the RFC 5424 case, as suggested by that specific RFC. For people interested in using this, this feature can be enabled by adding the following line to /etc/rc.conf: syslogd_flags="-s -O rfc5424" Differential Revision: https://reviews.freebsd.org/D15011 --- usr.bin/wall/ttymsg.c | 2 +- usr.bin/wall/ttymsg.h | 2 + usr.sbin/syslogd/syslogd.8 | 17 +- usr.sbin/syslogd/syslogd.c | 451 +++++++++++++++++++++++-------------- 4 files changed, 305 insertions(+), 167 deletions(-) diff --git a/usr.bin/wall/ttymsg.c b/usr.bin/wall/ttymsg.c index c8dc658a7931..beae788a9ba2 100644 --- a/usr.bin/wall/ttymsg.c +++ b/usr.bin/wall/ttymsg.c @@ -61,7 +61,7 @@ static const char sccsid[] = "@(#)ttymsg.c 8.2 (Berkeley) 11/16/93"; const char * ttymsg(struct iovec *iov, int iovcnt, const char *line, int tmout) { - struct iovec localiov[7]; + struct iovec localiov[TTYMSG_IOV_MAX]; ssize_t left, wret; int cnt, fd; char device[MAXNAMLEN] = _PATH_DEV; diff --git a/usr.bin/wall/ttymsg.h b/usr.bin/wall/ttymsg.h index 31312aa94f55..1915720087e6 100644 --- a/usr.bin/wall/ttymsg.h +++ b/usr.bin/wall/ttymsg.h @@ -1,3 +1,5 @@ /* $FreeBSD$ */ +#define TTYMSG_IOV_MAX 32 + const char *ttymsg(struct iovec *, int, const char *, int); diff --git a/usr.sbin/syslogd/syslogd.8 b/usr.sbin/syslogd/syslogd.8 index ce82472b49c4..2dff8be66632 100644 --- a/usr.sbin/syslogd/syslogd.8 +++ b/usr.sbin/syslogd/syslogd.8 @@ -28,7 +28,7 @@ .\" @(#)syslogd.8 8.1 (Berkeley) 6/6/93 .\" $FreeBSD$ .\" -.Dd November 28, 2017 +.Dd April 9, 2018 .Dt SYSLOGD 8 .Os .Sh NAME @@ -42,6 +42,7 @@ .Op Fl f Ar config_file .Op Fl l Oo Ar mode Ns \&: Oc Ns Ar path .Op Fl m Ar mark_interval +.Op Fl O Ar format .Op Fl P Ar pid_file .Op Fl p Ar log_socket .Op Fl S Ar logpriv_socket @@ -242,6 +243,20 @@ Usually the .Dq kern facility is reserved for messages read directly from .Pa /dev/klog . +.It Fl O Ar format +Select the output format of generated log messages. +The values +.Ar bsd +and +.Ar rfc3164 +are used to generate RFC 3164 log messages. +The values +.Ar syslog +and +.Ar rfc5424 +are used to generate RFC 5424 log messages, +having RFC 3339 timestamps with microsecond precision. +The default is to generate RFC 3164 log messages. .It Fl m Ar mark_interval Select the number of minutes between .Dq mark diff --git a/usr.sbin/syslogd/syslogd.c b/usr.sbin/syslogd/syslogd.c index 6074252bdff8..1f9dfc17aa11 100644 --- a/usr.sbin/syslogd/syslogd.c +++ b/usr.sbin/syslogd/syslogd.c @@ -136,6 +136,7 @@ __FBSDID("$FreeBSD$"); #include #include #include +#include #include #include #include @@ -367,9 +368,12 @@ static int KeepKernFac; /* Keep remotely logged kernel facility */ static int needdofsync = 0; /* Are any file(s) waiting to be fsynced? */ static struct pidfh *pfh; static int sigpipe[2]; /* Pipe to catch a signal during select(). */ +static bool RFC3164OutputFormat = true; /* Use legacy format by default. */ static volatile sig_atomic_t MarkSet, WantDie, WantInitialize, WantReapchild; +struct iovlist; + static int allowaddr(char *); static int addfile(struct filed *); static int addpeer(struct peer *); @@ -386,6 +390,7 @@ static void dofsync(void); static void domark(int); static void fprintlog_first(struct filed *, const char *, const char *, const char *, const char *, const char *, const char *, int); +static void fprintlog_write(struct filed *, struct iovlist *, int); static void fprintlog_successive(struct filed *, int); static void init(int); static void logerror(const char *); @@ -498,7 +503,7 @@ main(int argc, char *argv[]) if (madvise(NULL, 0, MADV_PROTECT) != 0) dprintf("madvise() failed: %s\n", strerror(errno)); - while ((ch = getopt(argc, argv, "468Aa:b:cCdf:FHkl:m:nNop:P:sS:Tuv")) + while ((ch = getopt(argc, argv, "468Aa:b:cCdf:FHkl:m:nNoO:p:P:sS:Tuv")) != -1) switch (ch) { #ifdef INET @@ -621,6 +626,16 @@ main(int argc, char *argv[]) case 'n': resolve = 0; break; + case 'O': + if (strcmp(optarg, "bsd") == 0 || + strcmp(optarg, "rfc3164") == 0) + RFC3164OutputFormat = true; + else if (strcmp(optarg, "syslog") == 0 || + strcmp(optarg, "rfc5424") == 0) + RFC3164OutputFormat = false; + else + usage(); + break; case 'o': use_bootfile = 1; break; @@ -880,12 +895,12 @@ static void usage(void) { - fprintf(stderr, "%s\n%s\n%s\n%s\n%s\n", - "usage: syslogd [-468ACcdFHknosTuv] [-a allowed_peer]", - " [-b bind_address] [-f config_file]", - " [-l [mode:]path] [-m mark_interval]", - " [-P pid_file] [-p log_socket]", - " [-S logpriv_socket]"); + fprintf(stderr, + "usage: syslogd [-468ACcdFHknosTuv] [-a allowed_peer]\n" + " [-b bind_address] [-f config_file]\n" + " [-l [mode:]path] [-m mark_interval]\n" + " [-O format] [-P pid_file] [-p log_socket]\n" + " [-S logpriv_socket]\n"); exit(1); } @@ -1558,177 +1573,114 @@ dofsync(void) } } -#define IOV_SIZE 7 +/* + * List of iovecs to which entries can be appended. + * Used for constructing the message to be logged. + */ +struct iovlist { + struct iovec iov[TTYMSG_IOV_MAX]; + size_t iovcnt; + size_t totalsize; +}; + static void -fprintlog_first(struct filed *f, const char *hostname, const char *app_name, - const char *procid, const char *msgid __unused, - const char *structured_data __unused, const char *msg, int flags) +iovlist_init(struct iovlist *il) { - struct iovec iov[IOV_SIZE]; + + il->iovcnt = 0; + il->totalsize = 0; +} + +static void +iovlist_append(struct iovlist *il, const char *str) +{ + size_t size; + + /* Discard components if we've run out of iovecs. */ + if (il->iovcnt < nitems(il->iov)) { + size = strlen(str); + il->iov[il->iovcnt++] = (struct iovec){ + .iov_base = __DECONST(char *, str), + .iov_len = size, + }; + il->totalsize += size; + } +} + +static void +iovlist_truncate(struct iovlist *il, size_t size) +{ + struct iovec *last; + size_t diff; + + while (size > il->totalsize) { + diff = size - il->totalsize; + last = &il->iov[il->iovcnt - 1]; + if (diff >= last->iov_len) { + /* Remove the last iovec entirely. */ + --il->iovcnt; + il->totalsize -= last->iov_len; + } else { + /* Remove the last iovec partially. */ + last->iov_len -= diff; + il->totalsize -= diff; + } + } +} + +static void +fprintlog_write(struct filed *f, struct iovlist *il, int flags) +{ + struct msghdr msghdr; struct addrinfo *r; - int l, lsent = 0; - char tagged_msg[MAXLINE + 1], line[MAXLINE + 1], greetings[200]; - char nul[] = "", space[] = " ", lf[] = "\n", crlf[] = "\r\n"; - char timebuf[RFC3164_DATELEN + 1]; + struct socklist *sl; const char *msgret; - - if (strftime(timebuf, sizeof(timebuf), RFC3164_DATEFMT, - &f->f_lasttime.tm) == 0) - timebuf[0] = '\0'; - if (f->f_type == F_WALL) { - /* The time displayed is not synchornized with the other log - * destinations (like messages). Following fragment was using - * ctime(&now), which was updating the time every 30 sec. - * With f_lasttime, time is synchronized correctly. - */ - iov[0] = (struct iovec){ - .iov_base = greetings, - .iov_len = snprintf(greetings, sizeof(greetings), - "\r\n\7Message from syslogd@%s " - "at %.24s ...\r\n", hostname, timebuf) - }; - if (iov[0].iov_len >= sizeof(greetings)) - iov[0].iov_len = sizeof(greetings) - 1; - iov[1] = (struct iovec){ - .iov_base = nul, - .iov_len = 0 - }; - } else { - iov[0] = (struct iovec){ - .iov_base = timebuf, - .iov_len = strlen(timebuf) - }; - iov[1] = (struct iovec){ - .iov_base = space, - .iov_len = 1 - }; - } - - if (LogFacPri) { - static char fp_buf[30]; /* Hollow laugh */ - int fac = f->f_prevpri & LOG_FACMASK; - int pri = LOG_PRI(f->f_prevpri); - const char *f_s = NULL; - char f_n[5]; /* Hollow laugh */ - const char *p_s = NULL; - char p_n[5]; /* Hollow laugh */ - - if (LogFacPri > 1) { - const CODE *c; - - for (c = facilitynames; c->c_name; c++) { - if (c->c_val == fac) { - f_s = c->c_name; - break; - } - } - for (c = prioritynames; c->c_name; c++) { - if (c->c_val == pri) { - p_s = c->c_name; - break; - } - } - } - if (!f_s) { - snprintf(f_n, sizeof f_n, "%d", LOG_FAC(fac)); - f_s = f_n; - } - if (!p_s) { - snprintf(p_n, sizeof p_n, "%d", pri); - p_s = p_n; - } - snprintf(fp_buf, sizeof fp_buf, "<%s.%s> ", f_s, p_s); - iov[2] = (struct iovec){ - .iov_base = fp_buf, - .iov_len = strlen(fp_buf) - }; - } else { - iov[2] = (struct iovec){ - .iov_base = nul, - .iov_len = 0 - }; - } - /* Prepend the application name to the message if provided. */ - if (app_name != NULL) { - if (procid != NULL) - snprintf(tagged_msg, sizeof(tagged_msg), - "%s[%s]: %s", app_name, procid, msg); - else - snprintf(tagged_msg, sizeof(tagged_msg), - "%s: %s", app_name, msg); - msg = tagged_msg; - } - iov[3] = (struct iovec){ - .iov_base = __DECONST(char *, hostname), - .iov_len = strlen(hostname) - }; - iov[4] = (struct iovec){ - .iov_base = space, - .iov_len = 1 - }; - iov[5] = (struct iovec){ - .iov_base = __DECONST(char *, msg), - .iov_len = strlen(msg) - }; - dprintf("Logging to %s", TypeNames[f->f_type]); - f->f_time = now; + ssize_t lsent; switch (f->f_type) { - case F_UNUSED: - dprintf("\n"); - break; - case F_FORW: + /* Truncate messages to RFC 5426 recommended size. */ dprintf(" %s", f->fu_forw_hname); switch (f->fu_forw_addr->ai_addr->sa_family) { #ifdef INET case AF_INET: dprintf(":%d\n", ntohs(satosin(f->fu_forw_addr->ai_addr)->sin_port)); + iovlist_truncate(il, 480); break; #endif #ifdef INET6 case AF_INET6: dprintf(":%d\n", ntohs(satosin6(f->fu_forw_addr->ai_addr)->sin6_port)); + iovlist_truncate(il, 1180); break; #endif default: dprintf("\n"); } - /* check for local vs remote messages */ - if (strcasecmp(hostname, LocalHostName)) - l = snprintf(line, sizeof line - 1, - "<%d>%.15s Forwarded from %s: %s", - f->f_prevpri, (char *)iov[0].iov_base, - hostname, (char *)iov[5].iov_base); - else - l = snprintf(line, sizeof line - 1, "<%d>%.15s %s", - f->f_prevpri, (char *)iov[0].iov_base, - (char *)iov[5].iov_base); - if (l < 0) - l = 0; - else if (l > MAXLINE) - l = MAXLINE; + lsent = 0; for (r = f->fu_forw_addr; r; r = r->ai_next) { - struct socklist *sl; - + memset(&msghdr, 0, sizeof(msghdr)); + msghdr.msg_name = r->ai_addr; + msghdr.msg_namelen = r->ai_addrlen; + msghdr.msg_iov = il->iov; + msghdr.msg_iovlen = il->iovcnt; STAILQ_FOREACH(sl, &shead, next) { if (sl->sl_ss.ss_family == AF_LOCAL || sl->sl_ss.ss_family == AF_UNSPEC || sl->sl_socket < 0) continue; - lsent = sendto(sl->sl_socket, line, l, 0, - r->ai_addr, r->ai_addrlen); - if (lsent == l) + lsent = sendmsg(sl->sl_socket, &msghdr, 0); + if (lsent == (ssize_t)il->totalsize) break; } - if (lsent == l && !send_to_all) + if (lsent == (ssize_t)il->totalsize && !send_to_all) break; } - dprintf("lsent/l: %d/%d\n", lsent, l); - if (lsent != l) { + dprintf("lsent/totalsize: %zd/%zu\n", lsent, il->totalsize); + if (lsent != (ssize_t)il->totalsize) { int e = errno; logerror("sendto"); errno = e; @@ -1758,11 +1710,8 @@ fprintlog_first(struct filed *f, const char *hostname, const char *app_name, case F_FILE: dprintf(" %s\n", f->fu_fname); - iov[6] = (struct iovec){ - .iov_base = lf, - .iov_len = 1 - }; - if (writev(f->f_file, iov, nitems(iov)) < 0) { + iovlist_append(il, "\n"); + if (writev(f->f_file, il->iov, il->iovcnt) < 0) { /* * If writev(2) fails for potentially transient errors * like the filesystem being full, ignore it. @@ -1782,10 +1731,7 @@ fprintlog_first(struct filed *f, const char *hostname, const char *app_name, case F_PIPE: dprintf(" %s\n", f->fu_pipe_pname); - iov[6] = (struct iovec){ - .iov_base = lf, - .iov_len = 1 - }; + iovlist_append(il, "\n"); if (f->fu_pipe_pid == 0) { if ((f->f_file = p_open(f->fu_pipe_pname, &f->fu_pipe_pid)) < 0) { @@ -1793,7 +1739,7 @@ fprintlog_first(struct filed *f, const char *hostname, const char *app_name, break; } } - if (writev(f->f_file, iov, nitems(iov)) < 0) { + if (writev(f->f_file, il->iov, il->iovcnt) < 0) { int e = errno; deadq_enter(f->fu_pipe_pid, f->fu_pipe_pname); @@ -1812,12 +1758,9 @@ fprintlog_first(struct filed *f, const char *hostname, const char *app_name, case F_TTY: dprintf(" %s%s\n", _PATH_DEV, f->fu_fname); - iov[6] = (struct iovec){ - .iov_base = crlf, - .iov_len = 2 - }; + iovlist_append(il, "\r\n"); errno = 0; /* ttymsg() only sometimes returns an errno */ - if ((msgret = ttymsg(iov, nitems(iov), f->fu_fname, 10))) { + if ((msgret = ttymsg(il->iov, il->iovcnt, f->fu_fname, 10))) { f->f_type = F_UNUSED; logerror(msgret); } @@ -1826,14 +1769,190 @@ fprintlog_first(struct filed *f, const char *hostname, const char *app_name, case F_USERS: case F_WALL: dprintf("\n"); - iov[6] = (struct iovec){ - .iov_base = crlf, - .iov_len = 2 - }; - wallmsg(f, iov, nitems(iov)); + iovlist_append(il, "\r\n"); + wallmsg(f, il->iov, il->iovcnt); break; } +} + +static void +fprintlog_rfc5424(struct filed *f, const char *hostname, const char *app_name, + const char *procid, const char *msgid, const char *structured_data, + const char *msg, int flags) +{ + struct iovlist il; + suseconds_t usec; + int i; + char timebuf[33], priority_number[5]; + + iovlist_init(&il); + if (f->f_type == F_WALL) + iovlist_append(&il, "\r\n\aMessage from syslogd ...\r\n"); + iovlist_append(&il, "<"); + snprintf(priority_number, sizeof(priority_number), "%d", f->f_prevpri); + iovlist_append(&il, priority_number); + iovlist_append(&il, ">1 "); + if (strftime(timebuf, sizeof(timebuf), "%FT%T.______%z", + &f->f_lasttime.tm) == sizeof(timebuf) - 2) { + /* Add colon to the time zone offset, which %z doesn't do. */ + timebuf[32] = '\0'; + timebuf[31] = timebuf[30]; + timebuf[30] = timebuf[29]; + timebuf[29] = ':'; + + /* Overwrite space for microseconds with actual value. */ + usec = f->f_lasttime.usec; + for (i = 25; i >= 20; --i) { + timebuf[i] = usec % 10 + '0'; + usec /= 10; + } + iovlist_append(&il, timebuf); + } else + iovlist_append(&il, "-"); + iovlist_append(&il, " "); + iovlist_append(&il, hostname); + iovlist_append(&il, " "); + iovlist_append(&il, app_name == NULL ? "-" : app_name); + iovlist_append(&il, " "); + iovlist_append(&il, procid == NULL ? "-" : procid); + iovlist_append(&il, " "); + iovlist_append(&il, msgid == NULL ? "-" : msgid); + iovlist_append(&il, " "); + iovlist_append(&il, structured_data == NULL ? "-" : structured_data); + iovlist_append(&il, " "); + iovlist_append(&il, msg); + + fprintlog_write(f, &il, flags); +} + +static void +fprintlog_rfc3164(struct filed *f, const char *hostname, const char *app_name, + const char *procid, const char *msg, int flags) +{ + struct iovlist il; + const CODE *c; + int facility, priority; + char timebuf[RFC3164_DATELEN + 1], facility_number[5], + priority_number[5]; + bool facility_found, priority_found; + + if (strftime(timebuf, sizeof(timebuf), RFC3164_DATEFMT, + &f->f_lasttime.tm) == 0) + timebuf[0] = '\0'; + + iovlist_init(&il); + switch (f->f_type) { + case F_FORW: + /* Message forwarded over the network. */ + iovlist_append(&il, "<"); + snprintf(priority_number, sizeof(priority_number), "%d", + f->f_prevpri); + iovlist_append(&il, priority_number); + iovlist_append(&il, ">"); + iovlist_append(&il, timebuf); + if (strcasecmp(hostname, LocalHostName) != 0) { + iovlist_append(&il, " Forwarded from "); + iovlist_append(&il, hostname); + iovlist_append(&il, ":"); + } + iovlist_append(&il, " "); + break; + + case F_WALL: + /* Message written to terminals. */ + iovlist_append(&il, "\r\n\aMessage from syslogd@"); + iovlist_append(&il, hostname); + iovlist_append(&il, " at "); + iovlist_append(&il, timebuf); + iovlist_append(&il, " ...\r\n"); + break; + + default: + /* Message written to files. */ + iovlist_append(&il, timebuf); + iovlist_append(&il, " "); + iovlist_append(&il, hostname); + iovlist_append(&il, " "); + + if (LogFacPri) { + iovlist_append(&il, "<"); + + facility = f->f_prevpri & LOG_FACMASK; + facility_found = false; + if (LogFacPri > 1) { + for (c = facilitynames; c->c_name; c++) { + if (c->c_val == facility) { + iovlist_append(&il, c->c_name); + facility_found = true; + break; + } + } + } + if (!facility_found) { + snprintf(facility_number, + sizeof(facility_number), "%d", + LOG_FAC(facility)); + iovlist_append(&il, facility_number); + } + + iovlist_append(&il, "."); + + priority = LOG_PRI(f->f_prevpri); + priority_found = false; + if (LogFacPri > 1) { + for (c = prioritynames; c->c_name; c++) { + if (c->c_val == priority) { + iovlist_append(&il, c->c_name); + priority_found = true; + break; + } + } + } + if (!priority_found) { + snprintf(priority_number, + sizeof(priority_number), "%d", priority); + iovlist_append(&il, priority_number); + } + + iovlist_append(&il, "> "); + } + break; + } + + /* Message body with application name and process ID prefixed. */ + if (app_name != NULL) { + iovlist_append(&il, app_name); + if (procid != NULL) { + iovlist_append(&il, "["); + iovlist_append(&il, procid); + iovlist_append(&il, "]"); + } + iovlist_append(&il, ": "); + } + iovlist_append(&il, msg); + + fprintlog_write(f, &il, flags); +} + +static void +fprintlog_first(struct filed *f, const char *hostname, const char *app_name, + const char *procid, const char *msgid __unused, + const char *structured_data __unused, const char *msg, int flags) +{ + + dprintf("Logging to %s", TypeNames[f->f_type]); + f->f_time = now; f->f_prevcount = 0; + if (f->f_type == F_UNUSED) { + dprintf("\n"); + return; + } + + if (RFC3164OutputFormat) + fprintlog_rfc3164(f, hostname, app_name, procid, msg, flags); + else + fprintlog_rfc5424(f, hostname, app_name, procid, msgid, + structured_data, msg, flags); } /* @@ -2229,8 +2348,10 @@ init(int signo) if (gethostname(LocalHostName, sizeof(LocalHostName))) err(EX_OSERR, "gethostname() failed"); if ((p = strchr(LocalHostName, '.')) != NULL) { - *p++ = '\0'; - LocalDomain = p; + /* RFC 5424 prefers logging FQDNs. */ + if (RFC3164OutputFormat) + *p = '\0'; + LocalDomain = p + 1; } else { LocalDomain = ""; }