monitor: enable OOB by default

It was unclear before on what does the CLOSED event mean. Meanwhile we add a TODO to fix up the CLOSED event in the future when the in/out ports are different for a chardev.

CC Paolo Bonzini <[email protected]>

CC "Marc-André Lureau" <[email protected]>

CC Stefan Hajnoczi <[email protected]>

CC Markus Armbruster <[email protected]>

Signed-off-by Peter Xu <[email protected]>

---
 include/chardev/char.h | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)

include/chardev/char.h +3 -1

index 04de45795e..6f0576e214 100644
@@ -22,7 +22,16 @@ typedef enum {
     CHR_EVENT_OPENED, /* new connection established */
     CHR_EVENT_MUX_IN, /* mux-focus was set to this terminal */
     CHR_EVENT_MUX_OUT, /* mux-focus will move on */
-    CHR_EVENT_CLOSED /* connection closed */
+    CHR_EVENT_CLOSED /* connection closed.  NOTE: currently this event
+                      * is only bound to the read port of the chardev.
+                      * Normally the read port and write port of a

It was unclear before on what does the CLOSED event mean. Meanwhile we add a TODO to fix up the CLOSED event in the future when the in/out ports are different for a chardev.

CC Paolo Bonzini <[email protected]>

CC "Marc-André Lureau" <[email protected]>

CC Stefan Hajnoczi <[email protected]>

CC Markus Armbruster <[email protected]>

Signed-off-by Peter Xu <[email protected]>

---
 include/chardev/char.h | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)

Previously we clean up the queues when we got CLOSED event. It was used to make sure we won't send leftover replies/events of a old client to a new client. Now this patch does an extra operation to flush the response queue before cleaning up.

In most cases, a QMP session will be based on a bidirectional channel (a TCP port, for example, we read/write to the same socket handle), so in port and out port of the backend chardev are fundamentally the same port. In these cases, it does not really matter much on whether we'll flush the response queue since flushing should possibly fail

anyways (just imagine to write to a socket that has already closed). However there can be cases where in & out ports of the QMP monitor's backend chardev are separated. One true example:

cat $QMP_COMMANDS | qemu -qmp stdio ... | filter_commands

In this case, the backend is fd-typed, and it is connected to stdio where in port is stdin and out port is stdout. Now if we drop all the events on the response queue then filter_command process might miss some events that it might expect. The thing is that, when stdin closes, stdout might still be there alive!

In practice, I encountered a very strange SHUTDOWN event missing when

running test with iotest 087 with Out-Of-Band enabled. One condition could be this (after "quit" command is executed and QEMU quits the main loop):

1. [main thread] QEMU queues one SHUTDOWN event into response queue

2. "cat" terminates (to distinguish it from the animal, I quote it). Logically it can terminate even earlier, but let's just assume it's here.

3. [monitor iothread] QEMU reads EOF from stdin, which connects to the "cat" process

4. [monitor iothread] QEMU calls the CLOSED event hook for the monitor,

which will clean up the response queue of the monitor, then the SHUTDOWN event is dropped

5. [main thread] clean up the monitors in monitor_cleanup(), when

trying to flush pending responses, it sees nothing. SHUTDOWN is lost forever

Note that before the monitor iothread was introduced, step [4]/[5] could never happen since the main loop was the only place to detect the EOF event of stdin and run the CLOSED event hooks. Now things can happen in parallel in the iothread.

Without this patch, iotest 087 will have ~10% chance to miss the SHUTDOWN event and fail when with Out-Of-Band enabled:

087 8s ... - output mismatch (see 087.out.bad)

home/peterx/git/qemu/bin/tests/qemu-iotests/087.out.bad 2018-06-01 18:53:44.267840928 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/087.out 2018-06-01 18:44:22.378982462 +0800 +0 -1

@@ -8,7 +8,6 @@
 {"return": {}}
 {"error": {"class": "GenericError", "desc": "'node-name' must be specified for the root node"}}
 {"return": {}}
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false}}
 
 === Duplicate ID ===

This patch fixes the problem.

Fixes 6d2d563f8c ("qmp: cleanup qmp queues properly", 2018-03-27)

Suggested-by Markus Armbruster <[email protected]>

Signed-off-by Peter Xu <[email protected]>

Signed-off-by Peter Xu <[email protected]>

---
 monitor.c | 30 +++++++++++++++++++++++++-----
 1 file changed, 25 insertions(+), 5 deletions(-)

monitor.c +0 -0

index 6d0cec552e..e59d4f09ac 100644
@@ -512,20 +512,39 @@ struct QMPResponse {
 };
 typedef struct QMPResponse QMPResponse;
 

monitor.c +2 -1

+
 /*
  * Return one QMPResponse.  The response is only valid if
  * response.data is not NULL.
  */
-static QMPResponse monitor_qmp_response_pop_one(void)
+static QMPResponse monitor_qmp_response_pop(void)
 {
     Monitor *mon;
     QObject *data = NULL;

monitor.c +1 -1

@@ -539,7 +558,7 @@ static void monitor_qmp_bh_responder(void *opaque)
     QMPResponse response;
 
     while (true) {
-        response = monitor_qmp_response_pop_one();
+        response = monitor_qmp_response_pop();
         if (!response.data) {
             break;
         }

Quoted 10 lines · Peter Xu

Previously we clean up the queues when we got CLOSED event. It was used to make sure we won't send leftover replies/events of a old client to a new client. Now this patch does an extra operation to flush the response queue before cleaning up.

In most cases, a QMP session will be based on a bidirectional channel (a TCP port, for example, we read/write to the same socket handle), so in port and out port of the backend chardev are fundamentally the same port. In these cases, it does not really matter much on whether we'll flush the response queue since flushing should possibly fail

s/should possibly fail anyways/will fail anyway/

Quoted 3 lines

anyways (just imagine to write to a socket that has already closed). However there can be cases where in & out ports of the QMP monitor's backend chardev are separated. One true example:

Suggest to drop "true", or say "Here's an example".

Quoted 9 lines

cat $QMP_COMMANDS | qemu -qmp stdio ... | filter_commands

In this case, the backend is fd-typed, and it is connected to stdio where in port is stdin and out port is stdout. Now if we drop all the events on the response queue then filter_command process might miss some events that it might expect. The thing is that, when stdin closes, stdout might still be there alive!

In practice, I encountered a very strange SHUTDOWN event missing when

The event isn't strange, its missing is (sort of). Suggest to drop "very strange".

Quoted 3 lines

running test with iotest 087 with Out-Of-Band enabled. One condition could be this (after "quit" command is executed and QEMU quits the main loop):

"could be" suggests this may or may not demonstrate the loss of the event. Misleading. "Here's one of the ways this can happen" would be clearer.

Quoted 2 lines

1. [main thread] QEMU queues one SHUTDOWN event into response queue

s/one/a/

Quoted 4 lines

2. "cat" terminates (to distinguish it from the animal, I quote it). Logically it can terminate even earlier, but let's just assume it's here.

Suggest to drop the second sentence. You're describing one way for the bug to bite here, not all possible ways.

Quoted 3 lines

3. [monitor iothread] QEMU reads EOF from stdin, which connects to the "cat" process

Suggest "QEMU's monitor iothread reads".

Suggest to drop ", which connects...", because that should be obvious.

Quoted 1 line

4. [monitor iothread] QEMU calls the CLOSED event hook for the monitor,

"QEMU's monitor iothread" again.

Quoted 2 lines

which will clean up the response queue of the monitor, then the SHUTDOWN event is dropped

Suggest to say "destroy" instead of "clean up", to make perfectly clear that we're throwing away the queue.

Quoted 2 lines

5. [main thread] clean up the monitors in monitor_cleanup(), when

"QEMU's main thread cleans up the monitors in monitor_cleanup(). When"

Quoted 2 lines

trying to flush pending responses, it sees nothing. SHUTDOWN is lost forever

Missing a period.

Quoted 19 lines

Note that before the monitor iothread was introduced, step [4]/[5] could never happen since the main loop was the only place to detect the EOF event of stdin and run the CLOSED event hooks. Now things can happen in parallel in the iothread.

Without this patch, iotest 087 will have ~10% chance to miss the SHUTDOWN event and fail when with Out-Of-Band enabled:

087 8s ... - output mismatch (see 087.out.bad)

home/peterx/git/qemu/bin/tests/qemu-iotests/087.out.bad 2018-06-01 18:53:44.267840928 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/087.out 2018-06-01 18:44:22.378982462 +0800 +0 -1

@@ -8,7 +8,6 @@
 {"return": {}}
 {"error": {"class": "GenericError", "desc": "'node-name' must be specified for the root node"}}
 {"return": {}}
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false}}
 
 === Duplicate ID ===

home/peterx/git/qemu/bin/tests/qemu-iotests/087.out.bad 2018-06-01 18:53:44.267840928 +0800 line 56

Quoted 4 lines

home/peterx/git/qemu/bin/tests/qemu-iotests/087.out.bad 2018-06-01 18:53:44.267840928 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/087.out 2018-06-01 18:44:22.378982462 +0800 +0 -1

@@ -53,7 +52,6 @@
 {"return": {}}
 {"return": {}}
 {"return": {}}
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false}}

