log: Handle errors from clock_gettime()

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 "<error>" in place of a
timestamp if something goes wrong with clock_gettime().

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
This commit is contained in:
David Gibson 2024-08-06 16:18:38 +10:00 committed by Stefano Brivio
parent b91bae1ded
commit 2c7558dc43

47
log.c
View file

@ -49,20 +49,37 @@ bool log_stderr = true; /* Not daemonised, no shell spawned */
#define LL_STRLEN (sizeof("-9223372036854775808")) #define LL_STRLEN (sizeof("-9223372036854775808"))
#define LOGTIME_STRLEN (LL_STRLEN + 5) #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 * logtime_fmt() - Format timestamp into a string for the log
* @buf: Buffer into which to format the time * @buf: Buffer into which to format the time
* @size: Size of @buf * @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) * Return: number of characters written to @buf (excluding \0)
*/ */
static int logtime_fmt(char *buf, size_t size, const struct timespec *ts) static 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, return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL,
(delta / 100LL) % 10000); (delta / 100LL) % 10000);
}
return snprintf(buf, size, "<error>");
} }
/* Prefixes for log file messages, indexed by priority */ /* 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) 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]; char buf[BUFSIZ];
int n; int n;
if (clock_gettime(CLOCK_MONOTONIC, &now)) now = logtime(&ts);
return;
n = logtime_fmt(buf, BUFSIZ, &now); n = logtime_fmt(buf, BUFSIZ, now);
n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
n += vsnprintf(buf + n, BUFSIZ - n, format, ap); 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') if (newline && format[strlen(format)] != '\n')
n += snprintf(buf + n, BUFSIZ - n, "\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; return;
if ((n = write(log_file, buf, n)) >= 0) 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) void vlogmsg(bool newline, int pri, const char *format, va_list ap)
{ {
bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;
struct timespec tp;
if (debug_print) { if (debug_print) {
char logtime[LOGTIME_STRLEN]; char timestr[LOGTIME_STRLEN];
const struct timespec *now;
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &tp); now = logtime(&ts);
logtime_fmt(timestr, sizeof(timestr), now);
logtime_fmt(logtime, sizeof(logtime), &tp); fprintf(stderr, "%s: ", timestr);
fprintf(stderr, "%s: ", logtime);
} }
if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) {