From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id 5C4E25A004E for ; Tue, 06 Aug 2024 08:18:50 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202312; t=1722925121; bh=OraUn+DmaotCwRZHq4n2gEiv/WUQB7jC631xf4a23iA=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=nAve9vsJRrek0ruHOHq3JswhtQBfkl+H7u9zHjViLkCoAYAfJ/Vmq+PkGRT3VoZfD ETwxCEjHAirKEgPLcg9TBcyYjsajlO2yj7RRcqH6F91PwsJWOhuHiHhu85JuhB2LSn qajn+AfjFskx/c0hoKez+2jaYh1DxVGQ1HO96w8jQUm0RMdwv21goqP/gp/xUkLW4j 6ZGXA8FAChq126uTOlVH/DLCm3hy9WyByhXB8Sqtb4jkDqjM6yVHV1cOo/9rxZcvfZ iya2C/cmaI+/vD39X6tZUcx8xMOEOUlK2jjAr3nigWlNekbfNtbn4GPl4HfMLBknR/ 6fQgpipQhNtIQ== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4WdNRP1qTcz4x0t; Tue, 6 Aug 2024 16:18:41 +1000 (AEST) From: David Gibson To: passt-dev@passt.top, Stefano Brivio Subject: [PATCH v2 2/4] log: Correct formatting of timestamps Date: Tue, 6 Aug 2024 16:18:37 +1000 Message-ID: <20240806061839.1950144-3-david@gibson.dropbear.id.au> X-Mailer: git-send-email 2.45.2 In-Reply-To: <20240806061839.1950144-1-david@gibson.dropbear.id.au> References: <20240806061839.1950144-1-david@gibson.dropbear.id.au> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Message-ID-Hash: 7MIOWL2NOC5BBDUB3SOROK7H37JBH3CU X-Message-ID-Hash: 7MIOWL2NOC5BBDUB3SOROK7H37JBH3CU X-MailFrom: dgibson@gandalf.ozlabs.org X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: David Gibson X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point. Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display. Signed-off-by: David Gibson --- log.c | 36 ++++++++++++++++++++++++------------ 1 file changed, 24 insertions(+), 12 deletions(-) diff --git a/log.c b/log.c index eb3a780a..e60852f7 100644 --- a/log.c +++ b/log.c @@ -46,14 +46,24 @@ int log_trace; /* --trace mode enabled */ bool log_conf_parsed; /* Logging options already parsed */ bool log_runtime; /* Daemonised, or ready in foreground */ +#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) + /** - * logtime_fmt_and_arg() - Build format and arguments to print relative log time - * @x: Current timestamp + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format + * + * Return: number of characters written to @buf (excluding \0) */ -#define logtime_fmt_and_arg(x) \ - "%lli.%04lli", \ - (timespec_diff_us((x), &log_start) / 1000000LL), \ - (timespec_diff_us((x), &log_start) / 100LL) +int logtime_fmt(char *buf, size_t size, const struct timespec *ts) +{ + int64_t delta = timespec_diff_us(ts, &log_start); + + return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, + (delta / 100LL) % 10000); +} /* Prefixes for log file messages, indexed by priority */ const char *logfile_prefix[] = { @@ -85,7 +95,7 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now) return; n = snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header); - n += snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now)); + n += logtime_fmt(buf + n, BUFSIZ - n, now); /* Avoid partial lines by padding the header with spaces */ nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1); @@ -117,8 +127,7 @@ static void logfile_rotate_move(int fd, const struct timespec *now) header_len = snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header); - header_len += snprintf(buf + header_len, BUFSIZ - header_len, - logtime_fmt_and_arg(now)); + header_len += logtime_fmt(buf + header_len, BUFSIZ - header_len, now); if (lseek(fd, 0, SEEK_SET) == -1) return; @@ -211,7 +220,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) if (clock_gettime(CLOCK_MONOTONIC, &now)) return; - n = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now)); + n = logtime_fmt(buf, BUFSIZ, &now); n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); n += vsnprintf(buf + n, BUFSIZ - n, format, ap); @@ -239,9 +248,12 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) struct timespec tp; if (debug_print) { + char logtime[LOGTIME_STRLEN]; + clock_gettime(CLOCK_MONOTONIC, &tp); - fprintf(stderr, logtime_fmt_and_arg(&tp)); - fprintf(stderr, ": "); + + logtime_fmt(logtime, sizeof(logtime), &tp); + fprintf(stderr, "%s: ", logtime); } if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { -- 2.45.2