From 630f3eecbecab4c5d46c84fe48c112b503effb5a Mon Sep 17 00:00:00 2001 From: "Richard W.M. Jones" Date: Thu, 29 Jan 2026 10:24:58 +0000 Subject: [PATCH] Add new nbdkit_timestamp() function This function can be used to flexibly add timestamps to debug and error messages (or any kind of logging). (cherry picked from commit 773d958c8f2a5043053d385b8bfe287c43ee63d4) --- .gitignore | 1 + docs/Makefile.am | 7 +++ docs/nbdkit_debug.pod | 4 ++ docs/nbdkit_error.pod | 6 +++ docs/nbdkit_timestamp.pod | 75 ++++++++++++++++++++++++++++++++ include/nbdkit-common.h | 1 + server/internal.h | 1 + server/nbdkit.syms | 1 + server/public.c | 55 +++++++++++++++++++++++- server/test-public.c | 6 +++ server/threadlocal.c | 20 +++++++++ tests/Makefile.am | 25 +++++++++++ tests/test-timestamp-plugin.c | 81 +++++++++++++++++++++++++++++++++++ tests/test-timestamp.sh | 61 ++++++++++++++++++++++++++ 14 files changed, 343 insertions(+), 1 deletion(-) create mode 100644 docs/nbdkit_timestamp.pod create mode 100644 tests/test-timestamp-plugin.c create mode 100755 tests/test-timestamp.sh diff --git a/.gitignore b/.gitignore index 55d971e6..2b86a056 100644 --- a/.gitignore +++ b/.gitignore @@ -48,6 +48,7 @@ docs/nbdkit_realpath.3 docs/nbdkit_shutdown.3 docs/nbdkit_stdio_safe.3 docs/nbdkit_strdup_intern.3 +docs/nbdkit_timestamp.3 docs/nbdkit-tracing.3 filters/*/*.1 plugins/*/*.1 diff --git a/docs/Makefile.am b/docs/Makefile.am index a43b13ed..742f5460 100644 --- a/docs/Makefile.am +++ b/docs/Makefile.am @@ -85,6 +85,7 @@ EXTRA_DIST = \ nbdkit_shutdown.pod \ nbdkit_stdio_safe.pod \ nbdkit_strdup_intern.pod \ + nbdkit_timestamp.pod \ nbdkit-tls.pod \ nbdkit-tracing.pod \ synopsis.txt \ @@ -176,6 +177,7 @@ generated_mans = \ nbdkit_shutdown.3 \ nbdkit_stdio_safe.3 \ nbdkit_strdup_intern.3 \ + nbdkit_timestamp.3 \ nbdkit-tls.1 \ nbdkit-tracing.3 \ $(NULL) @@ -348,6 +350,11 @@ nbdkit_strdup_intern.3: nbdkit_strdup_intern.pod $(top_builddir)/podwrapper.pl --html $(top_builddir)/html/$@.html \ $< +nbdkit_timestamp.3: nbdkit_timestamp.pod $(top_builddir)/podwrapper.pl + $(PODWRAPPER) --section=3 --man $@ \ + --html $(top_builddir)/html/$@.html \ + $< + nbdkit-tls.1: nbdkit-tls.pod $(top_builddir)/podwrapper.pl $(PODWRAPPER) --section=1 --man $@ \ --html $(top_builddir)/html/$@.html \ diff --git a/docs/nbdkit_debug.pod b/docs/nbdkit_debug.pod index d58d9bda..ee1ba719 100644 --- a/docs/nbdkit_debug.pod +++ b/docs/nbdkit_debug.pod @@ -25,6 +25,9 @@ and also support the glibc extension of a single C<%m> in a format string expanding to C, even on platforms that don't support that natively. +C does not timestamp messages. To add timestamps, see +L. + =head1 LANGUAGE BINDINGS In L: @@ -60,6 +63,7 @@ L, L, L, L, +L, L, L. diff --git a/docs/nbdkit_error.pod b/docs/nbdkit_error.pod index 2b41a4f0..d9283baa 100644 --- a/docs/nbdkit_error.pod +++ b/docs/nbdkit_error.pod @@ -61,6 +61,11 @@ The default is to send error messages to stderr, unless nbdkit forks into the background in which case they are sent to syslog. For more information read the description in L. +=head2 Timestamps + +C does not timestamp messages. To add timestamps, see +L. + =head1 LANGUAGE BINDINGS Most language bindings do not expose these functions explicitly. @@ -78,6 +83,7 @@ C was added in nbdkit 1.2. L, L, +L, L, L. diff --git a/docs/nbdkit_timestamp.pod b/docs/nbdkit_timestamp.pod new file mode 100644 index 00000000..2662b204 --- /dev/null +++ b/docs/nbdkit_timestamp.pod @@ -0,0 +1,75 @@ +=head1 NAME + +nbdkit_timestamp - generate a timestamp for log messages + +=head1 SYNOPSIS + + #include + + const char *nbdkit_timestamp (void); + +=head1 DESCRIPTION + +C generates a timestamp as a printable string which +may be added to debug or error messages (see L, +L). + +It can be used like this: + + nbdkit_debug ("%s: this is a debug message", nbdkit_timestamp ()); + +which would produce a debug message like this: + + debug: 2026-01-01 12:00:00.000333: this is a debug message + +The timestamps show the wallclock time in approximately ISO 8601 +format, but less ugly. They are always shown in UTC, in 24 hour +notation, to the nearest microsecond. (On Windows, timestamps use the +same format but are rounded to the nearest millisecond.) + +You can also separate the nbdkit_timestamp() call from the place where +it is used, allowing you to accurately timestamp, for example, the +point when a system call was invoked: + + const char *ts = nbdkit_timestamp (); + int r = pwrite (fd, ...); + if (r == -1) { + /* The error message shows the time that pwrite started. */ + nbdkit_error ("%s: pwrite: %m", ts); + return -1; + } + +=head1 RETURN VALUE + +The function returns a constant string allocated in thread-local +storage. The string is valid until the next call to +C in the same thread. + +It never returns C. In the (very unlikely) case that there was +an error generating the timestamp, the string C<"!"> is returned. + +=begin comment + +=head1 LANGUAGE BINDINGS + +=end comment + +=head1 HISTORY + +C was added in nbdkit 1.48. + +=head1 SEE ALSO + +L, +L, +L, +L, +L. + +=head1 AUTHORS + +Richard W.M. Jones + +=head1 COPYRIGHT + +Copyright Red Hat diff --git a/include/nbdkit-common.h b/include/nbdkit-common.h index 4b42c9d7..230365db 100644 --- a/include/nbdkit-common.h +++ b/include/nbdkit-common.h @@ -205,6 +205,7 @@ NBDKIT_EXTERN_DECL (char *, nbdkit_peer_tls_issuer_dn, NBDKIT_EXTERN_DECL (void, nbdkit_shutdown, (void)); NBDKIT_EXTERN_DECL (void, nbdkit_disconnect, (int force)); NBDKIT_EXTERN_DECL (const char *, nbdkit_name, (void)); +NBDKIT_EXTERN_DECL (const char *, nbdkit_timestamp, (void)); NBDKIT_EXTERN_DECL (const char *, nbdkit_strdup_intern, (const char *str) diff --git a/server/internal.h b/server/internal.h index f10de3ef..511ec536 100644 --- a/server/internal.h +++ b/server/internal.h @@ -633,6 +633,7 @@ extern int threadlocal_get_errno (void); extern void threadlocal_set_last_error (char *msg); extern void threadlocal_clear_last_error (void); extern const char *threadlocal_get_last_error (void); +extern int threadlocal_set_timestamp (char *timestamp); extern void *threadlocal_buffer (size_t size); extern void threadlocal_set_conn (struct connection *conn); extern struct connection *threadlocal_get_conn (void); diff --git a/server/nbdkit.syms b/server/nbdkit.syms index bf6bb378..fb732e9e 100644 --- a/server/nbdkit.syms +++ b/server/nbdkit.syms @@ -93,6 +93,7 @@ nbdkit_stdio_safe; nbdkit_strdup_intern; nbdkit_strndup_intern; + nbdkit_timestamp; nbdkit_use_default_export; nbdkit_vdebug; nbdkit_verror; diff --git a/server/public.c b/server/public.c index d08930dd..8d0b69d3 100644 --- a/server/public.c +++ b/server/public.c @@ -47,9 +47,11 @@ #include #include #include -#include #include +#include +#include + #ifdef HAVE_TERMIOS_H #include #endif @@ -1226,3 +1228,54 @@ nbdkit_name (void) { return process_name; } + +NBDKIT_DLL_PUBLIC const char * +nbdkit_timestamp (void) +{ + char *timestamp = NULL; + const size_t len = 64; + + timestamp = malloc (len); + if (timestamp == NULL) + goto err; + +#ifndef WIN32 + struct timeval tv; + struct tm tm; + size_t n; + + if (gettimeofday (&tv, NULL) == -1) + goto err; + gmtime_r (&tv.tv_sec, &tm); + + n = strftime (timestamp, len, "%F %T", &tm); + if (n == 0) + goto err; + snprintf (timestamp + n, len - n, ".%06" PRIu64, (uint64_t) tv.tv_usec); +#else /* WIN32 */ + /* Windows doesn't have thread-safe gmtime, or the strftime %F and + * %T formatters. Let's try to do this in a Windows native way. + * Windows SYSTEMTIME only returns milliseconds. + */ + SYSTEMTIME st; + GetSystemTime (&st); + snprintf (timestamp, len, "%04d-%02d-%02d %02d:%02d:%02d.%03d000", + st.wYear, st.wMonth, st.wDay, + st.wHour, st.wMinute, st.wSecond, + st.wMilliseconds); +#endif /* WIN32 */ + + /* Store the timestamp in thread-local storage. This passes + * ownership to threadlocal which will free it either on the next + * call or if the thread exits. This can fail (although it would be + * extremely unusual), and in that case we have to return something. + */ + if (threadlocal_set_timestamp (timestamp) == -1) + goto err; + + return timestamp; + + err: + free (timestamp); + return "!"; +} diff --git a/server/test-public.c b/server/test-public.c index 3ef530ff..0edd3f49 100644 --- a/server/test-public.c +++ b/server/test-public.c @@ -92,6 +92,12 @@ threadlocal_get_context (void) abort (); } +int +threadlocal_set_timestamp (char *timestamp) +{ + abort (); +} + conn_status connection_get_status (void) { diff --git a/server/threadlocal.c b/server/threadlocal.c index 74a3c4e5..108b9793 100644 --- a/server/threadlocal.c +++ b/server/threadlocal.c @@ -57,6 +57,7 @@ struct threadlocal { size_t instance_num; /* Can be 0. */ int err; char *last_error; /* Can be NULL. */ + char *timestamp; /* Can be NULL. */ void *buffer; /* Can be NULL. */ size_t buffer_size; struct connection *conn; /* Can be NULL. */ @@ -72,6 +73,7 @@ free_threadlocal (void *threadlocalv) free (threadlocal->name); free (threadlocal->last_error); + free (threadlocal->timestamp); free (threadlocal->buffer); free (threadlocal); } @@ -216,6 +218,24 @@ threadlocal_get_last_error (void) return threadlocal ? threadlocal->last_error : NULL; } +/* Set the timestamp. Ownership is passed to TLS. This is used by + * nbdkit_timestamp(). Calling this frees any existing timestamp in + * the thread. + */ +int +threadlocal_set_timestamp (char *timestamp) +{ + struct threadlocal *threadlocal = pthread_getspecific (threadlocal_key); + + if (threadlocal) { + free (threadlocal->timestamp); + threadlocal->timestamp = timestamp; + return 0; + } + else + return -1; +} + /* Return the single pread/pwrite buffer for this thread. The buffer * size is increased to ‘size’ bytes if required. * diff --git a/tests/Makefile.am b/tests/Makefile.am index f0665926..8b7cb851 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -273,6 +273,7 @@ TESTS += \ test-name.sh \ test-no-name.sh \ test-name-plugin.sh \ + test-timestamp.sh \ test-dump-plugin-example1.sh \ test-dump-plugin.sh \ test-dump-plugin-example2.sh \ @@ -413,6 +414,7 @@ EXTRA_DIST += \ test-timeout.sh \ test-timeout.py \ test-timeout-cancel.sh \ + test-timestamp.sh \ test-tls-priority.sh \ test-tls-psk.sh \ test-tls.sh \ @@ -603,6 +605,29 @@ test_name_plugin_la_LDFLAGS = \ $(NULL) test_name_plugin_la_LIBADD = $(IMPORT_LIBRARY_ON_WINDOWS) +# check_LTLIBRARIES won't build a shared library (see automake manual). +# So we have to do this and add a dependency. +noinst_LTLIBRARIES += \ + test-timestamp-plugin.la \ + $(NULL) +test-timestamp.sh: test-timestamp-plugin.la + +test_timestamp_plugin_la_SOURCES = \ + test-timestamp-plugin.c \ + $(top_srcdir)/include/nbdkit-plugin.h \ + $(NULL) +test_timestamp_plugin_la_CPPFLAGS = \ + -I$(top_srcdir)/include \ + -I$(top_builddir)/include \ + $(NULL) +test_timestamp_plugin_la_CFLAGS = $(WARNINGS_CFLAGS) +# For use of the -rpath option, see: +# https://lists.gnu.org/archive/html/libtool/2007-07/msg00067.html +test_timestamp_plugin_la_LDFLAGS = \ + -module -avoid-version -shared $(NO_UNDEFINED_ON_WINDOWS) -rpath /nowhere \ + $(NULL) +test_timestamp_plugin_la_LIBADD = $(IMPORT_LIBRARY_ON_WINDOWS) + endif HAVE_PLUGINS # Test the header files can be included on their own. diff --git a/tests/test-timestamp-plugin.c b/tests/test-timestamp-plugin.c new file mode 100644 index 00000000..f7efe270 --- /dev/null +++ b/tests/test-timestamp-plugin.c @@ -0,0 +1,81 @@ +/* nbdkit + * Copyright Red Hat + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are + * met: + * + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * + * * Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * + * * Neither the name of Red Hat nor the names of its contributors may be + * used to endorse or promote products derived from this software without + * specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS IS'' AND + * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, + * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A + * PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR + * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, + * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT + * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF + * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND + * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, + * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT + * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF + * SUCH DAMAGE. + */ + +/* This plugin tests nbdkit_timestamp(). + * + * The corresponding test is 'test-timestamp.sh'. + */ + +#include + +#include +#include +#include + +#define NBDKIT_API_VERSION 2 +#include + +static void * +timestamp_open (int readonly) +{ + nbdkit_debug ("%s: timestamped open", nbdkit_timestamp ()); + return NBDKIT_HANDLE_NOT_NEEDED; +} + +static int64_t +timestamp_get_size (void *handle) +{ + return 1024*1024*1024; +} + +#define THREAD_MODEL NBDKIT_THREAD_MODEL_PARALLEL + +static int +timestamp_pread (void *handle, void *buf, uint32_t count, uint64_t offset, + uint32_t flags) +{ + const char *ts = nbdkit_timestamp (); + memset (buf, 0, count); + nbdkit_debug ("%s: timestamped memset", ts); + + return 0; +} + +static struct nbdkit_plugin plugin = { + .name = "timestamp", + .version = PACKAGE_VERSION, + .open = timestamp_open, + .get_size = timestamp_get_size, + .pread = timestamp_pread, +}; + +NBDKIT_REGISTER_PLUGIN (plugin) diff --git a/tests/test-timestamp.sh b/tests/test-timestamp.sh new file mode 100755 index 00000000..5479fd37 --- /dev/null +++ b/tests/test-timestamp.sh @@ -0,0 +1,61 @@ +#!/usr/bin/env bash +# nbdkit +# Copyright Red Hat +# +# Redistribution and use in source and binary forms, with or without +# modification, are permitted provided that the following conditions are +# met: +# +# * Redistributions of source code must retain the above copyright +# notice, this list of conditions and the following disclaimer. +# +# * Redistributions in binary form must reproduce the above copyright +# notice, this list of conditions and the following disclaimer in the +# documentation and/or other materials provided with the distribution. +# +# * Neither the name of Red Hat nor the names of its contributors may be +# used to endorse or promote products derived from this software without +# specific prior written permission. +# +# THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS IS'' AND +# ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, +# THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A +# PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR +# CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF +# USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND +# ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, +# OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT +# OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF +# SUCH DAMAGE. + +# Test the nbdkit_timestamp() API. + +source ./functions.sh +set -e +set -x +set -u + +requires_run +requires_nbdcopy + +plugin=.libs/test-timestamp-plugin.$SOEXT +requires test -f $plugin + +out=timestamp.out +cleanup_fn rm -f "$out" +rm -f "$out" + +# Print the current date for comparison when checking the log. +date + +# The plugin is large (but empty). Run nbdcopy which will invoke +# the .pread method in the plugin in parallel. +nbdkit -fv "$plugin" --run 'nbdcopy "$uri" null:' 2> $out +cat $out + +# We are mainly interested that (a) the plugin nor nbdkit crash and +# (b) that valgrind checks pass. So here we only need to check that +# some timestamps were generated in the log. +grep 'debug: [[:digit:]]\{4\}-[[:digit:]]\{2\}-[[:digit:]]\{2\} [[:digit:]]\{2\}:[[:digit:]]\{2\}:[[:digit:]]\{2\}\.[[:digit:]]\{6\}: timestamped' $out -- 2.47.3