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 A877E5A0319 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=Bs/X2GmngUfeWGien+SBpfCnQZgItFkTirFYJ79JqcY=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=euZXD7zG+2oIiyAcWfI2IrA5fYVvwEyw1c4QED9sIa3zhlTuBqcIcW1QZyCotVvaj Dvm+E+405BCZ748hkgDA87lwEWqSIlZ/GeDaBzfLHUwrUtbKoJeVbs/Kn8vff6hCUh bdPJldyxs/NIo8FwddbwA6U5KWdMLyP2Fv/kEv44Koj6xZ+a0u5Ertou8Zy37nwkE1 ujKtRBC2Afq6ATg2elVuzS+I0gLFOieFQBKqWOIF02AdQn/hOjzGyH8XnAtyz/db/p hSMZrzWEDO1wohvtRcpR9tYZ5PPrZPvRTbNXToUmCmuX0+poVf4huywqGgTS3Wnpgq aF0ij+jjldUiw== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4WdNRP222dz4x3J; Tue, 6 Aug 2024 16:18:41 +1000 (AEST) From: David Gibson To: passt-dev@passt.top, Stefano Brivio Subject: [PATCH v2 3/4] log: Handle errors from clock_gettime() Date: Tue, 6 Aug 2024 16:18:38 +1000 Message-ID: <20240806061839.1950144-4-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: D4UKKW6IOYFCG35TRXCLRYCJNFRU3K6O X-Message-ID-Hash: D4UKKW6IOYFCG35TRXCLRYCJNFRU3K6O 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: clock_gettime() can, theoretically, fail, although it probably won't until 2038 on old 32-bit systems. Still, it's possible someone could run with a wildly out of sync clock, or new errors could be added, or it could fail due to a bug in libc or the kernel. We don't handle this well. In the debug_print case in vlogmsg we'll just ignore the failure, and print a timestamp based on uninitialised garbage. In logfile_write() we exit early and won't log anything at all, which seems like a good way to make an already weird situation undebuggable. Add some helpers to instead handle this by using "" in place of a timestamp if something goes wrong with clock_gettime(). Signed-off-by: David Gibson --- log.c | 47 ++++++++++++++++++++++++++++++++--------------- 1 file changed, 32 insertions(+), 15 deletions(-) diff --git a/log.c b/log.c index e60852f7..9f4cb7fc 100644 --- a/log.c +++ b/log.c @@ -49,20 +49,37 @@ bool log_runtime; /* Daemonised, or ready in foreground */ #define LL_STRLEN (sizeof("-9223372036854775808")) #define LOGTIME_STRLEN (LL_STRLEN + 5) +/** + * logtime() - Get the current time for logging purposes + * @ts: Buffer into which to store the timestamp + * + * Return: pointer to @now, or NULL if there was an error retrieving the time + */ +const struct timespec *logtime(struct timespec *ts) +{ + if (clock_gettime(CLOCK_MONOTONIC, ts)) + return NULL; + return ts; +} + /** * 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 + * @ts: Time to format (or NULL on error) * * Return: number of characters written to @buf (excluding \0) */ int logtime_fmt(char *buf, size_t size, const struct timespec *ts) { - int64_t delta = timespec_diff_us(ts, &log_start); + if (ts) { + int64_t delta = timespec_diff_us(ts, &log_start); + + return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, + (delta / 100LL) % 10000); + } - return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, - (delta / 100LL) % 10000); + return snprintf(buf, size, ""); } /* Prefixes for log file messages, indexed by priority */ @@ -213,14 +230,14 @@ static int logfile_rotate(int fd, const struct timespec *now) */ static void logfile_write(bool newline, int pri, const char *format, va_list ap) { - struct timespec now; + const struct timespec *now; + struct timespec ts; char buf[BUFSIZ]; int n; - if (clock_gettime(CLOCK_MONOTONIC, &now)) - return; + now = logtime(&ts); - n = logtime_fmt(buf, BUFSIZ, &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); @@ -228,7 +245,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) if (newline && format[strlen(format)] != '\n') n += snprintf(buf + n, BUFSIZ - n, "\n"); - if ((log_written + n >= log_size) && logfile_rotate(log_file, &now)) + if ((log_written + n >= log_size) && logfile_rotate(log_file, now)) return; if ((n = write(log_file, buf, n)) >= 0) @@ -245,15 +262,15 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) void vlogmsg(bool newline, int pri, const char *format, va_list ap) { bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; - struct timespec tp; if (debug_print) { - char logtime[LOGTIME_STRLEN]; - - clock_gettime(CLOCK_MONOTONIC, &tp); + char timestr[LOGTIME_STRLEN]; + const struct timespec *now; + struct timespec ts; - logtime_fmt(logtime, sizeof(logtime), &tp); - fprintf(stderr, "%s: ", logtime); + now = logtime(&ts); + logtime_fmt(timestr, sizeof(timestr), now); + fprintf(stderr, "%s: ", timestr); } if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { -- 2.45.2