[v2,7/7] misc: syslog: Use RFC5424

Message ID 20220218142322.432304-8-adhemerval.zanella@linaro.org
State Superseded
Headers
Series Use RFC5424 for syslog |

Checks

Context Check Description
dj/TryBot-apply_patch success Patch applied to master at the time it was sent
dj/TryBot-32bit fail Patch caused testsuite regressions

Commit Message

Adhemerval Zanella Netto Feb. 18, 2022, 2:23 p.m. UTC
  Current syslog format provides limited timestamp information (not full
year information nor microsecond precision) and the timezone information
might incur in confusion [1] since there is no metadata information on
how it was generated.

So instead of using another ad-hoc syslog format, this patch adapts it
to follow RFC5424:

  - VERSION is set as 1.
  - TIMESTAMP is logged as described by RFC 3339 using UTC ('Z') with
    maximum allowed TIME-SECFRAC precision (microseconds).
  - HOSTNAME is obtained with gethostname (as allowed by the RFC).
  - PROCID is only set if LOG_PID is previously set by openlog.
  - MSGID and STRUCTURED-DATA are both set to NILVALUE.

Checked on x86_64-linux-gnu.

[1] https://sourceware.org/pipermail/libc-alpha/2021-March/123583.html
---
 misc/syslog.c     | 79 +++++++++++++++++++++++++++++++++--------------
 misc/tst-syslog.c | 28 ++++++++---------
 2 files changed, 69 insertions(+), 38 deletions(-)
  

Comments

Paul Eggert Feb. 19, 2022, 3:50 a.m. UTC | #1
There should be documentation about the change, somewhere.

On 2/18/22 06:23, Adhemerval Zanella via Libc-alpha wrote:

> +  struct tm *gmtm = __gmtime64_r (&ts.tv_sec, &now_tm);
> +  if (gmtm == NULL)
> +    strcpy (timebuf->b, NILVALUE);

RFC 5424 requires unsigned four-digit years, so change "gmtm == NULL" to 
"gmtm == NULL || ! (-1900 <= gmtm->tm_year && gmtm->tm_year <= 9999 - 
1900)". Or, if the idea is to depart from RFC 5424 for out-of-range 
years (which might be better), document the departure.

> +  else
> +    {
> +      size_t datebytes = __strftime_l (timebuf->b, sizeof timebuf->b,
> +				       "%FT%T", gmtm, _nl_C_locobj_ptr);
RFC 5424 does not allow leap seconds, so something like this:

     if (gmtm->tv_sec == 60)
       {
          gmtm->tv_sec = 59;
          gmtm->tv_nsec = 999999999;
       }

before calling __strftime_l. (Or again, if the idea is to depart from 
RFC 5424, document the departure.)

> +      int usec = ts.tv_nsec / 1000;

Typically fewer instructions (and still correct) if you replace 1000 
with 1000ul (admittedly a microoptimization....).
  
Dan Raymond Feb. 19, 2022, 8:35 p.m. UTC | #2
On 3/9/2021 4:45 PM, Dan Raymond via Libc-alpha wrote:

> I noticed an issue with syslog() timestamps.  When a client generates a
> timestamp inside a call to syslog() it uses localtime_r().  When the
> server (syslogd) generates a timestamp it uses localtime().  The
> observable difference is that localtime() checks the timezone settings
> while localtime_r() does not.  Hence if you change the timezone settings
> while syslogd is running: server-generated timestamps will be correct
> while client-generated timestamps will be incorrect.
>
> Is this something that should be fixed?  There are various ways to
> mitigate the problem but none are ideal:
>
> 1) reboot or restart all processes using syslog() after changing the
> timezone (this may not be possible/practical)
>
> 2) call tzset() from all processes using syslog() after changing the
> timezone (not likely to be possible)
>
> 3) start syslogd with -t command line option to disable client-generated
> timestamps (timestamp accuracy is decreased)
>
> On the other hand, switching from localtime_r() to localtime() inside
> syslog() could adversely impact performance.  For instance it could
> incur an additional call to stat('/etc/localtime', ...) for each call to
> syslog().  This cost would be avoided if the calling process sets the TZ
> environment variable, however, since only changes to TZ would
> subsequently trigger a filesystem access.  Thoughts?
>   

Adhemerval, since you have been making changes in this area recently I 
wonder if you had any comments about the issue I raised last year 
(quoted above)?
  
