From patchwork Mon Apr 12 21:11:13 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Adhemerval Zanella X-Patchwork-Id: 42960 X-Patchwork-Delegate: carlos@redhat.com Return-Path: X-Original-To: patchwork@sourceware.org Delivered-To: patchwork@sourceware.org Received: from server2.sourceware.org (localhost [IPv6:::1]) by sourceware.org (Postfix) with ESMTP id 02A6C39DC4C6; Mon, 12 Apr 2021 21:11:33 +0000 (GMT) DKIM-Filter: OpenDKIM Filter v2.11.0 sourceware.org 02A6C39DC4C6 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=sourceware.org; s=default; t=1618261893; bh=GTyTdClYGgoYL4dUhJYcSn7zDsigjrLX+KxINQufVZM=; h=To:Subject:Date:In-Reply-To:References:List-Id:List-Unsubscribe: List-Archive:List-Post:List-Help:List-Subscribe:From:Reply-To: From; b=UnTWOJP63lCqRunHXqev6b8nQLFzTZfW0jvzYz+0sq7AtvwGmkbFY06Py1EZXrvJP aDW+Jih2y9J15rtP7B80CcsvdhgSDMVSM8NVGvo1p6BQ+z0BNgOF3XJILahxjPxyEY NkRhb5lEliNyexloszabKLe90mgyLdETOQJQUTWs= X-Original-To: libc-alpha@sourceware.org Delivered-To: libc-alpha@sourceware.org Received: from mail-qk1-x72f.google.com (mail-qk1-x72f.google.com [IPv6:2607:f8b0:4864:20::72f]) by sourceware.org (Postfix) with ESMTPS id D0BD6398207F for ; Mon, 12 Apr 2021 21:11:29 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.3.2 sourceware.org D0BD6398207F Received: by mail-qk1-x72f.google.com with SMTP id c4so15823360qkg.3 for ; Mon, 12 Apr 2021 14:11:29 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=GTyTdClYGgoYL4dUhJYcSn7zDsigjrLX+KxINQufVZM=; b=e3LMSRUwSoHMIQBsUHJAVqZYt/6MF5hJGqvhhrHw9FwYTTjS+EwZi1gpua9idvDTPL nShoJjSmXv+27kn4jlly7fLdzwvGdJ/iAU2SRKaltfD9MLCwrEVKsNJvwMS6uXMGISyd yR3fFYwgRqeOtYTbpiZXu/HLPhz3dGEl1SWWKJZK6unOonUXFIvkcDKGhVnDQBlYmOYZ haRCR89EPoEBJCmG9d+iltBCwAN1FpHBp4+cveSdyB2FgyBHXwbsbXzl/4cGffxDWUEQ uCLjEMVbUE8legJZDJmSbI9CSo/ziNiW38WamtLUjfJ+i5L2/N841Ruyw6fsK/smrTg8 xd7w== X-Gm-Message-State: AOAM531WMDNQyy4XftfCYSpOH5Ox2DcqDGoG1INPRCanMqZilONL0Bv1 5vkF1Fl7lu7tjJCSOfLbKBk9Aj4Z3ROk6Oc/ X-Google-Smtp-Source: ABdhPJzCM3gKP0q6wJTdqGfKccH69TdjmTntRdZfwv0fzRVFXOpJY0bVqKst3eKn+jFvLZNWY7ZPsw== X-Received: by 2002:a37:7985:: with SMTP id u127mr29080031qkc.333.1618261889161; Mon, 12 Apr 2021 14:11:29 -0700 (PDT) Received: from localhost.localdomain ([177.194.41.149]) by smtp.googlemail.com with ESMTPSA id i22sm3073392qko.135.2021.04.12.14.11.28 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 12 Apr 2021 14:11:28 -0700 (PDT) To: libc-alpha@sourceware.org Subject: [PATCH 11/11] misc: syslog: Use RFC5424 Date: Mon, 12 Apr 2021 18:11:13 -0300 Message-Id: <20210412211113.393120-11-adhemerval.zanella@linaro.org> X-Mailer: git-send-email 2.27.0 In-Reply-To: <20210412211113.393120-1-adhemerval.zanella@linaro.org> References: <20210412211113.393120-1-adhemerval.zanella@linaro.org> MIME-Version: 1.0 X-Spam-Status: No, score=-12.3 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 autolearn=ham autolearn_force=no version=3.4.2 X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) 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-Patchwork-Original-From: Adhemerval Zanella via Libc-alpha From: Adhemerval Zanella Reply-To: Adhemerval Zanella Errors-To: libc-alpha-bounces@sourceware.org Sender: "Libc-alpha" 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 --- include/time.h | 8 ++++++ misc/syslog.c | 69 +++++++++++++++++++++++++++++++---------------- misc/tst-syslog.c | 30 ++++++++++----------- 3 files changed, 68 insertions(+), 39 deletions(-) diff --git a/include/time.h b/include/time.h index caf2af5e74..3defec6c20 100644 --- a/include/time.h +++ b/include/time.h @@ -502,6 +502,14 @@ time_now (void) __clock_gettime (TIME_CLOCK_GETTIME_CLOCKID, &ts); return ts.tv_sec; } + +static inline struct __timespec64 +timespec64_now (void) +{ + struct __timespec64 ts64; + __clock_gettime64 (TIME_CLOCK_GETTIME_CLOCKID, &ts64); + return ts64; +} #endif #endif diff --git a/misc/syslog.c b/misc/syslog.c index be12bcc91d..36cdf037f8 100644 --- a/misc/syslog.c +++ b/misc/syslog.c @@ -38,6 +38,10 @@ #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 */ @@ -111,6 +115,30 @@ __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_t +{ + char b[sizeof ("YYYY-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_t *timebuf) +{ + struct __timespec64 ts = timespec64_now (); + struct tm now_tm; + __gmtime64_r (&ts.tv_sec, &now_tm); + + __snprintf (timebuf->b, sizeof (timebuf->b), + "%04d-%02d-%02dT%02d:%02d:%02d.%06dZ", + now_tm.tm_year + 1900, now_tm.tm_mon + 1, now_tm.tm_mday, + now_tm.tm_hour, now_tm.tm_min, now_tm.tm_sec, + (int32_t) ts.tv_nsec / 1000); +} + void __vsyslog_internal (int pri, const char *fmt, va_list ap, unsigned int mode_flags) @@ -143,35 +171,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; - - enum - { - timebuf_size = 3+1 /* "%h " */ - + 2+1 /* "%e " */ - + 2+1 + 2+1 + 2+1 + 1, /* "%T " */ + struct timebuf_t timestamp; + syslog_rfc3339_timestamp (×tamp); - 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; @@ -198,7 +221,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 ed8c528db4..5b24927afe 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)) @@ -218,28 +219,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); + <34>1 2003-10-11T22:14:15.003Z mymachine openlog_ident PID - MSG */ + 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; } @@ -252,8 +250,8 @@ 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", + 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); @@ -390,7 +388,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);