[Qemu-devel] [PATCH 0/3] nbd-client: drop extra error noise

[Qemu-devel] [PATCH 0/3] nbd-client: drop extra error noise

[Vladimir Sementsov-Ogievskiy]

Hi all.

It was discussed, that error messages, produced by error_reprt_err's,
added in f140e300 are
1. not really needed
2. subject to race conditions

And it was decided to drop them (switch to trace-points), look thread
https://lists.gnu.org/archive/html/qemu-devel/2018-08/msg00833.html

So, I've also dropped error_report_err, added earlier in be41c100c0d
and later in 78a33ab5878.

Hmm, I've tried to run 83 iotest in a loop, and it didn't fail, even
before these patches.

Vladimir Sementsov-Ogievskiy (3):
  error: add error_get_hint
  nbd: publish _lookup functions
  block/nbd-client: use traces instead of noisy error_report_err

 include/block/nbd.h        |  5 +++++
 include/qapi/error.h       |  5 +++++
 nbd/nbd-internal.h         |  5 -----
 block/nbd-client.c         | 27 +++++++++++++++++++++++----
 util/error.c               |  5 +++++
 block/trace-events         |  4 ++++
 tests/qemu-iotests/083.out | 28 ----------------------------
 7 files changed, 42 insertions(+), 37 deletions(-)

-- 
2.18.0

[Qemu-devel] [PATCH 1/3] error: add error_get_hint

[Vladimir Sementsov-Ogievskiy]

Add a function to export error hint - a pair to error_get_pretty. It's
needed to handle errors by hand, where we can't just report it or
propagate.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 include/qapi/error.h | 5 +++++
 util/error.c         | 5 +++++
 2 files changed, 10 insertions(+)