Paul Eggert Feb. 19, 2022, 10:23 p.m. UTC | #3
On 2/19/22 12:35, Dan Raymond wrote:
> Adhemerval, since you have been making changes in this area recently I 
> wonder if you had any comments about the issue I raised last year 
> (quoted above)?

Adhemerval's patches switch from localtime to gmtime, which should avoid 
many of the issues you raised.

If a process switches its TZ setting from a timezone that has leap 
seconds, to one that doesn't (or vice versa), there would be problems 
even with gmtime - but that would be a bad idea for so many other 
reasons that I don't think we need to worry too much about it.
  
Adhemerval Zanella Netto Feb. 21, 2022, 2:01 p.m. UTC | #4
On 19/02/2022 00:50, Paul Eggert wrote:
> There should be documentation about the change, somewhere.
> 
> On 2/18/22 06:23, Adhemerval Zanella via Libc-alpha wrote:
> 
>> +  struct tm *gmtm = __gmtime64_r (&ts.tv_sec, &now_tm);
>> +  if (gmtm == NULL)
>> +    strcpy (timebuf->b, NILVALUE);
> 
> RFC 5424 requires unsigned four-digit years, so change "gmtm == NULL" to "gmtm == NULL || ! (-1900 <= gmtm->tm_year && gmtm->tm_year <= 9999 - 1900)". Or, if the idea is to depart from RFC 5424 for out-of-range years (which might be better), document the departure.

Indeed I don't see why we can't support out-of-range years in such case.  I will add
a comment.