Suggest to indent the quoted diff a bit, so make it more obviously not part of the patch. In fact, git-am chokes on it for me.

Quoted 2 lines

This patch fixes the problem.

Quoted 5 lines

Fixes 6d2d563f8c ("qmp: cleanup qmp queues properly", 2018-03-27)

Suggested-by Markus Armbruster <[email protected]>

Signed-off-by Peter Xu <[email protected]>

Signed-off-by Peter Xu <[email protected]>

Don't let my nitpicking deceive you; this is a really nice commit message.

One more suggestion. Your first paragraph describes the solution. I like to start with the problem instead. More so when the problem description is long, as it is here, because by the time I'm done reading the problem, I'm prone to have forgotten the solution, and go "okay, and how's the patch addressing the problem?" But please use your judgement.

Quoted 13 lines

---
 monitor.c | 30 +++++++++++++++++++++++++-----
 1 file changed, 25 insertions(+), 5 deletions(-)

monitor.c +0 -0

index 6d0cec552e..e59d4f09ac 100644
@@ -512,20 +512,39 @@ struct QMPResponse {
 };
 typedef struct QMPResponse QMPResponse;
 

monitor.c struct QMPResponse { · line 524

Quoted 10 lines

monitor.c +10 -0

+static QObject *monitor_qmp_response_pop_one(Monitor *mon)
+{
+    QObject *data;
+
+    qemu_mutex_lock(&mon->qmp.qmp_queue_lock);
+    data = g_queue_pop_head(mon->qmp.qmp_responses);
+    qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
+
+    return data;
+}

Note for later: returns null only when the queue is empty (we never push null onto this queue).

monitor.c struct QMPResponse { · line 534

Quoted 10 lines

monitor.c +10 -0

+
+static void monitor_qmp_response_flush(Monitor *mon)
+{
+    QObject *data;
+
+    while ((data = monitor_qmp_response_pop_one(mon))) {
+        monitor_json_emitter_raw(mon, data);
+        qobject_unref(data);
+    }
+}

This flushes the queue to @mon. Good.

Quoted 10 lines

monitor.c +2 -1

+
 /*
  * Return one QMPResponse.  The response is only valid if
  * response.data is not NULL.
  */
-static QMPResponse monitor_qmp_response_pop_one(void)
+static QMPResponse monitor_qmp_response_pop(void)
 {
     Monitor *mon;
     QObject *data = NULL;

monitor.c static void monitor_qmp_response_flush(Monitor *mon) · line 552

Quoted 10 lines

monitor.c +1 -3

 
     qemu_mutex_lock(&monitor_lock);
     QTAILQ_FOREACH(mon, &mon_list, entry) {
-        qemu_mutex_lock(&mon->qmp.qmp_queue_lock);
-        data = g_queue_pop_head(mon->qmp.qmp_responses);
-        qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
+        data = monitor_qmp_response_pop_one(mon);
         if (data) {
             break;
         }

       }
       qemu_mutex_unlock(&monitor_lock);
       return (QMPResponse) { .mon = mon, .data = data };

}

Not this patch's fault, but this function gave me pause until I got the loop's purpose: the function returns a response from *any* monitor.

Moreover, your naming creates an inconsistency with monitor_qmp_requests_pop_one().

I append my attempt to make it easier to understand, and restore consistency. I guess I'd split it into a preparatory patch and a fixup for this one.

Quoted 4 lines

monitor.c +0 -0

@@ -539,7 +558,7 @@ static void monitor_qmp_bh_responder(void *opaque)
     QMPResponse response;
 

monitor.c static void monitor_qmp_event(void *opaque, int event) · line 4388

Quoted 11 lines

monitor.c +2 -1

     while (true) {
-        response = monitor_qmp_response_pop_one();
+        response = monitor_qmp_response_pop();
         if (!response.data) {
             break;
         }

@@ -4366,6 +4385,7 @@ static void monitor_qmp_event(void *opaque, int event)
         mon_refcount++;
         break;
     case CHR_EVENT_CLOSED:
+        monitor_qmp_response_flush(mon);

This wastes work in the common case when @mon's output fd has been closed already. I think that's just fine.

Quoted 4 lines

monitor.c +0 -0

         monitor_qmp_cleanup_queues(mon);
         json_message_parser_destroy(&mon->qmp.parser);
         json_message_parser_init(&mon->qmp.parser, handle_qmp_command);

monitor.c +0 -0

index e59d4f09ac..af28977549 100644

monitor.c +8 -10

  */
-static QMPResponse monitor_qmp_response_pop(void)
+static QMPResponse *monitor_qmp_response_pop_any(QMPResponse *response)
 {
     Monitor *mon;
     QObject *data = NULL;
 
     qemu_mutex_lock(&monitor_lock);
     QTAILQ_FOREACH(mon, &mon_list, entry) {
-        data = monitor_qmp_response_pop_one(mon);
+        data = monitor_qmp_requests_pop(mon);
         if (data) {
+            response->mon = mon;
+            response->data = data;
             break;
         }
     }
     qemu_mutex_unlock(&monitor_lock);
-    return (QMPResponse) { .mon = mon, .data = data };
+    return data ? response : NULL;
 }
 
 static void monitor_qmp_bh_responder(void *opaque)
 {
     QMPResponse response;
 
-    while (true) {
-        response = monitor_qmp_response_pop();
-        if (!response.data) {
-            break;
-        }
+    while (monitor_qmp_response_pop_any(&response)) {
         monitor_json_emitter_raw(response.mon, response.data);
         qobject_unref(response.data);
     }

@@ -4126,7 +4124,7 @@ static void monitor_qmp_dispatch_one(QMPRequest *req_obj)
  * when we process one request on a specific monitor, we put that
  * monitor to the end of mon_list queue.
  */
-static QMPRequest *monitor_qmp_requests_pop_one(void)
+static QMPRequest *monitor_qmp_requests_pop_any(void)
 {
     QMPRequest *req_obj = NULL;
     Monitor *mon;

@@ -4158,7 +4156,7 @@ static QMPRequest *monitor_qmp_requests_pop_one(void)
 
 static void monitor_qmp_bh_dispatcher(void *data)
 {
-    QMPRequest *req_obj = monitor_qmp_requests_pop_one();
+    QMPRequest *req_obj = monitor_qmp_requests_pop_any();
 
     if (req_obj) {
         trace_monitor_qmp_cmd_in_band(qobject_get_try_str(req_obj->id) ?: "");

On Fri, Jun 15, 2018 at 10:11:34AM +0200, Markus Armbruster wrote:

Quoted 8 lines

monitor.c +0 -0

index e59d4f09ac..af28977549 100644
@@ -512,7 +512,7 @@ struct QMPResponse {
 };
 typedef struct QMPResponse QMPResponse;
 

monitor.c struct QMPResponse { · line 515

Quoted 2 lines

monitor.c +1 -1

-static QObject *monitor_qmp_response_pop_one(Monitor *mon)
+static QObject *monitor_qmp_requests_pop(Monitor *mon)

I guess it's a typo; I'll keep the "response" word.

monitor.c static void monitor_qmp_response_flush(Monitor *mon) · line 530

Quoted 9 lines

monitor.c +1 -1

 {
     QObject *data;
 

@@ -527,41 +527,39 @@ static void monitor_qmp_response_flush(Monitor *mon)
 {
     QObject *data;
 
-    while ((data = monitor_qmp_response_pop_one(mon))) {
+    while ((data = monitor_qmp_requests_pop(mon))) {

Same here.

Quoted 5 lines

monitor.c +0 -0

         monitor_json_emitter_raw(mon, data);
         qobject_unref(data);
     }
 }
 

monitor.c static void monitor_qmp_response_flush(Monitor *mon) · line 538

Quoted 5 lines

monitor.c +2 -2

 /*
- * Return one QMPResponse.  The response is only valid if
- * response.data is not NULL.
+ * Pop a QMPResponse from any monitor's response queue into @response.
+ * Return NULL when all queues are empty, else @response.

I'll change the return value to a boolean directly if it's okay, since after all we'll pass the QMPResponse in now.

In my Out-Of-Band test, "check -qcow2 060" fail with this:

060 5s ... - output mismatch (see 060.out.bad)

home/peterx/git/qemu/bin/tests/qemu-iotests/060.out.bad 2018-06-15 08:33:09.679880113 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/060.out 2018-06-15 08:31:14.607411950 +0800 +1 -1

@@ -427,8 +427,8 @@
 QMP_VERSION
 {"return": {}}
 qcow2: Image is corrupt: L2 table offset 0x2a2a2a00 unaligned (L1 index: 0); further non-fatal corruption events will be suppressed
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_IMAGE_CORRUPTED", "data": {"device": "", "msg": "L2 table offset 0x2a2a2a0
 0 unaligned (L1 index: 0)", "node-name": "drive", "fatal": false}}
 read failed: Input/output error
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_IMAGE_CORRUPTED", "data": {"device": "", "msg": "L2 table offset 0x2a2a2a0
 0 unaligned (L1 index: 0)", "node-name": "drive", "fatal": false}}
 {"return": ""}

{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false}}
Failures: 060
Failed 1 of 1 tests

The order of the event and the in/out error line is swapped. I didn't dig up the reason, but AFAIU what we want to verify is the event rather than stderr. Let's drop the stderr line directly for this test.

Signed-off-by Peter Xu <[email protected]>

Signed-off-by Peter Xu <[email protected]>

Quoted 13 lines · Peter Xu

In my Out-Of-Band test, "check -qcow2 060" fail with this:

060 5s ... - output mismatch (see 060.out.bad)

home/peterx/git/qemu/bin/tests/qemu-iotests/060.out.bad 2018-06-15 08:33:09.679880113 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/060.out 2018-06-15 08:31:14.607411950 +0800 +1 -1

@@ -427,8 +427,8 @@
 QMP_VERSION
 {"return": {}}
 qcow2: Image is corrupt: L2 table offset 0x2a2a2a00 unaligned (L1 index: 0); further non-fatal corruption events will be suppressed
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_IMAGE_CORRUPTED", "data": {"device": "", "msg": "L2 table offset 0x2a2a2a0
 0 unaligned (L1 index: 0)", "node-name": "drive", "fatal": false}}
 read failed: Input/output error
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_IMAGE_CORRUPTED", "data": {"device": "", "msg": "L2 table offset 0x2a2a2a0

Quoted 6 lines

home/peterx/git/qemu/bin/tests/qemu-iotests/060.out.bad 2018-06-15 08:33:09.679880113 +0800 renamed from home/peterx/git/qemu/tests/qemu-iotests/060.out 2018-06-15 08:31:14.607411950 +0800 +0 -0

 0 unaligned (L1 index: 0)", "node-name": "drive", "fatal": false}}
 {"return": ""}

{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false}}
Failures: 060
Failed 1 of 1 tests

Please indent this diff; git-am chokes on it for me.

Quoted 8 lines

The order of the event and the in/out error line is swapped. I didn't dig up the reason, but AFAIU what we want to verify is the event rather than stderr. Let's drop the stderr line directly for this test.

Signed-off-by Peter Xu <[email protected]>

Signed-off-by Peter Xu <[email protected]>

Lose one S-o-b, please :)

docs/devel/qapi-code-gen.txt +0 -0

 If in doubt, do not implement OOB execution support.

docs/devel/qapi-code-gen.txt OOB command handlers must satisfy the following conditions:

Quoted 14 lines · Peter Xu

Out-Of-Band handlers need to protect shared state if there is any. Mention it in the document.

Suggested-by Markus Armbruster <[email protected]>

Signed-off-by Peter Xu <[email protected]>

---
 docs/devel/qapi-code-gen.txt | 3 +++
 1 file changed, 3 insertions(+)

docs/devel/qapi-code-gen.txt +0 -0

index 1366228b2a..bee9de35df 100644
@@ -680,6 +680,9 @@ OOB command handlers must satisfy the following conditions:

Under normal QMP command execution, the following apply to each command:

- They are executed in order,
- They run only in main thread of QEMU,
- They have the BQL taken during execution.

Not this patch's fault, but this sounds awkward. Perhaps "They run with the BQL held."

When a command is executed with OOB, the following changes occur:

- They can be completed before a pending in-band command,
- They run in a dedicated monitor thread,
- They do not take the BQL during execution.

"They run with the BQL not held".

OOB command handlers must satisfy the following conditions:

- It executes extremely fast,

"It terminates quickly"

- It does not take any lock, or, it can take very small locks if all critical regions also follow the rules for OOB command handler code,

"It takes only "fast" locks, i.e. all critical sections protected by any lock it takes also satisfy the conditions for OOB command handler code." Maybe make it the last item.

docs/devel/qapi-code-gen.txt OOB command handlers must satisfy the following conditions: · line 682

Quoted 3 lines

docs/devel/qapi-code-gen.txt +0 -0

 - It does not invoke system calls that may block,
 - It does not access guest RAM that may block when userfaultfd is
   enabled for postcopy live migration.

All these are corollaries of the first item. But that's okay.

docs/devel/qapi-code-gen.txt OOB command handlers must satisfy the following conditions: · line 685

Quoted 3 lines

docs/devel/qapi-code-gen.txt +3 -0

+- It needs to protect any shared state, since as long as a command
+  supports Out-Of-Band it means the handler can be run in parallel
+  with the same handler running in the other thread.

"in another thread"

Not just the same handler is a potential problem. Any code accessing shared state from another thread is.

"It needs" is not really a condition.

Perhaps we can make this a separate paragraph rather than an additional item:

The restrictions on locking limit access to shared state. Such access requires synchronization, but OOB commands can't take the BQL or any other "slow" lock.