From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-oo1-xc2d.google.com (mail-oo1-xc2d.google.com [IPv6:2607:f8b0:4864:20::c2d]) by sourceware.org (Postfix) with ESMTPS id 17AC9385E020 for ; Fri, 18 Feb 2022 14:23:38 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 17AC9385E020 Received: by mail-oo1-xc2d.google.com with SMTP id 189-20020a4a03c6000000b003179d7b30d8so3682861ooi.2 for ; Fri, 18 Feb 2022 06:23:38 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:from:to:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=EH5NyPiN4m9akW3nj+26qdQazOTL/9t+XhoQcZ+9j+Y=; b=4CRkt4Igi8h1hiGYMbsn91J5Rg4F8cVKpzZsUGTAJpRIl9csCXOw+gQgkXAKFKTd2s aDfJ2HZhGC1Nfz9fzp5mu3pEV0JmX0n9yI3zvirpOnQvH+N3i54iIGvGrydcUuoP4/N5 OTU81jDflUIRTGP3odJ/P7Ub7hueLmxz8KlmbTGo2+0U3HCO0xQhVkNk7ch0d+GUEIie QvY/0FsNPfFzInBXWq6ZKM1upVobiCixjq/PZBwDE0Um4O13etNxZpcUUj4LZzxA8izz 61uGBgtAizXGGwDHI8okAsVmU2+8t5e1Aq5T5QiiFdqeiZcuJro2i46BAHvhrkHpDy5+ ruyA== X-Gm-Message-State: AOAM533YsqLOocQI7BmtgoPSRMBV+pJwf85Gi4o6ojkGQU9ua48BPcJS difxKvlns6zDgN6WR4w/g3wxqZDHY0smrQ== X-Google-Smtp-Source: ABdhPJyyc9SqEY4fOaJ1vR0eqFgW70Fv7kljPApD/rl8eBG4StOwbF6A4zAsUk2PFaPJzwf+WE0nAQ== X-Received: by 2002:a05:6870:d3cc:b0:c4:7dc0:d72f with SMTP id l12-20020a056870d3cc00b000c47dc0d72fmr3129809oag.258.1645194217014; Fri, 18 Feb 2022 06:23:37 -0800 (PST) Received: from birita.. ([2804:431:c7cb:6747:90e1:2029:f1e0:f47a]) by smtp.gmail.com with ESMTPSA id bp5sm702993oib.25.2022.02.18.06.23.35 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 18 Feb 2022 06:23:36 -0800 (PST) From: Adhemerval Zanella To: libc-alpha@sourceware.org Subject: [PATCH v2 7/7] misc: syslog: Use RFC5424 Date: Fri, 18 Feb 2022 11:23:22 -0300 Message-Id: <20220218142322.432304-8-adhemerval.zanella@linaro.org> X-Mailer: git-send-email 2.32.0 In-Reply-To: <20220218142322.432304-1-adhemerval.zanella@linaro.org> References: <20220218142322.432304-1-adhemerval.zanella@linaro.org> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Spam-Status: No, score=-12.5 required=5.0 tests=BAYES_00, DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, DKIM_VALID_EF, GIT_PATCH_0, KAM_NUMSUBJECT, RCVD_IN_DNSWL_NONE, SPF_HELO_NONE, SPF_PASS, TXREP, T_SCC_BODY_TEXT_LINE autolearn=ham autolearn_force=no version=3.4.4 X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on server2.sourceware.org X-BeenThere: libc-alpha@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Libc-alpha mailing list List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 18 Feb 2022 14:23:40 -0000 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(-) 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 #include #include #include @@ -42,6 +43,10 @@ static char sccsid[] = "@(#)syslog.c 8.4 (Berkeley) 3/18/94"; #include #include +#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 (×tamp); - 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 #include +#include #include #include #include @@ -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); -- 2.32.0