Eric Blake
2022-Sep-03 18:10 UTC
[Libguestfs] [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
Eric Blake
2022-Sep-03 18:10 UTC
[Libguestfs] [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
Eric Blake
2022-Sep-03 18:10 UTC
[Libguestfs] [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