diff --git a/include/qapi/error.h b/include/qapi/error.h
index 51b63dd4b5..ff2f61b877 100644
--- a/include/qapi/error.h
+++ b/include/qapi/error.h
@@ -139,6 +139,11 @@ typedef enum ErrorClass {
  */
 const char *error_get_pretty(const Error *err);
 
+/*
+ * Get @err's hint if any. Otherwise return NULL.
+ */
+const char *error_get_hint(const Error *err);
+
 /*
  * Get @err's error class.
  * Note: use of error classes other than ERROR_CLASS_GENERIC_ERROR is
diff --git a/util/error.c b/util/error.c
index b5ccbd8eac..e7cedd5c4a 100644
--- a/util/error.c
+++ b/util/error.c
@@ -223,6 +223,11 @@ const char *error_get_pretty(const Error *err)
     return err->msg;
 }
 
+const char *error_get_hint(const Error *err)
+{
+    return err->hint ? err->hint->str : NULL;
+}
+
 void error_report_err(Error *err)
 {
     error_report("%s", error_get_pretty(err));
-- 
2.18.0

Re: [Qemu-devel] [PATCH 1/3] error: add error_get_hint

[Eric Blake]

On 11/2/18 10:11 AM, Vladimir Sementsov-Ogievskiy wrote:
> Add a function to export error hint - a pair to error_get_pretty. It's
> needed to handle errors by hand, where we can't just report it or
> propagate.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>   include/qapi/error.h | 5 +++++
>   util/error.c         | 5 +++++
>   2 files changed, 10 insertions(+)

I'll have to see how this is used before agreeing to it, but the code 
itself is fine if the series does indeed warrant it.  I wouldn't mind 
Markus chiming in on the topic, either.

Reviewed-by: Eric Blake <eblake@redhat.com>

>   
> +const char *error_get_hint(const Error *err)
> +{
> +    return err->hint ? err->hint->str : NULL;
> +}
> +
>   void error_report_err(Error *err)
>   {
>       error_report("%s", error_get_pretty(err));
> 

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

[Qemu-devel] [PATCH 2/3] nbd: publish _lookup functions

[Vladimir Sementsov-Ogievskiy]

These functions are used for formatting pretty trace points. We are
going to add some in block/nbd-client, so, let's publish all these
functions at once. Note, that nbd_reply_type_lookup is already
published, and constants, "named" by these functions live in
include/block/nbd.h too.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 include/block/nbd.h | 5 +++++
 nbd/nbd-internal.h  | 5 -----
 2 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/include/block/nbd.h b/include/block/nbd.h
index 6a5bfe5d55..65402d3396 100644
--- a/include/block/nbd.h
+++ b/include/block/nbd.h
@@ -343,5 +343,10 @@ static inline bool nbd_reply_is_structured(NBDReply *reply)
 }
 
 const char *nbd_reply_type_lookup(uint16_t type);
+const char *nbd_opt_lookup(uint32_t opt);
+const char *nbd_rep_lookup(uint32_t rep);
+const char *nbd_info_lookup(uint16_t info);
+const char *nbd_cmd_lookup(uint16_t info);
+const char *nbd_err_lookup(int err);
 
 #endif
diff --git a/nbd/nbd-internal.h b/nbd/nbd-internal.h
index eeff78d3c9..f38be9ebaa 100644
--- a/nbd/nbd-internal.h
+++ b/nbd/nbd-internal.h
@@ -100,11 +100,6 @@ struct NBDTLSHandshakeData {
 
 void nbd_tls_handshake(QIOTask *task,
                        void *opaque);
-const char *nbd_opt_lookup(uint32_t opt);
-const char *nbd_rep_lookup(uint32_t rep);
-const char *nbd_info_lookup(uint16_t info);
-const char *nbd_cmd_lookup(uint16_t info);
-const char *nbd_err_lookup(int err);
 
 int nbd_drop(QIOChannel *ioc, size_t size, Error **errp);
 
-- 
2.18.0

Re: [Qemu-devel] [PATCH 2/3] nbd: publish _lookup functions

[Eric Blake]

On 11/2/18 10:11 AM, Vladimir Sementsov-Ogievskiy wrote:
> These functions are used for formatting pretty trace points. We are
> going to add some in block/nbd-client, so, let's publish all these
> functions at once. Note, that nbd_reply_type_lookup is already
> published, and constants, "named" by these functions live in
> include/block/nbd.h too.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>   include/block/nbd.h | 5 +++++
>   nbd/nbd-internal.h  | 5 -----
>   2 files changed, 5 insertions(+), 5 deletions(-)
> 
> diff --git a/include/block/nbd.h b/include/block/nbd.h
> index 6a5bfe5d55..65402d3396 100644
> --- a/include/block/nbd.h
> +++ b/include/block/nbd.h
> @@ -343,5 +343,10 @@ static inline bool nbd_reply_is_structured(NBDReply *reply)
>   }
>   
>   const char *nbd_reply_type_lookup(uint16_t type);
> +const char *nbd_opt_lookup(uint32_t opt);
> +const char *nbd_rep_lookup(uint32_t rep);
> +const char *nbd_info_lookup(uint16_t info);
> +const char *nbd_cmd_lookup(uint16_t info);
> +const char *nbd_err_lookup(int err);

Reviewed-by: Eric Blake <eblake@redhat.com>

Side note: We could even go further, and have code to auto-generate the 
tables; see how nbdkit did it:

https://github.com/libguestfs/nbdkit/commit/d198cf9c

But for now, the protocol doesn't grow all that frequently, so keeping 
the lists up to date by hand doesn't bother me.


-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

[Qemu-devel] [PATCH 3/3] block/nbd-client: use traces instead of noisy error_report_err

[Vladimir Sementsov-Ogievskiy]

Reduce extra noise of nbd-client, change 083 correspondingly.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 block/nbd-client.c         | 27 +++++++++++++++++++++++----
 block/trace-events         |  4 ++++
 tests/qemu-iotests/083.out | 28 ----------------------------
 3 files changed, 27 insertions(+), 32 deletions(-)

diff --git a/block/nbd-client.c b/block/nbd-client.c
index 9686ecbd5e..9b1dab6e5d 100644
--- a/block/nbd-client.c
+++ b/block/nbd-client.c
@@ -28,6 +28,8 @@
  */
 
 #include "qemu/osdep.h"
+
+#include "trace.h"
 #include "qapi/error.h"
 #include "nbd-client.h"
 
@@ -79,7 +81,9 @@ static coroutine_fn void nbd_read_reply_entry(void *opaque)
         assert(s->reply.handle == 0);
         ret = nbd_receive_reply(s->ioc, &s->reply, &local_err);
         if (local_err) {
-            error_report_err(local_err);
+            trace_nbd_read_reply_entry_fail(ret, error_get_pretty(local_err),
+                                            error_get_hint(local_err) ?: "");
+            error_free(local_err);
         }
         if (ret <= 0) {
             break;
@@ -771,7 +775,12 @@ static int nbd_co_request(BlockDriverState *bs, NBDRequest *request,
 
     ret = nbd_co_receive_return_code(client, request->handle, &local_err);
     if (local_err) {
-        error_report_err(local_err);
+        trace_nbd_co_request_fail(request->from, request->len, request->handle,
+                                  request->flags, request->type,
+                                  nbd_cmd_lookup(request->type),
+                                  ret, error_get_pretty(local_err),
+                                  error_get_hint(local_err) ?: "");
+        error_free(local_err);
     }
     return ret;
 }
@@ -802,7 +811,12 @@ int nbd_client_co_preadv(BlockDriverState *bs, uint64_t offset,
     ret = nbd_co_receive_cmdread_reply(client, request.handle, offset, qiov,
                                        &local_err);
     if (local_err) {
-        error_report_err(local_err);
+        trace_nbd_co_request_fail(request.from, request.len, request.handle,
+                                  request.flags, request.type,
+                                  nbd_cmd_lookup(request.type),
+                                  ret, error_get_pretty(local_err),
+                                  error_get_hint(local_err) ?: "");
+        error_free(local_err);
     }
     return ret;
 }
@@ -925,7 +939,12 @@ int coroutine_fn nbd_client_co_block_status(BlockDriverState *bs,
     ret = nbd_co_receive_blockstatus_reply(client, request.handle, bytes,
                                            &extent, &local_err);
     if (local_err) {
-        error_report_err(local_err);
+        trace_nbd_co_request_fail(request.from, request.len, request.handle,
+                                  request.flags, request.type,
+                                  nbd_cmd_lookup(request.type),
+                                  ret, error_get_pretty(local_err),
+                                  error_get_hint(local_err) ?: "");
+        error_free(local_err);
     }
     if (ret < 0) {
         return ret;
diff --git a/block/trace-events b/block/trace-events
index 3e8c47bb24..f518432300 100644
--- a/block/trace-events
+++ b/block/trace-events
@@ -156,3 +156,7 @@ nvme_cmd_map_qiov_iov(void *s, int i, void *page, int pages) "s %p iov[%d] %p pa
 
 # block/iscsi.c
 iscsi_xcopy(void *src_lun, uint64_t src_off, void *dst_lun, uint64_t dst_off, uint64_t bytes, int ret) "src_lun %p offset %"PRIu64" dst_lun %p offset %"PRIu64" bytes %"PRIu64" ret %d"
+
+# block/nbd-client.c
+nbd_read_reply_entry_fail(int ret, const char *err, const char *hint) "ret = %d, err: %s%s"
+nbd_co_request_fail(uint64_t from, uint32_t len, uint64_t handle, uint16_t flags, uint16_t type, const char *name, int ret, const char *err, const char *hint) "Request failed { .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64 ", .flags = 0x%" PRIx16 ", .type = %" PRIu16 " (%s) } ret = %d, err: %s%s"
diff --git a/tests/qemu-iotests/083.out b/tests/qemu-iotests/083.out
index f9af8bb691..7419722cd7 100644
--- a/tests/qemu-iotests/083.out
+++ b/tests/qemu-iotests/083.out
@@ -41,8 +41,6 @@ can't open device nbd+tcp://127.0.0.1:PORT/foo
 
 === Check disconnect after neg2 ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 === Check disconnect 8 neg2 ===
@@ -55,40 +53,30 @@ can't open device nbd+tcp://127.0.0.1:PORT/foo
 
 === Check disconnect before request ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 === Check disconnect after request ===
 
-Connection closed
 read failed: Input/output error
 
 === Check disconnect before reply ===
 
-Connection closed
 read failed: Input/output error
 
 === Check disconnect after reply ===
 
-Unexpected end-of-file before all bytes were read
 read failed: Input/output error
 
 === Check disconnect 4 reply ===
 
-Unexpected end-of-file before all bytes were read
-Connection closed
 read failed: Input/output error
 
 === Check disconnect 8 reply ===
 
-Unexpected end-of-file before all bytes were read
-Connection closed
 read failed: Input/output error
 
 === Check disconnect before data ===
 
-Unexpected end-of-file before all bytes were read
 read failed: Input/output error
 
 === Check disconnect after data ===
@@ -118,8 +106,6 @@ can't open device nbd+tcp://127.0.0.1:PORT/
 
 === Check disconnect after neg-classic ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 === Check disconnect before neg1 ===
@@ -164,8 +150,6 @@ can't open device nbd+unix:///foo?socket=TEST_DIR/nbd.sock
 
 === Check disconnect after neg2 ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 === Check disconnect 8 neg2 ===
@@ -178,40 +162,30 @@ can't open device nbd+unix:///foo?socket=TEST_DIR/nbd.sock
 
 === Check disconnect before request ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 === Check disconnect after request ===
 
-Connection closed
 read failed: Input/output error
 
 === Check disconnect before reply ===
 
-Connection closed
 read failed: Input/output error
 
 === Check disconnect after reply ===
 
-Unexpected end-of-file before all bytes were read
 read failed: Input/output error
 
 === Check disconnect 4 reply ===
 
-Unexpected end-of-file before all bytes were read
-Connection closed
 read failed: Input/output error
 
 === Check disconnect 8 reply ===
 
-Unexpected end-of-file before all bytes were read
-Connection closed
 read failed: Input/output error
 
 === Check disconnect before data ===
 
-Unexpected end-of-file before all bytes were read
 read failed: Input/output error
 
 === Check disconnect after data ===
@@ -241,8 +215,6 @@ can't open device nbd+unix:///?socket=TEST_DIR/nbd.sock
 
 === Check disconnect after neg-classic ===
 
-Unable to read from socket: Connection reset by peer
-Connection closed
 read failed: Input/output error
 
 *** done
-- 
2.18.0

Re: [Qemu-devel] [PATCH 3/3] block/nbd-client: use traces instead of noisy error_report_err

[Eric Blake]

On 11/2/18 10:11 AM, Vladimir Sementsov-Ogievskiy wrote:
> Reduce extra noise of nbd-client, change 083 correspondingly.

This says what, but not why. The details from the cover letter are 
important to include here, namely:

> It was discussed, that error messages, produced by error_reprt_err's,
> added in f140e300 are
> 1. not really needed
> 2. subject to race conditions
> 
> And it was decided to drop them (switch to trace-points), look thread
> https://lists.gnu.org/archive/html/qemu-devel/2018-08/msg00833.html
> 
> So, I've also dropped error_report_err, added earlier in be41c100c0d
> and later in 78a33ab5878.


> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>   block/nbd-client.c         | 27 +++++++++++++++++++++++----
>   block/trace-events         |  4 ++++
>   tests/qemu-iotests/083.out | 28 ----------------------------
>   3 files changed, 27 insertions(+), 32 deletions(-)
> 
> diff --git a/block/nbd-client.c b/block/nbd-client.c
> index 9686ecbd5e..9b1dab6e5d 100644
> --- a/block/nbd-client.c
> +++ b/block/nbd-client.c
> @@ -28,6 +28,8 @@
>    */
>   
>   #include "qemu/osdep.h"
> +
> +#include "trace.h"

There are probably other things worth tracing, but this is a decent 
start.  In particular, note the comment in nbd_parse_error_payload():

     /* TODO: Add a trace point to mention the server complaint */

> @@ -79,7 +81,9 @@ static coroutine_fn void nbd_read_reply_entry(void *opaque)
>           assert(s->reply.handle == 0);
>           ret = nbd_receive_reply(s->ioc, &s->reply, &local_err);
>           if (local_err) {
> -            error_report_err(local_err);
> +            trace_nbd_read_reply_entry_fail(ret, error_get_pretty(local_err),
> +                                            error_get_hint(local_err) ?: "");

I'm not sold on the error hint being useful in the trace message.  For 
that matter, even error_get_pretty() seems like it might be rather verbose.

I do see why you are trying it, though: in nbd/client.c, 
nbd_handle_reply_err(), we have:


     case NBD_REP_ERR_BLOCK_SIZE_REQD:
         error_setg(errp, "Server requires INFO_BLOCK_SIZE for option %" 
PRIu32
                    " (%s)", reply->option, nbd_opt_lookup(reply->option));
         break;

     default:
         error_setg(errp, "Unknown error code when asking for option %" 
PRIu32
                    " (%s)", reply->option, nbd_opt_lookup(reply->option));
         break;
     }

     if (msg) {
         error_append_hint(errp, "server reported: %s\n", msg);

That is, we are reporting our own error no matter what (because we don't 
trust the server to always give us something useful, especially since 
many non-qemu servers still don't take advantage of the free-form error 
message slot in the protocol), and append the server's message if 
present as a hint (as most times a server that uses it actually manages 
to report something that the end user may benefit from seeing).

But instead of trying to make all the tracepoints in block/nbd-client.c 
extract this information, we could just improve nbd/client.c to have a 
tracepoint for any server-received error message at the same point where 
it calls error_append_hint().

The end result will be the same: if you enable all nbd_* traces, you'll 
still get the server's error message.  At the same time, doing it as two 
separate traces in the two separate files means that you can have 
finer-grained selection of which traces to view, and that the code in 
nbd-client.c doesn't have to extract the hint, which means patch 1/3 
isn't important after all.

I'll post a counter-proposal patch along those lines.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

Re: [Qemu-devel] [PATCH 3/3] block/nbd-client: use traces instead of noisy error_report_err

[Eric Blake]

On 12/18/18 3:23 PM, Eric Blake wrote:
> On 11/2/18 10:11 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Reduce extra noise of nbd-client, change 083 correspondingly.
> 
> This says what, but not why. The details from the cover letter are 
> important to include here, namely:
> 
>> It was discussed, that error messages, produced by error_reprt_err's,
>> added in f140e300 are
>> 1. not really needed
>> 2. subject to race conditions
>>
>> And it was decided to drop them (switch to trace-points), look thread
>> https://lists.gnu.org/archive/html/qemu-devel/2018-08/msg00833.html
>>
>> So, I've also dropped error_report_err, added earlier in be41c100c0d
>> and later in 78a33ab5878.
> 

>> @@ -79,7 +81,9 @@ static coroutine_fn void nbd_read_reply_entry(void 
>> *opaque)
>>           assert(s->reply.handle == 0);
>>           ret = nbd_receive_reply(s->ioc, &s->reply, &local_err);
>>           if (local_err) {
>> -            error_report_err(local_err);
>> +            trace_nbd_read_reply_entry_fail(ret, 
>> error_get_pretty(local_err),
>> +                                            error_get_hint(local_err) 
>> ?: "");
> 
> I'm not sold on the error hint being useful in the trace message.  For 
> that matter, even error_get_pretty() seems like it might be rather verbose.
> 
> I do see why you are trying it, though: in nbd/client.c, 
> nbd_handle_reply_err(), we have:

Actually, on looking further, the ONLY use of error_append_hint() in 
nbd/client.c is when handling NBD_OPT_ which is synchronous when first 
establishing the connection; but all of the additions of trace_nbd_* 
calls in this file occur during transmission phase, where we don't have 
any hints appended.  I could NOT trigger any error path where a hint 
would be present in the first place (although I will admit that I may 
have missed a spot in my tracing).

> But instead of trying to make all the tracepoints in block/nbd-client.c 
> extract this information, we could just improve nbd/client.c to have a 
> tracepoint for any server-received error message at the same point where 
> it calls error_append_hint().
> 

This part is still true, even if it is no longer relevant to this patch.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

[Qemu-devel] ping Re: [PATCH 0/3] nbd-client: drop extra error noise

[Vladimir Sementsov-Ogievskiy]

ping

02.11.2018 18:11, Vladimir Sementsov-Ogievskiy wrote:
> Hi all.
> 
> It was discussed, that error messages, produced by error_reprt_err's,
> added in f140e300 are
> 1. not really needed
> 2. subject to race conditions
> 
> And it was decided to drop them (switch to trace-points), look thread
> https://lists.gnu.org/archive/html/qemu-devel/2018-08/msg00833.html
> 
> So, I've also dropped error_report_err, added earlier in be41c100c0d
> and later in 78a33ab5878.
> 
> Hmm, I've tried to run 83 iotest in a loop, and it didn't fail, even
> before these patches.
> 
> Vladimir Sementsov-Ogievskiy (3):
>    error: add error_get_hint
>    nbd: publish _lookup functions
>    block/nbd-client: use traces instead of noisy error_report_err
> 
>   include/block/nbd.h        |  5 +++++
>   include/qapi/error.h       |  5 +++++
>   nbd/nbd-internal.h         |  5 -----
>   block/nbd-client.c         | 27 +++++++++++++++++++++++----
>   util/error.c               |  5 +++++
>   block/trace-events         |  4 ++++
>   tests/qemu-iotests/083.out | 28 ----------------------------
>   7 files changed, 42 insertions(+), 37 deletions(-)
> 


-- 
Best regards,
Vladimir