9:51 p.m.
'nbdkit -v' is quite verbose, and traces everything. Sometimes,
we want to trace JUST the client interactions. In particular, when
debugging another filter, being able to trace what the filter called
can be quite useful; and having the log filter in place will make
it easier to add testsuite coverage of other filters. Also, it is
nice to have timestamps in the log, in order to see if message
interleaving takes place, and what delays are occurring.
Signed-off-by: Eric Blake <eblake(a)redhat.com>
---
TODO | 2 -
docs/nbdkit-filter.pod | 1 +
docs/nbdkit.pod | 1 +
filters/log/nbdkit-log-filter.pod | 117 +++++++++++++
configure.ac | 1 +
filters/log/log.c | 357 ++++++++++++++++++++++++++++++++++++++
filters/Makefile.am | 1 +
filters/log/Makefile.am | 62 +++++++
8 files changed, 540 insertions(+), 2 deletions(-)
create mode 100644 filters/log/nbdkit-log-filter.pod
create mode 100644 filters/log/log.c
create mode 100644 filters/log/Makefile.am
diff --git a/TODO b/TODO
index 3f3a31b..ec71fa5 100644
--- a/TODO
+++ b/TODO
@@ -69,8 +69,6 @@ Suggestions for filters
* injecting artificial errors or otherwise masking plugin features
(such as hiding zero support) for testing clients
-* logging all client commands
-
* fua filter: setting mode=none stops advertisement, mode=emulate uses
flush emulation (or fails if !can_flush), mode=native passes on
through (or fails if can_fua does not report native support). When
diff --git a/docs/nbdkit-filter.pod b/docs/nbdkit-filter.pod
index 4ddf25d..a2babef 100644
--- a/docs/nbdkit-filter.pod
+++ b/docs/nbdkit-filter.pod
@@ -541,6 +541,7 @@ Filters:
L<nbdkit-cache-filter(1)>,
L<nbdkit-cow-filter(1)>,
L<nbdkit-delay-filter(1)>,
+L<nbdkit-log-filter(1)>,
L<nbdkit-offset-filter(1)>,
L<nbdkit-partition-filter(1)>.
diff --git a/docs/nbdkit.pod b/docs/nbdkit.pod
index 1167245..22d91e7 100644
--- a/docs/nbdkit.pod
+++ b/docs/nbdkit.pod
@@ -920,6 +920,7 @@ Filters:
L<nbdkit-cache-filter(1)>,
L<nbdkit-cow-filter(1)>,
L<nbdkit-delay-filter(1)>,
+L<nbdkit-log-filter(1)>,
L<nbdkit-offset-filter(1)>,
L<nbdkit-partition-filter(1)>.
diff --git a/filters/log/nbdkit-log-filter.pod b/filters/log/nbdkit-log-filter.pod
new file mode 100644
index 0000000..e80aa52
--- /dev/null
+++ b/filters/log/nbdkit-log-filter.pod
@@ -0,0 +1,117 @@
+=encoding utf8
+
+=head1 NAME
+
+nbdkit-log-filter - nbdkit log filter
+
+=head1 SYNOPSIS
+
+ nbdkit --filter=log [logfile=FILE] plugin [plugin-args...]
+
+=head1 DESCRIPTION
+
+C<nbdkit-log-filter> is a filter that logs all transactions. When
+used as the first filter, it can show the original client requests; as
+a later filter, it can show how earlier filters have modified the
+original request. The log results are placed in a user-specified
+file; for more details on the log format, see L<FILES>. Note that
+using C<nbdkit -v> produces much more verbose logging details to
+stderr about every aspect of nbdkit operation.
+
+=head1 PARAMETERS
+
+The nbdkit-log-filter accepts a single parameter C<logfile> which
+specifies the path of the file to use for logging. If the file
+already exists, it will be truncated. If C<logfile> is omitted,
+logging is send to stderr.
+
+=head1 EXAMPLES
+
+=head2 Log client requests
+
+Serve the file F<disk.img>, and log each client transaction in the
+file F<disk.log>:
+
+ nbdkit --filter=log file file=disk.img logfile=disk.log
+
+=head2 Trace filter transformations
+
+Use stderr to observe how many read requests are served from the
+original plugin, rather than the local cache, when using the cow
+(copy-on-write) filter:
+
+ nbdkit --filter=cow --filter=log file file=disk.img
+
+=head1 FILES
+
+This filter writes to the file specified by the C<logfile=FILE>
+parameter, or to stderr. All lines include a timestamp, a connection
+counter, then details about the command. The following actions are
+logged: Connect, Read, Write, Zero, Trim, Flush, and Disconnect.
+Except for Connect and Disconnect, an event is logged across two lines
+for call and return value, to allow tracking duration and tracing any
+parallel execution, using id for correlation (incremented per action
+on the connection).
+
+An example logging session of a client that performs a single
+successful read is:
+
+ 2018-01-27 20:38:22.959984 connection=1 Connect size=0x400 write=1 flush=1 rotational=0
trim=0
+ 2018-01-27 20:38:23.001720 connection=1 Read id=1 offset=0x0 count=0x100 ...
+ 2018-01-27 20:38:23.001995 connection=1 ...Read id=1 return=0 (Success)
+ 2018-01-27 20:38:23.044259 connection=1 Disconnect transactions=1
+
+=head1 SEE ALSO
+
+L<nbdkit(1)>,
+L<nbdkit-file-plugin(1)>,
+L<nbdkit-cow-plugin(1)>,
+L<nbdkit-filter(3)>.
+
+=head1 AUTHORS
+
+Eric Blake
+
+=head1 COPYRIGHT
+
+Copyright (C) 2018 Red Hat Inc.
+
+=head1 LICENSE
+
+Redistribution and use in source and binary forms, with or without
+modification, are permitted provided that the following conditions are
+met:
+
+=over 4
+
+=item *
+
+Redistributions of source code must retain the above copyright
+notice, this list of conditions and the following disclaimer.
+
+=item *
+
+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.
+
+=item *
+
+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.
+
+=back
+
+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.
diff --git a/configure.ac b/configure.ac
index 6025ce0..3fcc776 100644
--- a/configure.ac
+++ b/configure.ac
@@ -516,6 +516,7 @@ AC_CONFIG_FILES([Makefile
filters/cache/Makefile
filters/cow/Makefile
filters/delay/Makefile
+ filters/log/Makefile
filters/offset/Makefile
filters/partition/Makefile
src/Makefile
diff --git a/filters/log/log.c b/filters/log/log.c
new file mode 100644
index 0000000..46ddc75
--- /dev/null
+++ b/filters/log/log.c
@@ -0,0 +1,357 @@
+/* nbdkit
+ * Copyright (C) 2018 Red Hat Inc.
+ * All rights reserved.
+ *
+ * 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.
+ */
+
+#include <config.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <string.h>
+#include <stdarg.h>
+#include <errno.h>
+#include <inttypes.h>
+#include <pthread.h>
+#include <sys/time.h>
+#include <assert.h>
+
+#include <nbdkit-filter.h>
+
+#define THREAD_MODEL NBDKIT_THREAD_MODEL_PARALLEL
+
+static uint64_t connections;
+static char *logfilename;
+static FILE *logfile;
+static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
+
+static void
+log_unload (void)
+{
+ if (logfilename)
+ fclose (logfile);
+ free (logfilename);
+}
+
+/* Called for each key=value passed on the command line. */
+static int
+log_config (nbdkit_next_config *next, void *nxdata,
+ const char *key, const char *value)
+{
+ if (strcmp (key, "logfile") == 0) {
+ free (logfilename);
+ logfilename = strdup (value);
+ return 0;
+ }
+ return next (nxdata, key, value);
+}
+
+/* Open the logfile. */
+static int
+log_config_complete (nbdkit_next_config_complete *next, void *nxdata)
+{
+ if (logfilename) {
+ logfile = fopen (logfilename, "w");
+ if (!logfile) {
+ nbdkit_error ("fopen: %m");
+ return -1;
+ }
+ }
+ else
+ logfile = stderr;
+
+ return next (nxdata);
+}
+
+#define log_config_help \
+ "logfile=<FILE> (optional) The file to place the log in (default
stderr)."
+
+struct handle {
+ uint64_t connection;
+ uint64_t id;
+};
+
+/* Compute the next id number on the current connection. */
+static uint64_t
+get_id (struct handle *h)
+{
+ uint64_t r;
+
+ pthread_mutex_lock (&lock);
+ r = ++h->id;
+ pthread_mutex_unlock (&lock);
+ return r;
+}
+
+/* Output a timestamp and the log message. */
+static void __attribute__ ((format (printf, 4, 5)))
+output (struct handle *h, const char *act, uint64_t id, const char *fmt, ...)
+{
+ va_list args;
+ struct timeval tv;
+ struct tm tm;
+ char timestamp[27] = "Time unknown";
+
+ /* Logging is best effort, so ignore failure to get timestamp */
+ if (!gettimeofday (&tv, NULL))
+ {
+ size_t s;
+
+ gmtime_r (&tv.tv_sec, &tm);
+ s = strftime (timestamp, sizeof timestamp, "%F %T", &tm);
+ assert (s);
+ s = snprintf (timestamp + s, sizeof timestamp - s, ".%06ld",
+ 0L + tv.tv_usec);
+ }
+ flockfile (logfile);
+ fprintf (logfile, "%s connection=%" PRIu64 " %s ", timestamp,
h->connection,
+ act);
+ if (id)
+ fprintf (logfile, "id=%" PRIu64 " ", id);
+ va_start (args, fmt);
+ vfprintf (logfile, fmt, args);
+ va_end (args);
+ fputc ('\n', logfile);
+ funlockfile (logfile);
+}
+
+/* Shared code for a nicer log of return value */
+static void
+output_return (struct handle *h, const char *act, uint64_t id, int r)
+{
+ const char *s = "Other=>EINVAL";
+
+ /* Only decode what connections.c:nbd_errno() recognizes */
+ switch (r) {
+ case 0:
+ s = "Success";
+ break;
+ case EROFS:
+ s = "EROFS=>EPERM";
+ break;
+ case EPERM:
+ s = "EPERM";
+ break;
+ case EIO:
+ s = "EIO";
+ break;
+ case ENOMEM:
+ s = "ENOMEM";
+ break;
+#ifdef EDQUOT
+ case EDQUOT:
+ s = "EDQUOT=>ENOSPC";
+ break;
+#endif
+ case EFBIG:
+ s = "EFBIG=>ENOSPC";
+ break;
+ case ENOSPC:
+ s = "ENOSPC";
+ break;
+#ifdef ESHUTDOWN
+ case ESHUTDOWN:
+ s = "ESHUTDOWN";
+ break;
+#endif
+ case EINVAL:
+ s = "EINVAL";
+ break;
+ }
+ output (h, act, id, "return=%d (%s)", r, s);
+}
+
+/* Open a connection. */
+static void *
+log_open (nbdkit_next_open *next, void *nxdata, int readonly)
+{
+ struct handle *h;
+
+ if (next (nxdata, readonly) == -1)
+ return NULL;
+
+ h = malloc (sizeof *h);
+ if (h == NULL) {
+ nbdkit_error ("malloc: %m");
+ return NULL;
+ }
+
+ pthread_mutex_lock (&lock);
+ h->connection = ++connections;
+ pthread_mutex_unlock (&lock);
+ h->id = 0;
+ return h;
+}
+
+static void
+log_close (void *handle)
+{
+ struct handle *h = handle;
+
+ free (h);
+}
+
+static int
+log_prepare (struct nbdkit_next_ops *next_ops, void *nxdata, void *handle)
+{
+ struct handle *h = handle;
+ int64_t size = next_ops->get_size (nxdata);
+ int w = next_ops->can_write (nxdata);
+ int f = next_ops->can_flush (nxdata);
+ int r = next_ops->is_rotational (nxdata);
+ int t = next_ops->can_trim (nxdata);
+
+ if (size < 0 || w < 0 || f < 0 || r < 0 || t < 0)
+ return -1;
+
+ /* TODO expose can_zero, can_fua to filters */
+ output (h, "Connect", 0, "size=0x%" PRIx64 " write=%d flush=%d
"
+ "rotational=%d trim=%d" /* zero=? fua=? */, size, w, f, r, t);
+ return 0;
+}
+
+static int
+log_finalize (struct nbdkit_next_ops *next_ops, void *nxdata, void *handle)
+{
+ struct handle *h = handle;
+
+ output (h, "Disconnect", 0, "transactions=%" PRId64, h->id);
+ return 0;
+}
+
+/* Read data. */
+static int
+log_pread (struct nbdkit_next_ops *next_ops, void *nxdata,
+ void *handle, void *buf, uint32_t count, uint64_t offs)
+{
+ struct handle *h = handle;
+ uint64_t id = get_id (h);
+ int r;
+
+ /* TODO expose flags to filters */
+ /* assert (!flags); */
+ output (h, "Read", id, "offset=0x%" PRIx64 " count=0x%x
...",
+ offs, count);
+ r = next_ops->pread (nxdata, buf, count, offs);
+ output_return (h, "...Read", id, r);
+ return r;
+}
+
+/* Write data. */
+static int
+log_pwrite (struct nbdkit_next_ops *next_ops, void *nxdata,
+ void *handle, const void *buf, uint32_t count, uint64_t offs)
+{
+ struct handle *h = handle;
+ uint64_t id = get_id (h);
+ int r;
+
+ /* TODO expose flags to filters */
+ /* assert (!(flags & ~fua)) */
+ output (h, "Write", id, "offset=0x%" PRIx64 " count=0x%x fua=?
...",
+ offs, count);
+ r = next_ops->pwrite (nxdata, buf, count, offs);
+ output_return (h, "...Write", id, r);
+ return r;
+}
+
+/* Flush. */
+static int
+log_flush (struct nbdkit_next_ops *next_ops, void *nxdata, void *handle)
+{
+ struct handle *h = handle;
+ uint64_t id = get_id (h);
+ int r;
+
+ /* TODO expose flags to filters */
+ /* assert (!flags) */
+ output (h, "Flush", id, "...");
+ r = next_ops->flush (nxdata);
+ output_return (h, "...Flush", id, r);
+ return r;
+}
+
+/* Trim data. */
+static int
+log_trim (struct nbdkit_next_ops *next_ops, void *nxdata,
+ void *handle, uint32_t count, uint64_t offs)
+{
+ struct handle *h = handle;
+ uint64_t id = get_id (h);
+ int r;
+
+ /* TODO expose flags to filters */
+ /* assert (!(flags & ~fua)) */
+ output (h, "Trim", id, "offset=0x%" PRIx64 " count=0x%x fua=?
...",
+ offs, count);
+ r = next_ops->trim (nxdata, count, offs);
+ output_return (h, "...Trim", id, r);
+ return r;
+}
+
+/* Zero data. */
+static int
+log_zero (struct nbdkit_next_ops *next_ops, void *nxdata,
+ void *handle, uint32_t count, uint64_t offs, int may_trim)
+{
+ struct handle *h = handle;
+ uint64_t id = get_id (h);
+ int r;
+
+ /* TODO expose FUA flag to filters */
+ /* assert (!(flags & ~(fua | trim))) */
+ output (h, "Zero", id, "offset=0x%" PRIx64 " count=0x%x
trim=%d fua=? ...",
+ offs, count, may_trim);
+ r = next_ops->zero (nxdata, count, offs, may_trim);
+ output_return (h, "...Zero", id, r);
+ return r;
+}
+
+static struct nbdkit_filter filter = {
+ .name = "log",
+ .longname = "nbdkit log filter",
+ .version = PACKAGE_VERSION,
+ .config = log_config,
+ .config_complete = log_config_complete,
+ .config_help = log_config_help,
+ .unload = log_unload,
+ .open = log_open,
+ .close = log_close,
+ .prepare = log_prepare,
+ .finalize = log_finalize,
+ .pread = log_pread,
+ .pwrite = log_pwrite,
+ .flush = log_flush,
+ .trim = log_trim,
+ .zero = log_zero,
+};
+
+NBDKIT_REGISTER_FILTER(filter)
diff --git a/filters/Makefile.am b/filters/Makefile.am
index 9996d77..8e070e5 100644
--- a/filters/Makefile.am
+++ b/filters/Makefile.am
@@ -34,5 +34,6 @@ SUBDIRS = \
cache \
cow \
delay \
+ log \
offset \
partition
diff --git a/filters/log/Makefile.am b/filters/log/Makefile.am
new file mode 100644
index 0000000..18a0eba
--- /dev/null
+++ b/filters/log/Makefile.am
@@ -0,0 +1,62 @@
+# nbdkit
+# Copyright (C) 2018 Red Hat Inc.
+# All rights reserved.
+#
+# 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.
+
+EXTRA_DIST = nbdkit-log-filter.pod
+
+CLEANFILES = *~
+
+filterdir = $(libdir)/nbdkit/filters
+
+filter_LTLIBRARIES = nbdkit-log-filter.la
+
+nbdkit_log_filter_la_SOURCES = \
+ log.c \
+ $(top_srcdir)/include/nbdkit-filter.h
+
+nbdkit_log_filter_la_CPPFLAGS = \
+ -I$(top_srcdir)/include
+nbdkit_log_filter_la_CFLAGS = \
+ $(WARNINGS_CFLAGS)
+nbdkit_log_filter_la_LDFLAGS = \
+ -module -avoid-version -shared
+
+if HAVE_POD2MAN
+
+man_MANS = nbdkit-log-filter.1
+CLEANFILES += $(man_MANS)
+
+nbdkit-log-filter.1: nbdkit-log-filter.pod
+ $(POD2MAN) $(POD2MAN_ARGS) --section=1 --name=`basename $@ .1` $< $@.t && \
+ if grep 'POD ERROR' $@.t; then rm $@.t; exit 1; fi && \
+ mv $@.t $@
+
+endif
--
2.14.3