[libnbd PATCH 0/2] Trace even may_set_error=false functions
In my series to add nbd_stats_bytes_sent(), I was trying to see what values were being printed, only to learn we weren't printing any. This series fixes that. Eric Blake (2): debug: Change trace of RStaticString returns debug: Trace even may_set_error=false functions lib/internal.h | 16 +++++++---- generator/C.ml | 73 +++++++++++++++++++++++++------------------------- lib/debug.c | 9 ++++--- 3 files changed, 53 insertions(+), 45 deletions(-) -- 2.37.2
We have very few APIs that return RStaticString. At present, only two can fail (get_protocol, connection_state); and when they succeed, their string is short enough to not need sanitization. Thus we can simplify them, which in turn will make it easier for the next patch to convert the remaining two RStaticString functions that cannot fail (get_package_name, get_version) to also trace their results. This is the entire change to the generated api.c: | --- lib/api.c.bak 2022-09-03 12:38:46.213177887 -0500 | +++ lib/api.c 2022-09-03 12:44:41.571034888 -0500 | @@ -2839,10 +2839,7 @@ nbd_get_protocol (struct nbd_handle *h) | if (ret == NULL) | debug (h, "leave: error=\"%s\"", nbd_get_error ()); | else { | - char *ret_printable = | - nbd_internal_printable_string (ret); | - debug (h, "leave: ret=" "%s", ret_printable ? ret_printable : ""); | - free (ret_printable); | + debug (h, "leave: ret=" "%s", ret); | } | } | | @@ -5048,10 +5045,7 @@ nbd_connection_state (struct nbd_handle | if (ret == NULL) | debug (h, "leave: error=\"%s\"", nbd_get_error ()); | else { | - char *ret_printable = | - nbd_internal_printable_string (ret); | - debug (h, "leave: ret=" "%s", ret_printable ? ret_printable : ""); | - free (ret_printable); | + debug (h, "leave: ret=" "%s", ret); | } | } --- generator/C.ml | 22 ++++++++-------------- 1 file changed, 8 insertions(+), 14 deletions(-) diff --git a/generator/C.ml b/generator/C.ml index 9c67efaa..38f8d946 100644 --- a/generator/C.ml +++ b/generator/C.ml @@ -715,39 +715,33 @@ let (* Print the trace when we leave a call with debugging enabled. *) and print_trace_leave ret = pr " if_debug (h) {\n"; - let errcode = errcode_of_ret ret in - (match errcode with + (match errcode_of_ret ret with | Some r -> pr " if (ret == %s)\n" r; - | None -> - pr " if (0)\n"; + | None -> assert false ); pr " debug (h, \"leave: error=\\\"%%s\\\"\", nbd_get_error ());\n"; pr " else {\n"; (match ret with - | RStaticString | RString -> + | RString -> pr " char *ret_printable =\n"; pr " nbd_internal_printable_string (ret);\n" - | RBool | RErr | RFd | RInt - | RInt64 | RCookie | RSizeT - | RUInt | RUIntPtr | REnum _ | RFlags _ -> () + | _ -> () ); pr " debug (h, \"leave: ret=\" "; (match ret with | RBool | RErr | RFd | RInt | REnum _ -> pr "\"%%d\", ret" | RInt64 | RCookie -> pr "\"%%\" PRIi64 \"\", ret" | RSizeT -> pr "\"%%zd\", ret" - | RStaticString | RString -> - pr "\"%%s\", ret_printable ? ret_printable : \"\"" + | RString -> pr "\"%%s\", ret_printable ? ret_printable : \"\"" + | RStaticString -> pr "\"%%s\", ret" | RUInt | RFlags _ -> pr "\"%%u\", ret" | RUIntPtr -> pr "\"%%\" PRIuPTR, ret" ); pr ");\n"; (match ret with - | RStaticString | RString -> pr " free (ret_printable);\n" - | RBool | RErr | RFd | RInt - | RInt64 | RCookie | RSizeT - | RUInt | REnum _ | RFlags _ | RUIntPtr -> () + | RString -> pr " free (ret_printable);\n" + | _ -> () ); pr " }\n"; pr " }\n" -- 2.37.2
When we introduced debug tracing, we stated that "because of limitations in the way debugging works it can only be done on functions which have may_set_error = true". This is because our trace statements depended on the current error context for part of its trace. But this is overly restrictive; if we know there is not going to be any error, we can just pass in the function name to the debug trace directly, by tweaking the signature for internal debugging. The common case of debug() statements depending on an implicit context is unchanged. An example of the changes to the generated lib/api.c is: | --- lib/api.c.bak 2022-09-03 11:07:52.668893312 -0500 | +++ lib/api.c 2022-09-03 11:19:19.793796181 -0500 | @@ -68,8 +68,16 @@ nbd_get_debug (struct nbd_handle *h) | | /* This function must not call set_error. */ | pthread_mutex_lock (&h->lock); | + if_debug (h) { | + debug_direct (h, "nbd_get_debug", "enter:"); | + } | + | ret = nbd_unlocked_get_debug (h); | | + if_debug (h) { | + debug_direct (h, "nbd_get_debug", "leave: ret=" "%d", ret); | + } | + | if (h->public_state != get_next_state (h)) | h->public_state = get_next_state (h); | pthread_mutex_unlock (&h->lock); and traces for functions like set_private_data() now show up in the logs. Fixes: 9df088bf ("lib: Print function call parameters and results in debug output.", v0.9.7) --- lib/internal.h | 16 +++++++++---- generator/C.ml | 63 ++++++++++++++++++++++++++++---------------------- lib/debug.c | 9 ++++---- 3 files changed, 51 insertions(+), 37 deletions(-) diff --git a/lib/internal.h b/lib/internal.h index 8aaff151..ed074c1d 100644 --- a/lib/internal.h +++ b/lib/internal.h @@ -388,11 +388,17 @@ extern int nbd_internal_crypto_handshake (struct nbd_handle *); extern void nbd_internal_crypto_debug_tls_enabled (struct nbd_handle *); /* debug.c */ -extern void nbd_internal_debug (struct nbd_handle *h, const char *fs, ...); -#define debug(h, fs, ...) \ - do { \ - if_debug ((h)) \ - nbd_internal_debug ((h), (fs), ##__VA_ARGS__); \ +extern void nbd_internal_debug (struct nbd_handle *h, const char *context, + const char *fs, ...); +#define debug(h, fs, ...) \ + do { \ + if_debug ((h)) \ + nbd_internal_debug ((h), NULL, (fs), ##__VA_ARGS__); \ + } while (0) +#define debug_direct(h, c, fs, ...) \ + do { \ + if_debug ((h)) \ + nbd_internal_debug ((h), (c), (fs), ##__VA_ARGS__); \ } while (0) /* errors.c */ diff --git a/generator/C.ml b/generator/C.ml index 38f8d946..c8f6ef43 100644 --- a/generator/C.ml +++ b/generator/C.ml @@ -486,10 +486,8 @@ let (* Lock the handle. *) if is_locked then pr " pthread_mutex_lock (&h->lock);\n"; - if may_set_error then ( - print_trace_enter args optargs; - pr "\n" - ); + print_trace_enter name args optargs may_set_error; + pr "\n"; (* Sanitize read buffers before any error is possible. *) List.iter ( @@ -597,10 +595,8 @@ let pr "\n"; if !need_out_label then pr " out:\n"; - if may_set_error then ( - print_trace_leave ret; - pr "\n" - ); + print_trace_leave name ret may_set_error; + pr "\n"; (* Finish any closures not transferred to state machine. *) List.iter ( function @@ -624,7 +620,7 @@ let pr "\n" (* Print the trace when we enter a call with debugging enabled. *) - and print_trace_enter args optargs = + and print_trace_enter name args optargs may_set_error = pr " if_debug (h) {\n"; List.iter ( function @@ -644,7 +640,11 @@ let | Int64 _ | SizeT _ | SockAddrAndLen _ | UInt _ | UInt32 _ | UInt64 _ | UIntPtr _ -> () ) args; - pr " debug (h, \"enter:"; + if may_set_error then + pr " debug (h, \"enter:" + else ( + pr " debug_direct (h, \"nbd_%s\", \"enter:" name + ); List.iter ( function | Bool n -> pr " %s=%%s" n @@ -713,22 +713,27 @@ let ) args; pr " }\n" (* Print the trace when we leave a call with debugging enabled. *) - and print_trace_leave ret = + and print_trace_leave name ret may_set_error = pr " if_debug (h) {\n"; - (match errcode_of_ret ret with - | Some r -> - pr " if (ret == %s)\n" r; - | None -> assert false + if may_set_error then ( + (match errcode_of_ret ret with + | Some r -> + pr " if (ret == %s)\n" r; + | None -> assert false + ); + pr " debug (h, \"leave: error=\\\"%%s\\\"\", nbd_get_error ());\n"; + pr " else {\n"; + (match ret with + | RString -> + pr " char *ret_printable =\n"; + pr " nbd_internal_printable_string (ret);\n" + | _ -> () + ); + pr " debug (h, \"leave: ret=\" " + ) + else ( + pr " debug_direct (h, \"nbd_%s\", \"leave: ret=\" " name ); - pr " debug (h, \"leave: error=\\\"%%s\\\"\", nbd_get_error ());\n"; - pr " else {\n"; - (match ret with - | RString -> - pr " char *ret_printable =\n"; - pr " nbd_internal_printable_string (ret);\n" - | _ -> () - ); - pr " debug (h, \"leave: ret=\" "; (match ret with | RBool | RErr | RFd | RInt | REnum _ -> pr "\"%%d\", ret" | RInt64 | RCookie -> pr "\"%%\" PRIi64 \"\", ret" @@ -739,11 +744,13 @@ let | RUIntPtr -> pr "\"%%\" PRIuPTR, ret" ); pr ");\n"; - (match ret with - | RString -> pr " free (ret_printable);\n" - | _ -> () + if may_set_error then ( + (match ret with + | RString -> pr " free (ret_printable);\n" + | _ -> () + ); + pr " }\n"; ); - pr " }\n"; pr " }\n" in diff --git a/lib/debug.c b/lib/debug.c index b598ad3f..826e606d 100644 --- a/lib/debug.c +++ b/lib/debug.c @@ -1,5 +1,5 @@ /* NBD client library in userspace - * Copyright (C) 2013-2020 Red Hat Inc. + * Copyright (C) 2013-2022 Red Hat Inc. * * This library is free software; you can redistribute it and/or * modify it under the terms of the GNU Lesser General Public @@ -62,12 +62,12 @@ nbd_unlocked_set_debug_callback (struct nbd_handle *h, * all situations. */ void -nbd_internal_debug (struct nbd_handle *h, const char *fs, ...) +nbd_internal_debug (struct nbd_handle *h, const char *context, + const char *fs, ...) { int err, r; va_list args; char *msg = NULL; - const char *context; /* The debug() wrapper checks this, but check it again in case * something calls nbd_internal_debug directly. @@ -76,7 +76,8 @@ nbd_internal_debug (struct nbd_handle *h, const char *fs, ...) err = errno; - context = nbd_internal_get_error_context (); + if (context == NULL) + context = nbd_internal_get_error_context (); va_start (args, fs); r = vasprintf (&msg, fs, args); -- 2.37.2
So my feeling about this patch series: I don't understand why the first patch is necessary, _and_ I think it might be "dangerous" (for small values of dangerous). What happens if in future we add a new RStaticString API which returns a string that does need to be escaped? It should at least be documented that RStaticString must only return simple, printable strings. But ideally the first patch wouldn't exist and we could deal with any RStaticString API. Second patch is completely fine. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-p2v converts physical machines to virtual machines. Boot with a live CD or over the network (PXE) and turn machines into KVM guests. http://libguestfs.org/virt-v2v
On Sun, Sep 04, 2022 at 05:44:33PM +0100, Richard W.M. Jones wrote:
So my feeling about this patch series:
I don't understand why the first patch is necessary, _and_ I think it might be "dangerous" (for small values of dangerous).
What happens if in future we add a new RStaticString API which returns a string that does need to be escaped? It should at least be documented that RStaticString must only return simple, printable strings. But ideally the first patch wouldn't exist and we could deal with any RStaticString API.
At present, the only escaping we do is nbd_internal_printable_string(), which converts NULL to "NULL" (not relevant here; either may_set_error=true and we already filter out NULL as an error, or may_set_error=false and the result is guaranteed non-NULL), and which truncates strings longer than 512 bytes to avoid overlong logs. But RStaticString returns are going to be a compile-time constant string, and we aren't going to write a string that long that would need our current form of escaping.
Second patch is completely fine.
I had already pushed both patches. But if we revert the first one, using just the second, I was having difficulties making the generated api.c line up nicely. It was looking something like: if_debug (h) { char *ret_printable = nbd_internal_printable_string (ret); debug_direct (h, "nbd_get_tls", "leave: ret=" "%s", ret_printable ? ret_printable : ""); free (ret_printable); } where the detour through nbd_internal_printable_string() with its extra spacing wasn't making much sense compared to just printing it directly by removing the special handling for RStaticString in general. -- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3266 Virtualization: qemu.org | libvirt.org
On Mon, Sep 05, 2022 at 02:41:57PM -0500, Eric Blake wrote:
On Sun, Sep 04, 2022 at 05:44:33PM +0100, Richard W.M. Jones wrote:
So my feeling about this patch series:
I don't understand why the first patch is necessary, _and_ I think it might be "dangerous" (for small values of dangerous).
What happens if in future we add a new RStaticString API which returns a string that does need to be escaped? It should at least be documented that RStaticString must only return simple, printable strings. But ideally the first patch wouldn't exist and we could deal with any RStaticString API.
At present, the only escaping we do is nbd_internal_printable_string(), which converts NULL to "NULL" (not relevant here; either may_set_error=true and we already filter out NULL as an error, or may_set_error=false and the result is guaranteed non-NULL), and which truncates strings longer than 512 bytes to avoid overlong logs. But RStaticString returns are going to be a compile-time constant string, and we aren't going to write a string that long that would need our current form of escaping.
It actually hexdumps the buffer (which is a bit weird actually). So I think you're right here that printing it unconditionally is correct. Sorry for the noise!
Second patch is completely fine.
I had already pushed both patches. But if we revert the first one, using just the second, I was having difficulties making the generated api.c line up nicely. It was looking something like:
if_debug (h) { char *ret_printable = nbd_internal_printable_string (ret); debug_direct (h, "nbd_get_tls", "leave: ret=" "%s", ret_printable ? ret_printable : ""); free (ret_printable); }
where the detour through nbd_internal_printable_string() with its extra spacing wasn't making much sense compared to just printing it directly by removing the special handling for RStaticString in general.
Let's not worry, thanks. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com Fedora Windows cross-compiler. Compile Windows programs, test, and build Windows installers. Over 100 libraries supported. http://fedoraproject.org/wiki/MinGW
participants (2)
-
Eric Blake -
Richard W.M. Jones