> 
>> +  else
>> +    {
>> +      size_t datebytes = __strftime_l (timebuf->b, sizeof timebuf->b,
>> +                       "%FT%T", gmtm, _nl_C_locobj_ptr);
> RFC 5424 does not allow leap seconds, so something like this:
> 
>     if (gmtm->tv_sec == 60)
>       {
>          gmtm->tv_sec = 59;
>          gmtm->tv_nsec = 999999999;
>       }
> 
> before calling __strftime_l. (Or again, if the idea is to depart from RFC 5424, document the departure.)

I think this is worth to support, I will add such test.

> 
>> +      int usec = ts.tv_nsec / 1000;
> 
> Typically fewer instructions (and still correct) if you replace 1000 with 1000ul (admittedly a microoptimization....).

Ack.
  
Adhemerval Zanella Netto Feb. 21, 2022, 4:18 p.m. UTC | #5
On 21/02/2022 11:01, Adhemerval Zanella wrote:
> 
> 
> On 19/02/2022 00:50, Paul Eggert wrote:
>>> +  else
>>> +    {
>>> +      size_t datebytes = __strftime_l (timebuf->b, sizeof timebuf->b,
>>> +                       "%FT%T", gmtm, _nl_C_locobj_ptr);
>> RFC 5424 does not allow leap seconds, so something like this:
>>
>>     if (gmtm->tv_sec == 60)
>>       {
>>          gmtm->tv_sec = 59;
>>          gmtm->tv_nsec = 999999999;
>>       }
>>
>> before calling __strftime_l. (Or again, if the idea is to depart from RFC 5424, document the departure.)
> 
> I think this is worth to support, I will add such test.

In fact struct tm does not 'tv_nsec' so I am confused about your suggestion here.
  
Paul Eggert Feb. 21, 2022, 10:25 p.m. UTC | #6
On 2/21/22 08:18, Adhemerval Zanella wrote:
>>>      if (gmtm->tv_sec == 60)
>>>        {
>>>           gmtm->tv_sec = 59;
>>>           gmtm->tv_nsec = 999999999;
>>>        }
>>>
>>> before calling __strftime_l. (Or again, if the idea is to depart from RFC 5424, document the departure.)
>> I think this is worth to support, I will add such test.
> In fact struct tm does not 'tv_nsec' so I am confused about your suggestion here.

Oh, you're right, my suggestion should have been just:

   gmtm->tv_sec -= gmtm->tv_sec == 60;

However, as I understand from your other email you plan to support leap 
seconds and out-of-range years (even though this departs from RFC 5424) 
so in that case please ignore my corrected suggestion; all that's needed 
is documentation for the departure.
  

Patch

diff --git a/misc/syslog.c b/misc/syslog.c
index 088e3b5664..f15a536dd7 100644
--- a/misc/syslog.c
+++ b/misc/syslog.c
@@ -31,6 +31,7 @@ 
 static char sccsid[] = "@(#)syslog.c	8.4 (Berkeley) 3/18/94";
 #endif /* LIBC_SCCS and not lint */
 
+#include <intprops.h>
 #include <libc-lock.h>
 #include <libio/libioP.h>
 #include <math_ldbl_opt.h>
@@ -42,6 +43,10 @@  static char sccsid[] = "@(#)syslog.c	8.4 (Berkeley) 3/18/94";
 #include <sys/un.h>
 #include <stdio_ext.h>
 
+#ifndef HOST_NAME_MAX
+# define HOST_NAME_MAX 64
+#endif
+
 static int LogType = SOCK_DGRAM;	/* type of socket connection */
 static int LogFile = -1;		/* fd for log */
 static bool connected;		/* have done connect */
@@ -117,6 +122,39 @@  __vsyslog_chk(int pri, int flag, const char *fmt, va_list ap)
   __vsyslog_internal (pri, fmt, ap, (flag > 0) ? PRINTF_FORTIFY : 0);
 }
 
+/* Defined by RFC5424.  */
+#define NILVALUE "-"
+
+struct timebuf
+{
+  /* Leave room for outlandish but possible years.
+     The "+ 1" is for strftime's adding 1900 to tm_year.  */
+  char b[INT_STRLEN_BOUND (int) + 1
+	 + sizeof "-MM-DDThh:mm:ss.nnnnnnZ"];
+};
+
+
+/* Fill TIMEBUF with a RFC3339 timestamp.  Use UTC time and maximum
+   TIME-SECFRAC accurancy allowed (6 digits for microseconds).  */
+static void
+syslog_rfc3339_timestamp (struct timebuf *timebuf)
+{
+  struct __timespec64 ts;
+  __clock_gettime64 (TIME_CLOCK_GETTIME_CLOCKID, &ts);
+  struct tm now_tm;
+  struct tm *gmtm = __gmtime64_r (&ts.tv_sec, &now_tm);
+  if (gmtm == NULL)
+    strcpy (timebuf->b, NILVALUE);
+  else
+    {
+      size_t datebytes = __strftime_l (timebuf->b, sizeof timebuf->b,
+				       "%FT%T", gmtm, _nl_C_locobj_ptr);
+      int usec = ts.tv_nsec / 1000;
+      __snprintf (timebuf->b + datebytes, sizeof timebuf->b - datebytes,
+		  ".%06dZ", usec);
+    }
+}
+
 void
 __vsyslog_internal(int pri, const char *fmt, va_list ap,
 		   unsigned int mode_flags)
@@ -149,35 +187,30 @@  __vsyslog_internal(int pri, const char *fmt, va_list ap,
   if ((pri & LOG_FACMASK) == 0)
     pri |= LogFacility;
 
-  pid_t pid = LogStat & LOG_PID ? __getpid () : 0;
+  struct timebuf timestamp;
+  syslog_rfc3339_timestamp (&timestamp);
 
-  enum
-    {
-      timebuf_size = 3+1                     /* "%h "  */
-                     + 2+1                   /* "%e "  */
-                     + 2+1 + 2+1 + 2+1 + 1,  /* "%T "  */
-
-      bufs_size    = 1024
-    };
+  char hostname[HOST_NAME_MAX];
+  if (__gethostname (hostname, sizeof (hostname)) == -1)
+    strcpy (hostname, NILVALUE);
 
-  /* "%h %e %H:%M:%S "  */
-  char timestamp[timebuf_size];
-  time_t now = time_now ();
-  struct tm now_tm;
-  __localtime_r (&now, &now_tm);
-  __strftime_l (timestamp, sizeof (timestamp), "%h %e %T ", &now_tm,
-                _nl_C_locobj_ptr);
+  pid_t pid = LogStat & LOG_PID ? __getpid () : 0;
 
-#define SYSLOG_HEADER(__pri, __timestamp, __msgoff, pid) \
-  "<%d>%s %n%s%s%.0d%s: ",                               \
-  __pri, __timestamp, __msgoff,                          \
-  LogTag == NULL ? __progname : LogTag,                  \
-  pid != 0 ? "[" : "", pid, pid != 0 ? "]" : ""
+#define SYSLOG_HEADER(__pri, __timestamp, __msgoff, __hostname, __pid) \
+  "<%d>1 %s %n%s %s %s%.0d %s %s ",                      \
+  __pri,                                /* PRI  */       \
+  __timestamp.b,                        /* TIMESTAMP  */ \
+  __msgoff, __hostname,                 /* HOSTNAME  */  \
+  LogTag == NULL ? __progname : LogTag, /* APP-NAME  */  \
+  NILVALUE + !!__pid, __pid,            /* PROCID  */    \
+  NILVALUE,                             /* MSGID  */     \
+  NILVALUE                              /* STRUCT-DATA */
 
   /* Try to use a static buffer as an optimization.  */
+  enum { bufs_size  = 1024 };
   char bufs[bufs_size];
   int l = __snprintf (bufs, sizeof bufs,
-                      SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
+                      SYSLOG_HEADER (pri, timestamp, &msgoff, hostname, pid));
   if (l < sizeof (bufs))
     {
       va_list apc;
@@ -205,7 +238,7 @@  __vsyslog_internal(int pri, const char *fmt, va_list ap,
       if (f != NULL)
         {
           __fsetlocking (f, FSETLOCKING_BYCALLER);
-          fprintf (f, SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
+          fprintf (f, SYSLOG_HEADER (pri, timestamp, &msgoff, hostname, pid));
           /* Restore errno for %m format.  */
           __set_errno (saved_errno);
           __vfprintf_internal (f, fmt, ap, mode_flags);
diff --git a/misc/tst-syslog.c b/misc/tst-syslog.c
index 8505178616..7b78b0c619 100644
--- a/misc/tst-syslog.c
+++ b/misc/tst-syslog.c
@@ -18,6 +18,7 @@ 
 
 #include <array_length.h>
 #include <fcntl.h>
+#include <intprops.h>
 #include <paths.h>
 #include <netinet/in.h>
 #include <support/capture_subprocess.h>
@@ -201,7 +202,7 @@  check_openlog_message (const struct msg_t *msg, int msgnum,
     {
       if (options & LOG_PID)
         TEST_COMPARE (msg->pid, pid);
-      TEST_COMPARE_STRING (msg->ident, expected_ident);
+      TEST_COMPARE_STRING (msg->ident, OPENLOG_IDENT);
       TEST_COMPARE (msg->facility, LOG_LOCAL0);
     }
   else if (msgnum < 2 * array_length (priorities))
@@ -212,28 +213,25 @@  check_openlog_message (const struct msg_t *msg, int msgnum,
   return true;
 }
 
+#define NILVALUE "-"
+
 static struct msg_t
 parse_syslog_msg (const char *msg)
 {
   struct msg_t r = { .pid = -1 };
   int number;
+  char procid[INT_BUFSIZE_BOUND (pid_t)];
 
   /* The message in the form:
      <179>Apr  8 14:51:19 tst-syslog: syslog message 176 3  */
-  int n = sscanf (msg, "<%3d>%*s %*d %*d:%*d:%*d %32s %64s %*d %*d",
-                  &number, r.ident, r.msg);
-  TEST_COMPARE (n, 3);
+  int n = sscanf (msg, "<%6d>1 %*s %*s %32s %s - - %s",
+                  &number, r.ident, procid, r.msg);
+  TEST_COMPARE (n, 4);
 
   r.facility = number & LOG_FACMASK;
   r.priority = number & LOG_PRIMASK;
 
-  char *pid_start = strchr (r.ident, '[');
-  if (pid_start != NULL)
-    {
-       char *pid_end = strchr (r.ident, ']');
-       if (pid_end != NULL)
-         r.pid = strtoul (pid_start + 1, NULL, 10);
-    }
+  r.pid = strcmp (procid, NILVALUE) == 0 ? 0 : strtoul (procid, NULL, 10);
 
   return r;
 }
@@ -246,9 +244,9 @@  parse_syslog_console (const char *msg)
   struct msg_t r;
 
   /* The message in the form:
-     openlog_ident: syslog_message 128 0  */
-  int n = sscanf (msg, "%32s %64s %d %d",
-      r.ident, r.msg, &facility, &priority);
+     mymachine openlog_ident PID - syslog_message 128 0  */
+  int n = sscanf (msg, "%*s %32s %*s - - %s %d %d",
+		  r.ident, r.msg, &facility, &priority);
   TEST_COMPARE (n, 4);
 
   r.facility = facility;
@@ -384,7 +382,7 @@  check_syslog_console_read (FILE *fp)
   while (fgets (buf, sizeof (buf), fp) != NULL)
     {
       struct msg_t msg = parse_syslog_console (buf);
-      TEST_COMPARE_STRING (msg.ident, OPENLOG_IDENT ":");
+      TEST_COMPARE_STRING (msg.ident, OPENLOG_IDENT);
       TEST_COMPARE (msg.priority, priorities[msgnum]);
       TEST_COMPARE (msg.facility, LOG_LOCAL0);