Eric Blake
2018-Jan-28 03:51 UTC
[Libguestfs] [nbdkit PATCH 0/2] RFC: tweak error handling, add log filter
Here's what I'm currently playing with; I'm not ready to commit anything until I rebase my FUA work on top of this, as I only want to break filter ABI once between releases. Eric Blake (2): backend: Rework internal/filter error return semantics filters: Add log filter TODO | 2 - docs/nbdkit-filter.pod | 84 +++++++-- docs/nbdkit.pod | 1 + filters/log/nbdkit-log-filter.pod | 117 +++++++++++++ configure.ac | 1 + src/internal.h | 1 - src/connections.c | 45 ++--- src/filters.c | 81 +++++---- src/plugins.c | 66 +++---- filters/cache/cache.c | 49 ++++-- filters/cow/cow.c | 28 +-- filters/log/log.c | 357 ++++++++++++++++++++++++++++++++++++++ filters/partition/partition.c | 2 +- filters/Makefile.am | 1 + filters/log/Makefile.am | 62 +++++++ 15 files changed, 761 insertions(+), 136 deletions(-) create mode 100644 filters/log/nbdkit-log-filter.pod create mode 100644 filters/log/log.c create mode 100644 filters/log/Makefile.am -- 2.14.3
Eric Blake
2018-Jan-28 03:51 UTC
[Libguestfs] [nbdkit PATCH 1/2] backend: Rework internal/filter error return semantics
Previously, we let a plugin set an error in either thread-local
storage (nbdkit_set_error()) or errno, then connections.c would
decode which error to use. But with filters in the mix, it is
very difficult for a filter to know what error was set by the
plugin (particularly since nbdkit_set_error() has no public
counterpart for reading the thread-local storage). What's more,
if a filter does any non-trivial processing after calling into
next_ops, it is very probable that errno might be corrupted,
which would affect the error returned by a plugin that relied
on errno but not the error stored in thread-local storage.
Better is to change the backend interface to just pass the
direct error value, by moving the decoding of thread-local vs.
errno into plugins.c. With the change in decoding location,
the backend interface no longer needs an .errno_is_preserved()
callback.
For maximum convenience, this change lets a filter return an
error either by passing through the underlying plugin return
(a positive error) or by setting -1 and storing something in
errno. However, I did have to tweak some of the existing
filters to actually handle and/or return the right error; which
means this IS a subtle change to the filter interface (and
worse, one that cannot be detected by the compiler because
the API signatures did not change). However, more ABI changes
are planned with adding FUA support, so as long as it is all
done as part of the same release, we are okay.
Also note that only nbdkit-plugin.h declares nbdkit_set_error();
we can actually keep it this way (filters do not need to call
that function).
Signed-off-by: Eric Blake <eblake@redhat.com>
---
docs/nbdkit-filter.pod | 83 +++++++++++++++++++++++++++++++++++++------
src/internal.h | 1 -
src/connections.c | 45 ++++++-----------------
src/filters.c | 81 +++++++++++++++++++++++++----------------
src/plugins.c | 66 +++++++++++++++++++---------------
filters/cache/cache.c | 49 +++++++++++++++----------
filters/cow/cow.c | 28 +++++++++------
filters/partition/partition.c | 2 +-
8 files changed, 221 insertions(+), 134 deletions(-)
diff --git a/docs/nbdkit-filter.pod b/docs/nbdkit-filter.pod
index eb72dae..4ddf25d 100644
--- a/docs/nbdkit-filter.pod
+++ b/docs/nbdkit-filter.pod
@@ -163,10 +163,14 @@ short-circuited.
The filter’s other methods like C<.prepare>, C<.get_size>,
C<.pread>
etc ― always called in the context of a connection ― are passed a
-pointer to C<struct nbdkit_next_ops> which contains a subset of the
-plugin methods that can be called during a connection. It is possible
-for a filter to issue (for example) extra read calls in response to a
-single C<.pwrite> call.
+pointer to C<struct nbdkit_next_ops> which contains a comparable set
+of accessors to plugin methods that can be called during a connection.
+It is possible for a filter to issue (for example) extra read calls in
+response to a single C<.pwrite> call. Note that the semantics of the
+functions in C<struct nbdkit_next_ops> are slightly different from
+what a plugin implements: for example, while a plugin's C<.pread>
+returns -1 on error, C<next_ops->pread> returns a positive errno
+value.
You can modify parameters when you call the C<next> function. However
be careful when modifying strings because for some methods
@@ -324,6 +328,11 @@ will see.
The returned size must be E<ge> 0. If there is an error,
C<.get_size>
should call C<nbdkit_error> with an error message and return C<-1>.
+If this function is called more than once for the same connection, it
+should return the same value; similarly, the filter may cache
+C<next_ops->get_size> for a given connection rather than repeating
+calls. Note that if C<next_ops->get_size> fails, the value of
+C<errno> is indeterminate.
=head2 C<.can_write>
@@ -346,7 +355,11 @@ should call C<nbdkit_error> with an error message and
return C<-1>.
These intercept the corresponding plugin methods.
If there is an error, the callback should call C<nbdkit_error> with an
-error message and return C<-1>.
+error message and return C<-1>. If these functions are called more
+than once for the same connection, they should return the same value;
+similarly, the filter may cache the results of each counterpart in
+C<next_ops> for a given connection rather than repeating calls. Note
+that if C<next_ops> fails, the value of C<errno> is indeterminate.
=head2 C<.pread>
@@ -356,9 +369,15 @@ error message and return C<-1>.
This intercepts the plugin C<.pread> method and can be used to read or
modify data read by the plugin.
+Note that unlike the plugin C<.pread> which returns -1 on error,
+C<next_ops->pread> returns a positive errno value on error; the filter
+should use this return value to learn why the plugin failed, and not
+rely on C<errno>.
+
If there is an error (including a short read which couldn't be
recovered from), C<.pread> should call C<nbdkit_error> with an
error
-message B<and> set C<errno>, then return C<-1>.
+message B<and> either return -1 with C<errno> set or return a
positive
+errno value corresponding to the problem.
=head2 C<.pwrite>
@@ -369,9 +388,15 @@ message B<and> set C<errno>, then return
C<-1>.
This intercepts the plugin C<.pwrite> method and can be used to modify
data written by the plugin.
+Note that unlike the plugin C<.pwrite> which returns -1 on error,
+C<next_ops->pwrite> returns a positive errno value on error; the
+filter should use this return value to learn why the plugin failed,
+and not rely on C<errno>.
+
If there is an error (including a short write which couldn't be
recovered from), C<.pwrite> should call C<nbdkit_error> with an
error
-message B<and> set C<errno>, then return C<-1>.
+message B<and> either return -1 with C<errno> set or return a
positive
+errno value corresponding to the problem.
=head2 C<.flush>
@@ -381,8 +406,14 @@ message B<and> set C<errno>, then return
C<-1>.
This intercepts the plugin C<.flush> method and can be used to modify
flush requests.
+Note that unlike the plugin C<.flush> which returns -1 on error,
+C<next_ops->flush> returns a positive errno value on error; the filter
+should use this return value to learn why the plugin failed, and not
+rely on C<errno>.
+
If there is an error, C<.flush> should call C<nbdkit_error> with an
-error message B<and> set C<errno>, then return C<-1>.
+error message B<and> either return -1 with C<errno> set or return a
+positive errno value corresponding to the problem.
=head2 C<.trim>
@@ -392,8 +423,14 @@ error message B<and> set C<errno>, then return
C<-1>.
This intercepts the plugin C<.trim> method and can be used to modify
trim requests.
+Note that unlike the plugin C<.trim> which returns -1 on error,
+C<next_ops->trim> returns a positive errno value on error; the filter
+should use this return value to learn why the plugin failed, and not
+rely on C<errno>.
+
If there is an error, C<.trim> should call C<nbdkit_error> with an
-error message B<and> set C<errno>, then return C<-1>.
+error message B<and> either return -1 with C<errno> set or return a
+positive errno value corresponding to the problem.
=head2 C<.zero>
@@ -403,8 +440,34 @@ error message B<and> set C<errno>, then return
C<-1>.
This intercepts the plugin C<.zero> method and can be used to modify
zero requests.
+Note that unlike the plugin C<.zero> which returns -1 on error,
+C<next_ops->zero> returns a positive errno value on error; the filter
+should use this return value to learn why the plugin failed, and not
+rely on C<errno>. Furthermore, C<next_ops->zero> will never
return
+C<ENOTSUP>; the plugin will have already fallen back to using
+C<.pwrite> instead.
+
If there is an error, C<.zero> should call C<nbdkit_error> with an
-error message B<and> set C<errno>, then return C<-1>.
+error message B<and> either return -1 with C<errno> set or return a
+positive errno value corresponding to the problem. The filter should
+never fail with C<ENOTSUP> (while plugins have automatic fallback to
+C<.pwrite>, filters do not).
+
+=head1 ERROR HANDLING
+
+If there is an error in the filter itself, the filter should call
+C<nbdkit_error> to report an error message. If the callback is
+involved in serving data, the return value determines the error code
+that will be sent to the client; other callbacks should return the
+appropriate error indication, eg. C<NULL> or C<-1>.
+
+C<nbdkit_error> has the following prototype and works like
+L<printf(3)>:
+
+ void nbdkit_error (const char *fs, ...);
+ void nbdkit_verror (const char *fs, va_list args);
+
+For convenience, C<nbdkit_error> preserves the value of C<errno>.
=head1 DEBUGGING
diff --git a/src/internal.h b/src/internal.h
index 3cbfde5..2cda390 100644
--- a/src/internal.h
+++ b/src/internal.h
@@ -176,7 +176,6 @@ struct backend {
void (*dump_fields) (struct backend *);
void (*config) (struct backend *, const char *key, const char *value);
void (*config_complete) (struct backend *);
- int (*errno_is_preserved) (struct backend *);
int (*open) (struct backend *, struct connection *conn, int readonly);
int (*prepare) (struct backend *, struct connection *conn);
int (*finalize) (struct backend *, struct connection *conn);
diff --git a/src/connections.c b/src/connections.c
index 75c2c2d..2959493 100644
--- a/src/connections.c
+++ b/src/connections.c
@@ -43,6 +43,7 @@
#include <endian.h>
#include <sys/types.h>
#include <stddef.h>
+#include <assert.h>
#include <pthread.h>
@@ -912,18 +913,6 @@ validate_request (struct connection *conn,
return true; /* Command validates. */
}
-/* Grab the appropriate error value.
- */
-static int
-get_error (struct connection *conn)
-{
- int ret = threadlocal_get_error ();
-
- if (!ret && backend->errno_is_preserved (backend))
- ret = errno;
- return ret ? ret : EIO;
-}
-
/* This is called with the request lock held to actually execute the
* request (by calling the plugin). Note that the request fields have
* been validated already in 'validate_request' so we don't have to
@@ -942,49 +931,36 @@ handle_request (struct connection *conn,
uint32_t f = 0;
bool fua = conn->can_flush && (flags & NBD_CMD_FLAG_FUA);
- /* The plugin should call nbdkit_set_error() to request a particular
- error, otherwise we fallback to errno or EIO. */
+ /* Clear the error, so that we know if the plugin calls
+ nbdkit_set_error() or relied on errno. */
threadlocal_set_error (0);
switch (cmd) {
case NBD_CMD_READ:
- if (backend->pread (backend, conn, buf, count, offset, 0) == -1)
- return get_error (conn);
- break;
+ return backend->pread (backend, conn, buf, count, offset, 0);
case NBD_CMD_WRITE:
if (fua)
f |= NBDKIT_FLAG_FUA;
- if (backend->pwrite (backend, conn, buf, count, offset, f) == -1)
- return get_error (conn);
- break;
+ return backend->pwrite (backend, conn, buf, count, offset, f);
case NBD_CMD_FLUSH:
- if (backend->flush (backend, conn, 0) == -1)
- return get_error (conn);
- break;
+ return backend->flush (backend, conn, 0);
case NBD_CMD_TRIM:
if (fua)
f |= NBDKIT_FLAG_FUA;
- if (backend->trim (backend, conn, count, offset, f) == -1)
- return get_error (conn);
- break;
+ return backend->trim (backend, conn, count, offset, f);
case NBD_CMD_WRITE_ZEROES:
if (!(flags & NBD_CMD_FLAG_NO_HOLE))
f |= NBDKIT_FLAG_MAY_TRIM;
if (fua)
f |= NBDKIT_FLAG_FUA;
- if (backend->zero (backend, conn, count, offset, f) == -1)
- return get_error (conn);
- break;
-
- default:
- abort ();
+ return backend->zero (backend, conn, count, offset, f);
}
-
- return 0;
+ /* Unreachable */
+ abort ();
}
static int
@@ -1130,6 +1106,7 @@ recv_request_send_reply (struct connection *conn)
else {
lock_request (conn);
error = handle_request (conn, cmd, flags, offset, count, buf);
+ assert ((int) error >= 0);
unlock_request (conn);
}
diff --git a/src/filters.c b/src/filters.c
index 40c4913..1003dc7 100644
--- a/src/filters.c
+++ b/src/filters.c
@@ -107,14 +107,6 @@ filter_thread_model (struct backend *b)
/* These are actually passing through to the final plugin, hence
* the function names.
*/
-static int
-plugin_errno_is_preserved (struct backend *b)
-{
- struct backend_filter *f = container_of (b, struct backend_filter, backend);
-
- return f->backend.next->errno_is_preserved (f->backend.next);
-}
-
static const char *
plugin_name (struct backend *b)
{
@@ -463,17 +455,23 @@ filter_pread (struct backend *b, struct connection *conn,
struct backend_filter *f = container_of (b, struct backend_filter, backend);
void *handle = connection_get_handle (conn, f->backend.i);
struct b_conn nxdata = { .b = f->backend.next, .conn = conn };
+ int r;
assert (flags == 0);
debug ("pread count=%" PRIu32 " offset=%" PRIu64, count,
offset);
- if (f->filter.pread)
- return f->filter.pread (&next_ops, &nxdata, handle,
- buf, count, offset);
+ if (f->filter.pread) {
+ r = f->filter.pread (&next_ops, &nxdata, handle,
+ buf, count, offset);
+ if (r < 0)
+ r = errno;
+ }
else
- return f->backend.next->pread (f->backend.next, conn,
- buf, count, offset, flags);
+ r = f->backend.next->pread (f->backend.next, conn,
+ buf, count, offset, flags);
+ assert (r >= 0);
+ return r;
}
static int
@@ -485,18 +483,24 @@ filter_pwrite (struct backend *b, struct connection *conn,
void *handle = connection_get_handle (conn, f->backend.i);
struct b_conn nxdata = { .b = f->backend.next, .conn = conn };
bool fua = flags & NBDKIT_FLAG_FUA;
+ int r;
assert (!(flags & ~NBDKIT_FLAG_FUA));
debug ("pwrite count=%" PRIu32 " offset=%" PRIu64 "
fua=%d",
count, offset, fua);
- if (f->filter.pwrite)
- return f->filter.pwrite (&next_ops, &nxdata, handle,
- buf, count, offset);
+ if (f->filter.pwrite) {
+ r = f->filter.pwrite (&next_ops, &nxdata, handle,
+ buf, count, offset);
+ if (r < 0)
+ r = errno;
+ }
else
- return f->backend.next->pwrite (f->backend.next, conn,
- buf, count, offset, flags);
+ r = f->backend.next->pwrite (f->backend.next, conn,
+ buf, count, offset, flags);
+ assert (r >= 0);
+ return r;
}
static int
@@ -505,15 +509,21 @@ filter_flush (struct backend *b, struct connection *conn,
uint32_t flags)
struct backend_filter *f = container_of (b, struct backend_filter, backend);
void *handle = connection_get_handle (conn, f->backend.i);
struct b_conn nxdata = { .b = f->backend.next, .conn = conn };
+ int r;
assert (flags == 0);
debug ("flush");
- if (f->filter.flush)
- return f->filter.flush (&next_ops, &nxdata, handle);
+ if (f->filter.flush) {
+ r= f->filter.flush (&next_ops, &nxdata, handle);
+ if (r < 0)
+ r = errno;
+ }
else
- return f->backend.next->flush (f->backend.next, conn, flags);
+ r = f->backend.next->flush (f->backend.next, conn, flags);
+ assert (r >= 0);
+ return r;
}
static int
@@ -524,15 +534,21 @@ filter_trim (struct backend *b, struct connection *conn,
struct backend_filter *f = container_of (b, struct backend_filter, backend);
void *handle = connection_get_handle (conn, f->backend.i);
struct b_conn nxdata = { .b = f->backend.next, .conn = conn };
+ int r;
assert (flags == 0);
debug ("trim count=%" PRIu32 " offset=%" PRIu64, count,
offset);
- if (f->filter.trim)
- return f->filter.trim (&next_ops, &nxdata, handle, count,
offset);
+ if (f->filter.trim) {
+ r = f->filter.trim (&next_ops, &nxdata, handle, count, offset);
+ if (r < 0)
+ r = errno;
+ }
else
- return f->backend.next->trim (f->backend.next, conn, count,
offset, flags);
+ r = f->backend.next->trim (f->backend.next, conn, count, offset,
flags);
+ assert (r >= 0);
+ return r;
}
static int
@@ -543,18 +559,24 @@ filter_zero (struct backend *b, struct connection *conn,
void *handle = connection_get_handle (conn, f->backend.i);
struct b_conn nxdata = { .b = f->backend.next, .conn = conn };
int may_trim = (flags & NBDKIT_FLAG_MAY_TRIM) != 0;
+ int r;
assert (!(flags & ~(NBDKIT_FLAG_MAY_TRIM | NBDKIT_FLAG_FUA)));
debug ("zero count=%" PRIu32 " offset=%" PRIu64 "
may_trim=%d",
count, offset, may_trim);
- if (f->filter.zero)
- return f->filter.zero (&next_ops, &nxdata, handle,
- count, offset, may_trim);
+ if (f->filter.zero) {
+ r = f->filter.zero (&next_ops, &nxdata, handle,
+ count, offset, may_trim);
+ if (r < 0)
+ r = errno;
+ }
else
- return f->backend.next->zero (f->backend.next, conn,
- count, offset, flags);
+ r = f->backend.next->zero (f->backend.next, conn,
+ count, offset, flags);
+ assert (r >= 0 && r != ENOTSUP);
+ return r;
}
static struct backend filter_functions = {
@@ -567,7 +589,6 @@ static struct backend filter_functions = {
.dump_fields = filter_dump_fields,
.config = filter_config,
.config_complete = filter_config_complete,
- .errno_is_preserved = plugin_errno_is_preserved,
.open = filter_open,
.prepare = filter_prepare,
.finalize = filter_finalize,
diff --git a/src/plugins.c b/src/plugins.c
index dba3e24..c49c0f0 100644
--- a/src/plugins.c
+++ b/src/plugins.c
@@ -227,14 +227,6 @@ plugin_config_complete (struct backend *b)
exit (EXIT_FAILURE);
}
-static int
-plugin_errno_is_preserved (struct backend *b)
-{
- struct backend_plugin *p = container_of (b, struct backend_plugin, backend);
-
- return p->plugin.errno_is_preserved;
-}
-
static int
plugin_open (struct backend *b, struct connection *conn, int readonly)
{
@@ -358,11 +350,24 @@ plugin_can_trim (struct backend *b, struct connection
*conn)
return p->plugin.trim != NULL;
}
+/* Grab the appropriate error value.
+ */
+static int
+get_error (struct backend_plugin *p)
+{
+ int ret = threadlocal_get_error ();
+
+ if (!ret && p->plugin.errno_is_preserved)
+ ret = errno;
+ return ret ? ret : EIO;
+}
+
static int
plugin_pread (struct backend *b, struct connection *conn,
void *buf, uint32_t count, uint64_t offset, uint32_t flags)
{
struct backend_plugin *p = container_of (b, struct backend_plugin, backend);
+ int r;
assert (connection_get_handle (conn, 0));
assert (p->plugin.pread != NULL);
@@ -370,25 +375,29 @@ plugin_pread (struct backend *b, struct connection *conn,
debug ("pread count=%" PRIu32 " offset=%" PRIu64, count,
offset);
- return p->plugin.pread (connection_get_handle (conn, 0), buf, count,
offset);
+ r = p->plugin.pread (connection_get_handle (conn, 0), buf, count, offset);
+ if (r < 0)
+ r = get_error (p);
+ return r;
}
static int
plugin_flush (struct backend *b, struct connection *conn, uint32_t flags)
{
struct backend_plugin *p = container_of (b, struct backend_plugin, backend);
+ int r;
assert (connection_get_handle (conn, 0));
assert (!flags);
debug ("flush");
- if (p->plugin.flush != NULL)
- return p->plugin.flush (connection_get_handle (conn, 0));
- else {
- errno = EINVAL;
- return -1;
- }
+ if (!p->plugin.flush)
+ return EINVAL;
+ r = p->plugin.flush (connection_get_handle (conn, 0));
+ if (r < 0)
+ r = get_error (p);
+ return r;
}
static int
@@ -408,14 +417,14 @@ plugin_pwrite (struct backend *b, struct connection *conn,
if (p->plugin.pwrite != NULL)
r = p->plugin.pwrite (connection_get_handle (conn, 0),
buf, count, offset);
- else {
- errno = EROFS;
- return -1;
- }
+ else
+ return EROFS;
if (r == 0 && fua) {
assert (p->plugin.flush);
r = plugin_flush (b, conn, 0);
}
+ if (r < 0)
+ r = get_error (p);
return r;
}
@@ -435,14 +444,14 @@ plugin_trim (struct backend *b, struct connection *conn,
if (p->plugin.trim != NULL)
r = p->plugin.trim (connection_get_handle (conn, 0), count, offset);
- else {
- errno = EINVAL;
- return -1;
- }
+ else
+ return EINVAL;
if (r == 0 && fua) {
assert (p->plugin.flush);
r = plugin_flush (b, conn, 0);
}
+ if (r < 0)
+ r = get_error (p);
return r;
}
@@ -472,7 +481,7 @@ plugin_zero (struct backend *b, struct connection *conn,
count, offset, may_trim);
if (result == -1) {
err = threadlocal_get_error ();
- if (!err && plugin_errno_is_preserved (b))
+ if (!err && p->plugin.errno_is_preserved)
err = errno;
}
if (result == 0 || err != EOPNOTSUPP)
@@ -483,10 +492,8 @@ plugin_zero (struct backend *b, struct connection *conn,
threadlocal_set_error (0);
limit = count < MAX_REQUEST_SIZE ? count : MAX_REQUEST_SIZE;
buf = calloc (limit, 1);
- if (!buf) {
- errno = ENOMEM;
- return -1;
- }
+ if (!buf)
+ return ENOMEM;
while (count) {
result = p->plugin.pwrite (connection_get_handle (conn, 0),
@@ -507,6 +514,8 @@ plugin_zero (struct backend *b, struct connection *conn,
assert (p->plugin.flush);
result = plugin_flush (b, conn, 0);
}
+ if (result < 0)
+ result = get_error (p);
return result;
}
@@ -520,7 +529,6 @@ static struct backend plugin_functions = {
.dump_fields = plugin_dump_fields,
.config = plugin_config,
.config_complete = plugin_config_complete,
- .errno_is_preserved = plugin_errno_is_preserved,
.open = plugin_open,
.prepare = plugin_prepare,
.finalize = plugin_finalize,
diff --git a/filters/cache/cache.c b/filters/cache/cache.c
index 9473f2c..2ae6f01 100644
--- a/filters/cache/cache.c
+++ b/filters/cache/cache.c
@@ -292,6 +292,7 @@ blk_writethrough (struct nbdkit_next_ops *next_ops, void
*nxdata,
uint64_t blknum, const uint8_t *block)
{
off_t offset = blknum * BLKSIZE;
+ int r;
nbdkit_debug ("cache: blk_writethrough block %" PRIu64
" (offset %" PRIu64 ")",
@@ -302,8 +303,9 @@ blk_writethrough (struct nbdkit_next_ops *next_ops, void
*nxdata,
return -1;
}
- if (next_ops->pwrite (nxdata, block, BLKSIZE, offset) == -1)
- return -1;
+ r = next_ops->pwrite (nxdata, block, BLKSIZE, offset);
+ if (r)
+ return r;
blk_set_bitmap_entry (blknum, BLOCK_CLEAN);
@@ -341,6 +343,7 @@ cache_pread (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle, void *buf, uint32_t count, uint64_t offset)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -357,9 +360,10 @@ cache_pread (struct nbdkit_next_ops *next_ops, void
*nxdata,
if (n > count)
n = count;
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memcpy (buf, &block[blkoffs], n);
@@ -379,6 +383,7 @@ cache_pwrite (struct nbdkit_next_ops *next_ops, void
*nxdata,
void *handle, const void *buf, uint32_t count, uint64_t offset)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -396,14 +401,16 @@ cache_pwrite (struct nbdkit_next_ops *next_ops, void
*nxdata,
n = count;
/* Do a read-modify-write operation on the current block. */
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memcpy (&block[blkoffs], buf, n);
- if (blk_writeback (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_writeback (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
buf += n;
@@ -421,6 +428,7 @@ cache_zero (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle, uint32_t count, uint64_t offset, int may_trim)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -437,14 +445,16 @@ cache_zero (struct nbdkit_next_ops *next_ops, void
*nxdata,
if (n > count)
n = count;
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memset (&block[blkoffs], 0, n);
- if (blk_writeback (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_writeback (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
count -= n;
@@ -463,7 +473,7 @@ cache_flush (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle)
uint64_t i, j;
uint64_t blknum;
enum bm_entry state;
- unsigned errors = 0;
+ int error = 0, r;
if (cache_mode == CACHE_MODE_UNSAFE)
return 0;
@@ -494,10 +504,10 @@ cache_flush (struct nbdkit_next_ops *next_ops, void
*nxdata, void *handle)
/* Perform a read + writethrough which will read from the
* cache and write it through to the underlying storage.
*/
- if (blk_read (next_ops, nxdata, blknum, block) == -1 ||
- blk_writethrough (next_ops, nxdata, blknum, block)) {
+ if ((r = blk_read (next_ops, nxdata, blknum, block)) ||
+ (r = blk_writethrough (next_ops, nxdata, blknum, block))) {
nbdkit_error ("cache: flush of block %" PRIu64 "
failed", blknum);
- errors++;
+ error = error ? error : r;
}
}
}
@@ -507,10 +517,11 @@ cache_flush (struct nbdkit_next_ops *next_ops, void
*nxdata, void *handle)
free (block);
/* Now issue a flush request to the underlying storage. */
- if (next_ops->flush (nxdata) == -1)
- errors++;
+ r = next_ops->flush (nxdata);
+ if (r)
+ error = error ? error : r;
- return errors == 0 ? 0 : -1;
+ return error;
}
static struct nbdkit_filter filter = {
diff --git a/filters/cow/cow.c b/filters/cow/cow.c
index 5c2fcd0..18debf7 100644
--- a/filters/cow/cow.c
+++ b/filters/cow/cow.c
@@ -313,6 +313,7 @@ cow_pread (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle, void *buf, uint32_t count, uint64_t offset)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -329,9 +330,10 @@ cow_pread (struct nbdkit_next_ops *next_ops, void *nxdata,
if (n > count)
n = count;
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memcpy (buf, &block[blkoffs], n);
@@ -351,6 +353,7 @@ cow_pwrite (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle, const void *buf, uint32_t count, uint64_t offset)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -368,14 +371,16 @@ cow_pwrite (struct nbdkit_next_ops *next_ops, void
*nxdata,
n = count;
/* Do a read-modify-write operation on the current block. */
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memcpy (&block[blkoffs], buf, n);
- if (blk_write (blknum, block) == -1) {
+ r = blk_write (blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
buf += n;
@@ -393,6 +398,7 @@ cow_zero (struct nbdkit_next_ops *next_ops, void *nxdata,
void *handle, uint32_t count, uint64_t offset, int may_trim)
{
uint8_t *block;
+ int r;
block = malloc (BLKSIZE);
if (block == NULL) {
@@ -412,14 +418,16 @@ cow_zero (struct nbdkit_next_ops *next_ops, void *nxdata,
/* XXX There is the possibility of optimizing this: ONLY if we are
* writing a whole, aligned block, then use FALLOC_FL_ZERO_RANGE.
*/
- if (blk_read (next_ops, nxdata, blknum, block) == -1) {
+ r = blk_read (next_ops, nxdata, blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
memset (&block[blkoffs], 0, n);
- if (blk_write (blknum, block) == -1) {
+ r = blk_write (blknum, block);
+ if (r) {
free (block);
- return -1;
+ return r;
}
count -= n;
diff --git a/filters/partition/partition.c b/filters/partition/partition.c
index f74b3af..bf5238d 100644
--- a/filters/partition/partition.c
+++ b/filters/partition/partition.c
@@ -216,7 +216,7 @@ find_gpt_partition (struct nbdkit_next_ops *next_ops, void
*nxdata,
* partition_prepare call above.
*/
if (next_ops->pread (nxdata, partition_bytes, sizeof partition_bytes,
- 2*512 + i*128) == -1)
+ 2*512 + i*128))
return -1;
get_gpt_partition (partition_bytes, &partition);
if (memcmp (partition.partition_type_guid,
--
2.14.3
'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@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
Eric Blake
2018-Jan-30 03:26 UTC
Re: [Libguestfs] [nbdkit PATCH 2/2] filters: Add log filter
On 01/27/2018 09:51 PM, Eric Blake wrote:> '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@redhat.com> > ---> +=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.s/send/sent/ But that doesn't work unless you use 'nbdkit -f' - as soon as you let nbdkit fork into the background, it silently replaces the original stdout/stderr with /dev/null. Looks like I should just make logfilemandatory. I'm also debating whether truncation makes the most sense, or whether the log should use append mode.> +++ b/filters/log/log.c> +static void > +log_unload (void) > +{ > + if (logfilename) > + fclose (logfile); > + free (logfilename); > +}> +/* 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);Also, I found that either this needs to fflush(logfile), or else explicitly request that stdio use line buffering; otherwise, 'tail -f logfile' doesn't see live updates until the buffer fills or nbdkit quits and invokes the final implied flush via fclose(). -- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3266 Virtualization: qemu.org | libvirt.org