1:10 p.m.
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
1:10 p.m.
New subject: [libnbd PATCH 1/2] debug: Change trace of RStaticString returns
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
1:10 p.m.
New subject: [libnbd PATCH 2/2] debug: Trace even may_set_error=false functions
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
11:44 a.m.
New subject: [libnbd PATCH 2/2] debug: Trace even may_set_error=false functions
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
2:41 p.m.
New subject: [libnbd PATCH 2/2] debug: Trace even may_set_error=false functions
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
2:48 p.m.
New subject: [libnbd PATCH 2/2] debug: Trace even may_set_error=false functions
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
812
days inactive
814
days old
5 comments
2 participants
participants (2)
-
Eric Blake -
Richard W.M. Jones