[Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

The following changes since commit 3f3285491dd52014852a56135c90e428c8b507ea:

  Merge remote-tracking branch 'remotes/jnsnow/tags/bitmaps-pull-request' into staging (2018-10-30 14:09:25 +0000)

are available in the Git repository at:

  git://repo.or.cz/qemu/armbru.git tags/pull-monitor-2018-10-30

for you to fetch changes up to 1a8de278dd3c93a7aa40f88486509fe0e2de04da:

  vl: Avoid crash when -mon is underspecified (2018-10-30 20:13:52 +0100)

----------------------------------------------------------------
Monitor patches for 2018-10-30

* Fix crash on shutdown with --daemonize
* Change out-of-band execution to stop reading instead of dropping
  commands
* Enable out-of-band execution by default
* Avoid crash when -mon lacks chardev=...

----------------------------------------------------------------
Eric Blake (1):
      vl: Avoid crash when -mon is underspecified

Peter Xu (5):
      monitor: Suspend monitor instead dropping commands
      monitor: remove "x-oob", turn oob on by default
      Revert "tests: Add parameter to qtest_init_without_qmp_handshake"
      tests: add oob functional test for test-qmp-cmds
      tests: qmp-test: add queue full test

Wolfgang Bumiller (2):
      monitor: guard iothread access by mon->use_io_thread
      monitor: delay monitor iothread creation

 docs/interop/qmp-spec.txt |   5 ++-
 include/monitor/monitor.h |   3 +-
 monitor.c                 | 111 +++++++++++++++++++++-------------------------
 qapi/misc.json            |  40 -----------------
 tests/libqtest.c          |  10 ++---
 tests/libqtest.h          |   4 +-
 tests/qmp-test.c          |  32 +++++++++++--
 tests/test-qmp-cmds.c     |  16 +++++++
 vl.c                      |   9 ++--
 9 files changed, 110 insertions(+), 120 deletions(-)

-- 
2.17.2

[Qemu-devel] [PULL 1/8] monitor: guard iothread access by mon->use_io_thread

[Markus Armbruster]

From: Wolfgang Bumiller <w.bumiller@proxmox.com>

monitor_resume() and monitor_suspend() both want to
"kick" the I/O thread if it is there, but in
monitor_suspend() lacked the use_io_thread flag condition.
This is required when we later only spawn the thread on
first use.

Signed-off-by: Wolfgang Bumiller <w.bumiller@proxmox.com>
Reviewed-by: Eric Blake <eblake@redhat.com>
Reviewed-by: Peter Xu <peterx@redhat.com>
Message-Id: <20180925081507.11873-2-w.bumiller@proxmox.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 monitor.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/monitor.c b/monitor.c
index 823b5a1099..66f149c1dc 100644
--- a/monitor.c
+++ b/monitor.c
@@ -4292,7 +4292,7 @@ int monitor_suspend(Monitor *mon)
 
     atomic_inc(&mon->suspend_cnt);
 
-    if (monitor_is_qmp(mon)) {
+    if (monitor_is_qmp(mon) && mon->use_io_thread) {
         /*
          * Kick I/O thread to make sure this takes effect.  It'll be
          * evaluated again in prepare() of the watch object.
-- 
2.17.2

[Qemu-devel] [PULL 2/8] monitor: delay monitor iothread creation

[Markus Armbruster]

From: Wolfgang Bumiller <w.bumiller@proxmox.com>

Commit d32749deb615 moved the call to monitor_init_globals()
to before os_daemonize(), making it an unsuitable place to
spawn the monitor iothread as it won't be inherited over the
fork() in os_daemonize().

We now spawn the thread the first time we instantiate a
monitor which actually has use_io_thread == true.
Instantiation of monitors happens only after os_daemonize().
We still need to create the qmp_dispatcher_bh when not using
iothreads, so this now still happens in
monitor_init_globals().

Signed-off-by: Wolfgang Bumiller <w.bumiller@proxmox.com>
Fixes: d32749deb615 ("monitor: move init global earlier")
Message-Id: <20180925081507.11873-3-w.bumiller@proxmox.com>
Reviewed-by: Eric Blake <eblake@redhat.com>
Reviewed-by: Peter Xu <peterx@redhat.com>
Tested-by: Peter Xu <peterx@redhat.com>
[This fixes a crash on shutdown with --daemonize]
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 monitor.c | 35 +++++++++++++++++++++--------------
 1 file changed, 21 insertions(+), 14 deletions(-)

diff --git a/monitor.c b/monitor.c
index 66f149c1dc..d39390c2f2 100644
--- a/monitor.c
+++ b/monitor.c
@@ -708,9 +708,14 @@ static void monitor_qapi_event_init(void)
 
 static void handle_hmp_command(Monitor *mon, const char *cmdline);
 
+static void monitor_iothread_init(void);
+
 static void monitor_data_init(Monitor *mon, bool skip_flush,
                               bool use_io_thread)
 {
+    if (use_io_thread && !mon_iothread) {
+        monitor_iothread_init();
+    }
     memset(mon, 0, sizeof(Monitor));
     qemu_mutex_init(&mon->mon_lock);
     qemu_mutex_init(&mon->qmp.qmp_queue_lock);
@@ -4461,15 +4466,6 @@ static AioContext *monitor_get_aio_context(void)
 static void monitor_iothread_init(void)
 {
     mon_iothread = iothread_create("mon_iothread", &error_abort);
-
-    /*
-     * The dispatcher BH must run in the main loop thread, since we
-     * have commands assuming that context.  It would be nice to get
-     * rid of those assumptions.
-     */
-    qmp_dispatcher_bh = aio_bh_new(iohandler_get_aio_context(),
-                                   monitor_qmp_bh_dispatcher,
-                                   NULL);
 }
 
 void monitor_init_globals(void)
@@ -4479,7 +4475,15 @@ void monitor_init_globals(void)
     sortcmdlist();
     qemu_mutex_init(&monitor_lock);
     qemu_mutex_init(&mon_fdsets_lock);
-    monitor_iothread_init();
+
+    /*
+     * The dispatcher BH must run in the main loop thread, since we
+     * have commands assuming that context.  It would be nice to get
+     * rid of those assumptions.
+     */
+    qmp_dispatcher_bh = aio_bh_new(iohandler_get_aio_context(),
+                                   monitor_qmp_bh_dispatcher,
+                                   NULL);
 }
 
 /* These functions just adapt the readline interface in a typesafe way.  We
@@ -4624,7 +4628,9 @@ void monitor_cleanup(void)
      * we need to unregister from chardev below in
      * monitor_data_destroy(), and chardev is not thread-safe yet
      */
-    iothread_stop(mon_iothread);
+    if (mon_iothread) {
+        iothread_stop(mon_iothread);
+    }
 
     /* Flush output buffers and destroy monitors */
     qemu_mutex_lock(&monitor_lock);
@@ -4639,9 +4645,10 @@ void monitor_cleanup(void)
     /* QEMUBHs needs to be deleted before destroying the I/O thread */
     qemu_bh_delete(qmp_dispatcher_bh);
     qmp_dispatcher_bh = NULL;
-
-    iothread_destroy(mon_iothread);
-    mon_iothread = NULL;
+    if (mon_iothread) {
+        iothread_destroy(mon_iothread);
+        mon_iothread = NULL;
+    }
 }
 
 QemuOptsList qemu_mon_opts = {
-- 
2.17.2

[Qemu-devel] [PULL 3/8] monitor: Suspend monitor instead dropping commands

[Markus Armbruster]

From: Peter Xu <peterx@redhat.com>

When a QMP client sends in-band commands more quickly that we can
process them, we can either queue them without limit (QUEUE), drop
commands when the queue is full (DROP), or suspend receiving commands
when the queue is full (SUSPEND).  None of them is ideal:

* QUEUE lets a misbehaving client make QEMU eat memory without bounds.
Not such a hot idea.

* With DROP, the client has to cope with dropped in-band commands.  To
inform the client, we send a COMMAND_DROPPED event then.  The event is
flawed by design in two ways: it's ambiguous (see commit d621cfe0a17),
and it brings back the "eat memory without bounds" problem.

* With SUSPEND, the client has to manage the flow of in-band commands to
keep the monitor available for out-of-band commands.

We currently DROP.  Switch to SUSPEND.

Managing the flow of in-band commands to keep the monitor available for
out-of-band commands isn't really hard: just count the number of
"outstanding" in-band commands (commands sent minus replies received),
and if it exceeds the limit, hold back additional ones until it drops
below the limit again.

Note that we need to be careful pairing the suspend with a resume, or
else the monitor will hang, possibly forever.  And here since we need to
make sure both:

     (1) popping request from the req queue, and
     (2) reading length of the req queue

will be in the same critical section, we let the pop function take the
corresponding queue lock when there is a request, then we release the
lock from the caller.

Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
Message-Id: <20181009062718.1914-2-peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 docs/interop/qmp-spec.txt |  5 ++--
 include/monitor/monitor.h |  2 ++
 monitor.c                 | 52 +++++++++++++++++----------------------
 qapi/misc.json            | 40 ------------------------------
 4 files changed, 28 insertions(+), 71 deletions(-)

diff --git a/docs/interop/qmp-spec.txt b/docs/interop/qmp-spec.txt
index 8f7da0245d..67e44a8120 100644
--- a/docs/interop/qmp-spec.txt
+++ b/docs/interop/qmp-spec.txt
@@ -130,8 +130,9 @@ to pass "id" with out-of-band commands.  Passing it with all commands
 is recommended for clients that accept capability "oob".
 
 If the client sends in-band commands faster than the server can
-execute them, the server will eventually drop commands to limit the
-queue length.  The sever sends event COMMAND_DROPPED then.
+execute them, the server will stop reading the requests from the QMP
+channel until the request queue length is reduced to an acceptable
+range.
 
 Only a few commands support out-of-band execution.  The ones that do
 have "allow-oob": true in output of query-qmp-schema.
diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h
index 6fd2c53b09..0c0a37d8cb 100644
--- a/include/monitor/monitor.h
+++ b/include/monitor/monitor.h
@@ -15,6 +15,8 @@ extern __thread Monitor *cur_mon;
 #define MONITOR_USE_PRETTY    0x08
 #define MONITOR_USE_OOB       0x10
 
+#define QMP_REQ_QUEUE_LEN_MAX 8
+
 bool monitor_cur_is_qmp(void);
 
 void monitor_init_globals(void);
diff --git a/monitor.c b/monitor.c
index d39390c2f2..9334867110 100644
--- a/monitor.c
+++ b/monitor.c
@@ -4109,8 +4109,12 @@ static void monitor_qmp_dispatch(Monitor *mon, QObject *req, QObject *id)
  * processing commands only on a very busy monitor.  To achieve that,
  * when we process one request on a specific monitor, we put that
  * monitor to the end of mon_list queue.
+ *
+ * Note: if the function returned with non-NULL, then the caller will
+ * be with mon->qmp.qmp_queue_lock held, and the caller is responsible
+ * to release it.
  */
-static QMPRequest *monitor_qmp_requests_pop_any(void)
+static QMPRequest *monitor_qmp_requests_pop_any_with_lock(void)
 {
     QMPRequest *req_obj = NULL;
     Monitor *mon;
@@ -4120,10 +4124,11 @@ static QMPRequest *monitor_qmp_requests_pop_any(void)
     QTAILQ_FOREACH(mon, &mon_list, entry) {
         qemu_mutex_lock(&mon->qmp.qmp_queue_lock);
         req_obj = g_queue_pop_head(mon->qmp.qmp_requests);
-        qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
         if (req_obj) {
+            /* With the lock of corresponding queue held */
             break;
         }
+        qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
     }
 
     if (req_obj) {
@@ -4142,30 +4147,34 @@ static QMPRequest *monitor_qmp_requests_pop_any(void)
 
 static void monitor_qmp_bh_dispatcher(void *data)
 {
-    QMPRequest *req_obj = monitor_qmp_requests_pop_any();
+    QMPRequest *req_obj = monitor_qmp_requests_pop_any_with_lock();
     QDict *rsp;
     bool need_resume;
+    Monitor *mon;
 
     if (!req_obj) {
         return;
     }
 
+    mon = req_obj->mon;
     /*  qmp_oob_enabled() might change after "qmp_capabilities" */
-    need_resume = !qmp_oob_enabled(req_obj->mon);
+    need_resume = !qmp_oob_enabled(mon) ||
+        mon->qmp.qmp_requests->length == QMP_REQ_QUEUE_LEN_MAX - 1;
+    qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
     if (req_obj->req) {
         trace_monitor_qmp_cmd_in_band(qobject_get_try_str(req_obj->id) ?: "");
-        monitor_qmp_dispatch(req_obj->mon, req_obj->req, req_obj->id);
+        monitor_qmp_dispatch(mon, req_obj->req, req_obj->id);
     } else {
         assert(req_obj->err);
         rsp = qmp_error_response(req_obj->err);
         req_obj->err = NULL;
-        monitor_qmp_respond(req_obj->mon, rsp, NULL);
+        monitor_qmp_respond(mon, rsp, NULL);
         qobject_unref(rsp);
     }
 
     if (need_resume) {
         /* Pairs with the monitor_suspend() in handle_qmp_command() */
-        monitor_resume(req_obj->mon);
+        monitor_resume(mon);
     }
     qmp_request_free(req_obj);
 
@@ -4173,8 +4182,6 @@ static void monitor_qmp_bh_dispatcher(void *data)
     qemu_bh_schedule(qmp_dispatcher_bh);
 }
 
-#define  QMP_REQ_QUEUE_LEN_MAX  (8)
-
 static void handle_qmp_command(void *opaque, QObject *req, Error *err)
 {
     Monitor *mon = opaque;
@@ -4216,28 +4223,14 @@ static void handle_qmp_command(void *opaque, QObject *req, Error *err)
     qemu_mutex_lock(&mon->qmp.qmp_queue_lock);
 
     /*
-     * If OOB is not enabled on the current monitor, we'll emulate the
-     * old behavior that we won't process the current monitor any more
-     * until it has responded.  This helps make sure that as long as
-     * OOB is not enabled, the server will never drop any command.
+     * Suspend the monitor when we can't queue more requests after
+     * this one.  Dequeuing in monitor_qmp_bh_dispatcher() will resume
+     * it.  Note that when OOB is disabled, we queue at most one
+     * command, for backward compatibility.
      */
-    if (!qmp_oob_enabled(mon)) {
+    if (!qmp_oob_enabled(mon) ||
+        mon->qmp.qmp_requests->length == QMP_REQ_QUEUE_LEN_MAX - 1) {
         monitor_suspend(mon);
-    } else {
-        /* Drop the request if queue is full. */
-        if (mon->qmp.qmp_requests->length >= QMP_REQ_QUEUE_LEN_MAX) {
-            qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
-            /*
-             * FIXME @id's scope is just @mon, and broadcasting it is
-             * wrong.  If another monitor's client has a command with
-             * the same ID in flight, the event will incorrectly claim
-             * that command was dropped.
-             */
-            qapi_event_send_command_dropped(id,
-                                            COMMAND_DROP_REASON_QUEUE_FULL);
-            qmp_request_free(req_obj);
-            return;
-        }
     }
 
     /*
@@ -4245,6 +4238,7 @@ static void handle_qmp_command(void *opaque, QObject *req, Error *err)
      * handled in time order.  Ownership for req_obj, req, id,
      * etc. will be delivered to the handler side.
      */
+    assert(mon->qmp.qmp_requests->length < QMP_REQ_QUEUE_LEN_MAX);
     g_queue_push_tail(mon->qmp.qmp_requests, req_obj);
     qemu_mutex_unlock(&mon->qmp.qmp_queue_lock);
 
diff --git a/qapi/misc.json b/qapi/misc.json
index 6c1c5c0a37..1cd9aa29a1 100644
--- a/qapi/misc.json
+++ b/qapi/misc.json
@@ -3438,46 +3438,6 @@
 ##
 { 'command': 'query-sev-capabilities', 'returns': 'SevCapability' }
 
-##
-# @CommandDropReason:
-#
-# Reasons that caused one command to be dropped.
-#
-# @queue-full: the command queue is full. This can only occur when
-#              the client sends a new non-oob command before the
-#              response to the previous non-oob command has been
-#              received.
-#
-# Since: 2.12
-##
-{ 'enum': 'CommandDropReason',
-  'data': [ 'queue-full' ] }
-
-##
-# @COMMAND_DROPPED:
-#
-# Emitted when a command is dropped due to some reason.  Commands can
-# only be dropped when the oob capability is enabled.
-#
-# @id: The dropped command's "id" field.
-# FIXME Broken by design.  Events are broadcast to all monitors.  If
-# another monitor's client has a command with the same ID in flight,
-# the event will incorrectly claim that command was dropped.
-#
-# @reason: The reason why the command is dropped.
-#
-# Since: 2.12
-#
-# Example:
-#
-# { "event": "COMMAND_DROPPED",
-#   "data": {"result": {"id": "libvirt-102",
-#                       "reason": "queue-full" } } }
-#
-##
-{ 'event': 'COMMAND_DROPPED' ,
-  'data': { 'id': 'any', 'reason': 'CommandDropReason' } }
-
 ##
 # @set-numa-node:
 #
-- 
2.17.2

[Qemu-devel] [PULL 4/8] monitor: remove "x-oob", turn oob on by default

[Markus Armbruster]

From: Peter Xu <peterx@redhat.com>

OOB commands were introduced in commit cf869d53172.  Unfortunately, we
ran into a regression, and had to disable them by default for 2.12
(commit be933ffc23).

  http://lists.gnu.org/archive/html/qemu-devel/2018-03/msg06231.html

The regression has since been fixed (commit 951702f39c7 "monitor: bind
dispatch bh to iohandler context").  Time to re-enable OOB.

This patch partly reverts be933ffc23 (monitor: new parameter "x-oob"),
and turns it on again for non-MUX QMPs.  Note that we can't enable
Out-Of-Band for monitors with MUX-typed chardev backends, because not
all the chardev frontends can run without main thread, or can run in
multiple threads.

Some trivial touch-up in the test code is required to make sure qmp-test
won't break.

Reviewed-by: Markus Armbruster <armbru@redhat.com>
Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
Message-Id: <20181009062718.1914-4-peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 include/monitor/monitor.h |  1 -
 monitor.c                 | 22 ++++++----------------
 tests/libqtest.c          |  2 +-
 tests/qmp-test.c          |  2 +-
 vl.c                      |  5 -----
 5 files changed, 8 insertions(+), 24 deletions(-)

diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h
index 0c0a37d8cb..c1b40a9cac 100644
--- a/include/monitor/monitor.h
+++ b/include/monitor/monitor.h
@@ -13,7 +13,6 @@ extern __thread Monitor *cur_mon;
 #define MONITOR_USE_READLINE  0x02
 #define MONITOR_USE_CONTROL   0x04
 #define MONITOR_USE_PRETTY    0x08
-#define MONITOR_USE_OOB       0x10
 
 #define QMP_REQ_QUEUE_LEN_MAX 8
 
diff --git a/monitor.c b/monitor.c
index 9334867110..431795d686 100644
--- a/monitor.c
+++ b/monitor.c
@@ -4554,19 +4554,12 @@ void monitor_init(Chardev *chr, int flags)
 {
     Monitor *mon = g_malloc(sizeof(*mon));
     bool use_readline = flags & MONITOR_USE_READLINE;
-    bool use_oob = flags & MONITOR_USE_OOB;
-
-    if (use_oob) {
-        if (CHARDEV_IS_MUX(chr)) {
-            error_report("Monitor out-of-band is not supported with "
-                         "MUX typed chardev backend");
-            exit(1);
-        }
-        if (use_readline) {
-            error_report("Monitor out-of-band is only supported by QMP");
-            exit(1);
-        }
-    }
+    /*
+     * Note: we can't enable Out-Of-Band for monitors with MUX-typed
+     * chardev backends, because not all the chardev frontends can run
+     * without main thread, or can run in multiple threads.
+     */
+    bool use_oob = (flags & MONITOR_USE_CONTROL) && !CHARDEV_IS_MUX(chr);
 
     monitor_data_init(mon, false, use_oob);
 
@@ -4659,9 +4652,6 @@ QemuOptsList qemu_mon_opts = {
         },{
             .name = "pretty",
             .type = QEMU_OPT_BOOL,
-        },{
-            .name = "x-oob",
-            .type = QEMU_OPT_BOOL,
         },
         { /* end of list */ }
     },
diff --git a/tests/libqtest.c b/tests/libqtest.c
index 44ce118cfc..90084522f6 100644
--- a/tests/libqtest.c
+++ b/tests/libqtest.c
@@ -227,7 +227,7 @@ QTestState *qtest_init_without_qmp_handshake(bool use_oob,
                                   "-display none "
                                   "%s", qemu_binary, socket_path,
                                   getenv("QTEST_LOG") ? "/dev/fd/2" : "/dev/null",
-                                  qmp_socket_path, use_oob ? ",x-oob=on" : "",
+                                  qmp_socket_path, "",
                                   extra_args ?: "");
         execlp("/bin/sh", "sh", "-c", command, NULL);
         exit(1);
diff --git a/tests/qmp-test.c b/tests/qmp-test.c
index 6c419f6023..030d813f77 100644
--- a/tests/qmp-test.c
+++ b/tests/qmp-test.c
@@ -116,7 +116,7 @@ static void test_qmp_protocol(void)
     g_assert(q);
     test_version(qdict_get(q, "version"));
     capabilities = qdict_get_qlist(q, "capabilities");
-    g_assert(capabilities && qlist_empty(capabilities));
+    g_assert(capabilities);
     qobject_unref(resp);
 
     /* Test valid command before handshake */
diff --git a/vl.c b/vl.c
index 1fcacc5caa..7d9bcf442e 100644
--- a/vl.c
+++ b/vl.c
@@ -2317,11 +2317,6 @@ static int mon_init_func(void *opaque, QemuOpts *opts, Error **errp)
     if (qemu_opt_get_bool(opts, "pretty", 0))
         flags |= MONITOR_USE_PRETTY;
 
-    /* OOB is off by default */
-    if (qemu_opt_get_bool(opts, "x-oob", 0)) {
-        flags |= MONITOR_USE_OOB;
-    }
-
     chardev = qemu_opt_get(opts, "chardev");
     chr = qemu_chr_find(chardev);
     if (chr == NULL) {
-- 
2.17.2

[Qemu-devel] [PULL 5/8] Revert "tests: Add parameter to qtest_init_without_qmp_handshake"

[Markus Armbruster]

From: Peter Xu <peterx@redhat.com>

This reverts commit ddee57e0176f6ab53b13c6c97605b62737a8fd7a.

Meanwhile, revert one line from fa198ad9bdef to make sure
qtest_init_without_qmp_handshake() will only pass in one parameter.

Reviewed-by: Markus Armbruster <armbru@redhat.com>
Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
Message-Id: <20181009062718.1914-5-peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 tests/libqtest.c | 10 ++++------
 tests/libqtest.h |  4 +---
 tests/qmp-test.c |  4 ++--
 3 files changed, 7 insertions(+), 11 deletions(-)

diff --git a/tests/libqtest.c b/tests/libqtest.c
index 90084522f6..48d710d89e 100644
--- a/tests/libqtest.c
+++ b/tests/libqtest.c
@@ -187,8 +187,7 @@ static const char *qtest_qemu_binary(void)
     return qemu_bin;
 }
 
-QTestState *qtest_init_without_qmp_handshake(bool use_oob,
-                                             const char *extra_args)
+QTestState *qtest_init_without_qmp_handshake(const char *extra_args)
 {
     QTestState *s;
     int sock, qmpsock, i;
@@ -221,13 +220,12 @@ QTestState *qtest_init_without_qmp_handshake(bool use_oob,
         command = g_strdup_printf("exec %s "
                                   "-qtest unix:%s,nowait "
                                   "-qtest-log %s "
-                                  "-chardev socket,path=%s,nowait,id=char0 "
-                                  "-mon chardev=char0,mode=control%s "
+                                  "-qmp unix:%s,nowait "
                                   "-machine accel=qtest "
                                   "-display none "
                                   "%s", qemu_binary, socket_path,
                                   getenv("QTEST_LOG") ? "/dev/fd/2" : "/dev/null",
-                                  qmp_socket_path, "",
+                                  qmp_socket_path,
                                   extra_args ?: "");
         execlp("/bin/sh", "sh", "-c", command, NULL);
         exit(1);
@@ -262,7 +260,7 @@ QTestState *qtest_init_without_qmp_handshake(bool use_oob,
 
 QTestState *qtest_init(const char *extra_args)
 {
-    QTestState *s = qtest_init_without_qmp_handshake(false, extra_args);
+    QTestState *s = qtest_init_without_qmp_handshake(extra_args);
     QDict *greeting;
 
     /* Read the QMP greeting and then do the handshake */
diff --git a/tests/libqtest.h b/tests/libqtest.h
index ed88ff99d5..96a6c01352 100644
--- a/tests/libqtest.h
+++ b/tests/libqtest.h
@@ -55,14 +55,12 @@ QTestState *qtest_init(const char *extra_args);
 
 /**
  * qtest_init_without_qmp_handshake:
- * @use_oob: true to have the server advertise OOB support
  * @extra_args: other arguments to pass to QEMU.  CAUTION: these
  * arguments are subject to word splitting and shell evaluation.
  *
  * Returns: #QTestState instance.
  */
-QTestState *qtest_init_without_qmp_handshake(bool use_oob,
-                                             const char *extra_args);
+QTestState *qtest_init_without_qmp_handshake(const char *extra_args);
 
 /**
  * qtest_quit:
diff --git a/tests/qmp-test.c b/tests/qmp-test.c
index 030d813f77..cc9907b525 100644
--- a/tests/qmp-test.c
+++ b/tests/qmp-test.c
@@ -108,7 +108,7 @@ static void test_qmp_protocol(void)
     QList *capabilities;
     QTestState *qts;
 
-    qts = qtest_init_without_qmp_handshake(false, common_args);
+    qts = qtest_init_without_qmp_handshake(common_args);
 
     /* Test greeting */
     resp = qtest_qmp_receive(qts);
@@ -219,7 +219,7 @@ static void test_qmp_oob(void)
     QList *capabilities;
     QString *qstr;
 
-    qts = qtest_init_without_qmp_handshake(true, common_args);
+    qts = qtest_init_without_qmp_handshake(common_args);
 
     /* Check the greeting message. */
     resp = qtest_qmp_receive(qts);
-- 
2.17.2

[Qemu-devel] [PULL 6/8] tests: add oob functional test for test-qmp-cmds

[Markus Armbruster]

From: Peter Xu <peterx@redhat.com>

Straightforward test just to let the test-qmp-cmds be complete.

Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
Message-Id: <20181009062718.1914-6-peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 tests/test-qmp-cmds.c | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)

diff --git a/tests/test-qmp-cmds.c b/tests/test-qmp-cmds.c
index 4ab2b6e5ce..481cb069ca 100644
--- a/tests/test-qmp-cmds.c
+++ b/tests/test-qmp-cmds.c
@@ -126,6 +126,21 @@ static void test_dispatch_cmd(void)
     qobject_unref(req);
 }
 
+static void test_dispatch_cmd_oob(void)
+{
+    QDict *req = qdict_new();
+    QDict *resp;
+
+    qdict_put_str(req, "exec-oob", "test-flags-command");
+
+    resp = qmp_dispatch(&qmp_commands, QOBJECT(req), true);
+    assert(resp != NULL);
+    assert(!qdict_haskey(resp, "error"));
+
+    qobject_unref(resp);
+    qobject_unref(req);
+}
+
 /* test commands that return an error due to invalid parameters */
 static void test_dispatch_cmd_failure(void)
 {
@@ -302,6 +317,7 @@ int main(int argc, char **argv)
     g_test_init(&argc, &argv, NULL);
 
     g_test_add_func("/qmp/dispatch_cmd", test_dispatch_cmd);
+    g_test_add_func("/qmp/dispatch_cmd_oob", test_dispatch_cmd_oob);
     g_test_add_func("/qmp/dispatch_cmd_failure", test_dispatch_cmd_failure);
     g_test_add_func("/qmp/dispatch_cmd_io", test_dispatch_cmd_io);
     g_test_add_func("/qmp/dispatch_cmd_success_response",
-- 
2.17.2

[Qemu-devel] [PULL 7/8] tests: qmp-test: add queue full test

[Markus Armbruster]

From: Peter Xu <peterx@redhat.com>

We'll need to include "monitor/monitor.h" for the queue length macro,
then we don't need to hard code it.

Suggested-by: Markus Armbruster <armbru@redhat.com>
Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
Message-Id: <20181009062718.1914-7-peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 tests/qmp-test.c | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/tests/qmp-test.c b/tests/qmp-test.c
index cc9907b525..6989acbca4 100644
--- a/tests/qmp-test.c
+++ b/tests/qmp-test.c
@@ -18,6 +18,7 @@
 #include "qapi/qmp/qlist.h"
 #include "qapi/qobject-input-visitor.h"
 #include "qapi/qmp/qstring.h"
+#include "monitor/monitor.h"
 
 const char common_args[] = "-nodefaults -machine none";
 
@@ -218,6 +219,8 @@ static void test_qmp_oob(void)
     const QListEntry *entry;
     QList *capabilities;
     QString *qstr;
+    gchar *id;
+    int i;
 
     qts = qtest_init_without_qmp_handshake(common_args);
 
@@ -272,6 +275,29 @@ static void test_qmp_oob(void)
     unblock_blocked_cmd();
     recv_cmd_id(qts, "blocks-2");
     recv_cmd_id(qts, "err-2");
+
+    /*
+     * Test queue full.  When that happens, the out-of-band command
+     * will only be able to be handled after the queue is shrinked, so
+     * it'll be processed only after one existing in-band command
+     * finishes.
+     */
+    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
+        id = g_strdup_printf("queue-blocks-%d", i);
+        send_cmd_that_blocks(qts, id);
+        g_free(id);
+    }
+    send_oob_cmd_that_fails(qts, "oob-1");
+    unblock_blocked_cmd();
+    recv_cmd_id(qts, "queue-blocks-1");
+    recv_cmd_id(qts, "oob-1");
+    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
+        unblock_blocked_cmd();
+        id = g_strdup_printf("queue-blocks-%d", i);
+        recv_cmd_id(qts, id);
+        g_free(id);
+    }
+
     cleanup_blocking_cmd();
 
     qtest_quit(qts);
-- 
2.17.2

[Qemu-devel] [PULL 8/8] vl: Avoid crash when -mon is underspecified

[Markus Armbruster]

From: Eric Blake <eblake@redhat.com>

A quick coredump on an incomplete command line:
./x86_64-softmmu/qemu-system-x86_64 -mon mode=control,pretty=on

 #0  0x00007ffff723d9e4 in g_str_hash () at /lib64/libglib-2.0.so.0
 #1  0x00007ffff723ce38 in g_hash_table_lookup () at /lib64/libglib-2.0.so.0
 #2  0x0000555555cc0073 in object_class_property_find (klass=0x5555566a94b0, name=0x0, errp=0x0) at qom/object.c:1135
 #3  0x0000555555cc004b in object_class_property_find (klass=0x5555566a9440, name=0x0, errp=0x0) at qom/object.c:1129
 #4  0x0000555555cbfe6e in object_property_find (obj=0x5555568348c0, name=0x0, errp=0x0) at qom/object.c:1080
 #5  0x0000555555cc183d in object_resolve_path_component (parent=0x5555568348c0, part=0x0) at qom/object.c:1762
 #6  0x0000555555d82071 in qemu_chr_find (name=0x0) at chardev/char.c:802
 #7  0x00005555559d77cb in mon_init_func (opaque=0x0, opts=0x5555566b65a0, errp=0x0) at vl.c:2291

Fix it to instead fail gracefully.

Signed-off-by: Eric Blake <eblake@redhat.com>
Message-Id: <20181023213600.364086-1-eblake@redhat.com>
Reviewed-by: Paolo Bonzini <pbonzini@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Reviewed-by: Peter Xu <peterx@redhat.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 vl.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/vl.c b/vl.c
index 7d9bcf442e..0a5cc9aa75 100644
--- a/vl.c
+++ b/vl.c
@@ -2318,6 +2318,10 @@ static int mon_init_func(void *opaque, QemuOpts *opts, Error **errp)
         flags |= MONITOR_USE_PRETTY;
 
     chardev = qemu_opt_get(opts, "chardev");
+    if (!chardev) {
+        error_report("chardev is required");
+        exit(1);
+    }
     chr = qemu_chr_find(chardev);
     if (chr == NULL) {
         error_setg(errp, "chardev \"%s\" not found", chardev);
-- 
2.17.2

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Maydell]

On 30 October 2018 at 19:16, Markus Armbruster <armbru@redhat.com> wrote:
> The following changes since commit 3f3285491dd52014852a56135c90e428c8b507ea:
>
>   Merge remote-tracking branch 'remotes/jnsnow/tags/bitmaps-pull-request' into staging (2018-10-30 14:09:25 +0000)
>
> are available in the Git repository at:
>
>   git://repo.or.cz/qemu/armbru.git tags/pull-monitor-2018-10-30
>
> for you to fetch changes up to 1a8de278dd3c93a7aa40f88486509fe0e2de04da:
>
>   vl: Avoid crash when -mon is underspecified (2018-10-30 20:13:52 +0100)
>
> ----------------------------------------------------------------
> Monitor patches for 2018-10-30
>
> * Fix crash on shutdown with --daemonize
> * Change out-of-band execution to stop reading instead of dropping
>   commands
> * Enable out-of-band execution by default
> * Avoid crash when -mon lacks chardev=...
>
> ----------------------------------------------------------------

Hi; I get test failures on FreeBSD host:

TEST: tests/qmp-test... (pid=18305)
  /sparc64/qmp/protocol:                                               OK
  /sparc64/qmp/oob:                                                    FAIL
GTester: last random seed: R02Se36038cab4c051a2cd47374ec9718e98
(pid=18337)
  /sparc64/qmp/preconfig:                                              OK
FAIL: tests/qmp-test

ERROR:tests/qmp-test.c:211:recv_cmd_id: assertion failed
(qdict_get_try_str(resp, "id") == id): ("oob-1" == "queue-blocks-1")
gmake: *** [/var/tmp/qemu-test.2n2tBU/tests/Makefile.include:805:
check-qtest-sparc] Error 1

and similarly with i386/qmp/oob and sparc/qmp/oob.

thanks
-- PMM

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

Peter Maydell <peter.maydell@linaro.org> writes:

> On 30 October 2018 at 19:16, Markus Armbruster <armbru@redhat.com> wrote:
>> The following changes since commit 3f3285491dd52014852a56135c90e428c8b507ea:
>>
>>   Merge remote-tracking branch 'remotes/jnsnow/tags/bitmaps-pull-request' into staging (2018-10-30 14:09:25 +0000)
>>
>> are available in the Git repository at:
>>
>>   git://repo.or.cz/qemu/armbru.git tags/pull-monitor-2018-10-30
>>
>> for you to fetch changes up to 1a8de278dd3c93a7aa40f88486509fe0e2de04da:
>>
>>   vl: Avoid crash when -mon is underspecified (2018-10-30 20:13:52 +0100)
>>
>> ----------------------------------------------------------------
>> Monitor patches for 2018-10-30
>>
>> * Fix crash on shutdown with --daemonize
>> * Change out-of-band execution to stop reading instead of dropping
>>   commands
>> * Enable out-of-band execution by default
>> * Avoid crash when -mon lacks chardev=...
>>
>> ----------------------------------------------------------------
>
> Hi; I get test failures on FreeBSD host:
>
> TEST: tests/qmp-test... (pid=18305)
>   /sparc64/qmp/protocol:                                               OK
>   /sparc64/qmp/oob:                                                    FAIL
> GTester: last random seed: R02Se36038cab4c051a2cd47374ec9718e98
> (pid=18337)
>   /sparc64/qmp/preconfig:                                              OK
> FAIL: tests/qmp-test
>
> ERROR:tests/qmp-test.c:211:recv_cmd_id: assertion failed
> (qdict_get_try_str(resp, "id") == id): ("oob-1" == "queue-blocks-1")
> gmake: *** [/var/tmp/qemu-test.2n2tBU/tests/Makefile.include:805:
> check-qtest-sparc] Error 1
>
> and similarly with i386/qmp/oob and sparc/qmp/oob.

I haven't been able to reproduce, yet.  I'm going to respin with fewer
patches, to get the other stuff in while I debug.

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Tue, Nov 06, 2018 at 04:56:51PM +0100, Markus Armbruster wrote:
> Peter Maydell <peter.maydell@linaro.org> writes:
> 
> > On 30 October 2018 at 19:16, Markus Armbruster <armbru@redhat.com> wrote:
> >> The following changes since commit 3f3285491dd52014852a56135c90e428c8b507ea:
> >>
> >>   Merge remote-tracking branch 'remotes/jnsnow/tags/bitmaps-pull-request' into staging (2018-10-30 14:09:25 +0000)
> >>
> >> are available in the Git repository at:
> >>
> >>   git://repo.or.cz/qemu/armbru.git tags/pull-monitor-2018-10-30
> >>
> >> for you to fetch changes up to 1a8de278dd3c93a7aa40f88486509fe0e2de04da:
> >>
> >>   vl: Avoid crash when -mon is underspecified (2018-10-30 20:13:52 +0100)
> >>
> >> ----------------------------------------------------------------
> >> Monitor patches for 2018-10-30
> >>
> >> * Fix crash on shutdown with --daemonize
> >> * Change out-of-band execution to stop reading instead of dropping
> >>   commands
> >> * Enable out-of-band execution by default
> >> * Avoid crash when -mon lacks chardev=...
> >>
> >> ----------------------------------------------------------------
> >
> > Hi; I get test failures on FreeBSD host:
> >
> > TEST: tests/qmp-test... (pid=18305)
> >   /sparc64/qmp/protocol:                                               OK
> >   /sparc64/qmp/oob:                                                    FAIL
> > GTester: last random seed: R02Se36038cab4c051a2cd47374ec9718e98
> > (pid=18337)
> >   /sparc64/qmp/preconfig:                                              OK
> > FAIL: tests/qmp-test
> >
> > ERROR:tests/qmp-test.c:211:recv_cmd_id: assertion failed
> > (qdict_get_try_str(resp, "id") == id): ("oob-1" == "queue-blocks-1")
> > gmake: *** [/var/tmp/qemu-test.2n2tBU/tests/Makefile.include:805:
> > check-qtest-sparc] Error 1
> >
> > and similarly with i386/qmp/oob and sparc/qmp/oob.
> 
> I haven't been able to reproduce, yet.  I'm going to respin with fewer
> patches, to get the other stuff in while I debug.

Strange, "make check -j8" failed on my hosts (I tried two) with either
Markus's pull tree or qemu master:

hw/core/ptimer.o: In function `timer_new_tl':
/home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
collect2: error: ld returned 1 exit status
make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1

Is that only happening on my hosts?

And I can't reproduce the error too by only running the standalone
qmp-test.

Regaring to the test failure reported - when I saw that I thought
about the patch "monitor: resume the monitor earlier if needed" in my
series since that seems to have the possibility to bring such an
uncertainty, though I noticed that Markus has already removed that
patch from the pull.

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Maydell]

On 7 November 2018 at 02:56, Peter Xu <peterx@redhat.com> wrote:
> Strange, "make check -j8" failed on my hosts (I tried two) with either
> Markus's pull tree or qemu master:
>
> hw/core/ptimer.o: In function `timer_new_tl':
> /home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
> collect2: error: ld returned 1 exit status
> make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1
>
> Is that only happening on my hosts?

Commit 89a603a0c80ae3 changed things so that there is no
timer_new_tl() or timer_init_tl() any more, so if you have
an object file that's referring to it then it's probably
stale. Try a make clean.

thanks
-- PMM

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Eric Blake]

On 11/7/18 5:21 AM, Peter Maydell wrote:
> On 7 November 2018 at 02:56, Peter Xu <peterx@redhat.com> wrote:
>> Strange, "make check -j8" failed on my hosts (I tried two) with either
>> Markus's pull tree or qemu master:
>>
>> hw/core/ptimer.o: In function `timer_new_tl':
>> /home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
>> collect2: error: ld returned 1 exit status
>> make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1
>>
>> Is that only happening on my hosts?
> 
> Commit 89a603a0c80ae3 changed things so that there is no
> timer_new_tl() or timer_init_tl() any more, so if you have
> an object file that's referring to it then it's probably
> stale. Try a make clean.

I ran into it as well:
https://lists.gnu.org/archive/html/qemu-devel/2018-11/msg00876.html

Wonder what makefile dependency we are missing that is resulting in 
stale .o files being picked up?

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

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Wed, Nov 07, 2018 at 11:21:32AM +0000, Peter Maydell wrote:
> On 7 November 2018 at 02:56, Peter Xu <peterx@redhat.com> wrote:
> > Strange, "make check -j8" failed on my hosts (I tried two) with either
> > Markus's pull tree or qemu master:
> >
> > hw/core/ptimer.o: In function `timer_new_tl':
> > /home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
> > collect2: error: ld returned 1 exit status
> > make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1
> >
> > Is that only happening on my hosts?
> 
> Commit 89a603a0c80ae3 changed things so that there is no
> timer_new_tl() or timer_init_tl() any more, so if you have
> an object file that's referring to it then it's probably
> stale. Try a make clean.

Yeh it worked for me, thanks Peter.

Though after running a few more rounds of "configure --enable-debug &&
make check -j8" I still cannot see anything wrong with Markus's tree.
I'll see whether there's any news from Markus and then I'll consider
whether I should install a FreeBSD.

Regards,

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Thu, Nov 08, 2018 at 10:44:06AM +0800, Peter Xu wrote:
> On Wed, Nov 07, 2018 at 11:21:32AM +0000, Peter Maydell wrote:
> > On 7 November 2018 at 02:56, Peter Xu <peterx@redhat.com> wrote:
> > > Strange, "make check -j8" failed on my hosts (I tried two) with either
> > > Markus's pull tree or qemu master:
> > >
> > > hw/core/ptimer.o: In function `timer_new_tl':
> > > /home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
> > > collect2: error: ld returned 1 exit status
> > > make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1
> > >
> > > Is that only happening on my hosts?
> > 
> > Commit 89a603a0c80ae3 changed things so that there is no
> > timer_new_tl() or timer_init_tl() any more, so if you have
> > an object file that's referring to it then it's probably
> > stale. Try a make clean.
> 
> Yeh it worked for me, thanks Peter.
> 
> Though after running a few more rounds of "configure --enable-debug &&
> make check -j8" I still cannot see anything wrong with Markus's tree.
> I'll see whether there's any news from Markus and then I'll consider
> whether I should install a FreeBSD.

I reproduced the error with a FreeBSD guest and this change (which
possibly can be squashed into "tests: qmp-test: add queue full test")
worked for me:

diff --git a/tests/qmp-test.c b/tests/qmp-test.c
index 6989acbca4..83f353db4f 100644
--- a/tests/qmp-test.c
+++ b/tests/qmp-test.c
@@ -281,8 +281,15 @@ static void test_qmp_oob(void)
      * will only be able to be handled after the queue is shrinked, so
      * it'll be processed only after one existing in-band command
      * finishes.
+     *
+     * NOTE: we need to feed the queue with one extra request to make
+     * sure it'll be stuck since when we have sent the Nth request
+     * it's possible that we have already popped and processing the
+     * 1st request so the Nth request (which could potentially be the
+     * [N-1]th element on the queue) might not trigger the
+     * monitor-full condition deterministically.
      */
-    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
+    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
         id = g_strdup_printf("queue-blocks-%d", i);
         send_cmd_that_blocks(qts, id);
         g_free(id);
@@ -291,7 +298,7 @@ static void test_qmp_oob(void)
     unblock_blocked_cmd();
     recv_cmd_id(qts, "queue-blocks-1");
     recv_cmd_id(qts, "oob-1");
-    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
+    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
         unblock_blocked_cmd();
         id = g_strdup_printf("queue-blocks-%d", i);
         recv_cmd_id(qts, id);

So the problem here is that the queue-block-N command might not really
suspend the monitor everytime if we already popped the 1st request,
which will let the N-th request to be (N-1)th, then the parser will
continue to eat the oob command and it could "preempt" the previous
commands.

Maybe FreeBSD is scheduling the threads in some pattern so it happens
only on FreeBSD and very constantly, but anyway it should be a general
fix to the test program.

Regards,

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Mon, Nov 19, 2018 at 02:17:27PM +0800, Peter Xu wrote:
> On Thu, Nov 08, 2018 at 10:44:06AM +0800, Peter Xu wrote:
> > On Wed, Nov 07, 2018 at 11:21:32AM +0000, Peter Maydell wrote:
> > > On 7 November 2018 at 02:56, Peter Xu <peterx@redhat.com> wrote:
> > > > Strange, "make check -j8" failed on my hosts (I tried two) with either
> > > > Markus's pull tree or qemu master:
> > > >
> > > > hw/core/ptimer.o: In function `timer_new_tl':
> > > > /home/xz/git/qemu/include/qemu/timer.h:536: undefined reference to `timer_init_tl'
> > > > collect2: error: ld returned 1 exit status
> > > > make: *** [/home/xz/git/qemu/rules.mak:124: tests/ptimer-test] Error 1
> > > >
> > > > Is that only happening on my hosts?
> > > 
> > > Commit 89a603a0c80ae3 changed things so that there is no
> > > timer_new_tl() or timer_init_tl() any more, so if you have
> > > an object file that's referring to it then it's probably
> > > stale. Try a make clean.
> > 
> > Yeh it worked for me, thanks Peter.
> > 
> > Though after running a few more rounds of "configure --enable-debug &&
> > make check -j8" I still cannot see anything wrong with Markus's tree.
> > I'll see whether there's any news from Markus and then I'll consider
> > whether I should install a FreeBSD.
> 
> I reproduced the error with a FreeBSD guest and this change (which
> possibly can be squashed into "tests: qmp-test: add queue full test")
> worked for me:
> 
> diff --git a/tests/qmp-test.c b/tests/qmp-test.c
> index 6989acbca4..83f353db4f 100644
> --- a/tests/qmp-test.c
> +++ b/tests/qmp-test.c
> @@ -281,8 +281,15 @@ static void test_qmp_oob(void)
>       * will only be able to be handled after the queue is shrinked, so
>       * it'll be processed only after one existing in-band command
>       * finishes.
> +     *
> +     * NOTE: we need to feed the queue with one extra request to make
> +     * sure it'll be stuck since when we have sent the Nth request
> +     * it's possible that we have already popped and processing the
> +     * 1st request so the Nth request (which could potentially be the
> +     * [N-1]th element on the queue) might not trigger the
> +     * monitor-full condition deterministically.
>       */
> -    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> +    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>          id = g_strdup_printf("queue-blocks-%d", i);
>          send_cmd_that_blocks(qts, id);
>          g_free(id);
> @@ -291,7 +298,7 @@ static void test_qmp_oob(void)
>      unblock_blocked_cmd();
>      recv_cmd_id(qts, "queue-blocks-1");
>      recv_cmd_id(qts, "oob-1");
> -    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> +    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>          unblock_blocked_cmd();
>          id = g_strdup_printf("queue-blocks-%d", i);
>          recv_cmd_id(qts, id);
> 
> So the problem here is that the queue-block-N command might not really
> suspend the monitor everytime if we already popped the 1st request,
> which will let the N-th request to be (N-1)th, then the parser will
> continue to eat the oob command and it could "preempt" the previous
> commands.
> 
> Maybe FreeBSD is scheduling the threads in some pattern so it happens
> only on FreeBSD and very constantly, but anyway it should be a general
> fix to the test program.

Markus, do you want me to repost a new version with this change?  Is
it still possible to have the oob-default series for 3.1?

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

Peter Xu <peterx@redhat.com> writes:

> On Mon, Nov 19, 2018 at 02:17:27PM +0800, Peter Xu wrote:
>> I reproduced the error with a FreeBSD guest and this change (which
>> possibly can be squashed into "tests: qmp-test: add queue full test")
>> worked for me:
>> 
>> diff --git a/tests/qmp-test.c b/tests/qmp-test.c
>> index 6989acbca4..83f353db4f 100644
>> --- a/tests/qmp-test.c
>> +++ b/tests/qmp-test.c
>> @@ -281,8 +281,15 @@ static void test_qmp_oob(void)
>>       * will only be able to be handled after the queue is shrinked, so
>>       * it'll be processed only after one existing in-band command
>>       * finishes.
>> +     *
>> +     * NOTE: we need to feed the queue with one extra request to make
>> +     * sure it'll be stuck since when we have sent the Nth request
>> +     * it's possible that we have already popped and processing the
>> +     * 1st request so the Nth request (which could potentially be the
>> +     * [N-1]th element on the queue) might not trigger the
>> +     * monitor-full condition deterministically.
>>       */
>> -    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
>> +    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>>          id = g_strdup_printf("queue-blocks-%d", i);
>>          send_cmd_that_blocks(qts, id);
>>          g_free(id);
>> @@ -291,7 +298,7 @@ static void test_qmp_oob(void)
>>      unblock_blocked_cmd();
>>      recv_cmd_id(qts, "queue-blocks-1");
>>      recv_cmd_id(qts, "oob-1");
>> -    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
>> +    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>>          unblock_blocked_cmd();
>>          id = g_strdup_printf("queue-blocks-%d", i);
>>          recv_cmd_id(qts, id);
>> 
>> So the problem here is that the queue-block-N command might not really
>> suspend the monitor everytime if we already popped the 1st request,
>> which will let the N-th request to be (N-1)th, then the parser will
>> continue to eat the oob command and it could "preempt" the previous
>> commands.
>> 
>> Maybe FreeBSD is scheduling the threads in some pattern so it happens
>> only on FreeBSD and very constantly, but anyway it should be a general
>> fix to the test program.

I feel particularly dense right now, and need a more detailed analysis
to understand.  Let me try.

Here's what the test does before your fix

    Send QMP_REQ_QUEUE_LEN_MAX "blocking" in-band commands
    queue-blocks-1, queue-blocks-2, ...  "Blocking" means the command
    blocks until we explicitly unblock it.

    Send an out-of-band command oob-1.

    Unblock queue-blocks-1.

    Receive response to queue-blocks-1.

    Receive response to oob-1.

    Unblock queue-blocks-2, receive response
    ...

Here's what test test expects QEMU to do:

    In I/O thread:

        Receive and queue queue-blocks-1, ...

        Queue is full, stop receiving commands.

    In main thread:

        Dequeue queue-blocks-1.

        Execute queue-blocks-1, block for a while, finish and send
        response.

    In I/O thread:

        Queue is no longer full, resume receiving commands.

        Receive and execute oob-1, send response

    In main thread:

        Dequeue queue-blocks-2, execute, block for a while, finish and
        send response.
        ...

No good because the two threads race.  On my Linux box the test passes.
Let's have a closer look how it does that.  The appended patch that adds
another tracepoint.  With tracepoints monitor_* and handle_qmp_command
enabled, I get:

    19271@1542641581.372890:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}

I/O thread receives and queues queue-blocks-1.

    19271@1542641581.372954:monitor_qmp_cmd_in_band queue-blocks-1

Main thread dequeues qemu-blocks-1 and starts executing it.

We already lost: the queue won't actually fill up.  The test passes
anyway, but it doesn't actually test "queue full".  But why does it
pass?  Let's see.

    19271@1542641581.373211:monitor_qmp_respond queue-blocks-1

Main thread sends response to queue-blocks-1.  This means queue-blocks-1
has been unblocked already.  This is possible, because qmp-test sends
all the commands and then immediately unblocks queue-blocks-1, and the
main thread can win the race with the I/O thread.

    19271@1542641581.373826:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.373864:monitor_qmp_cmd_in_band queue-blocks-2
    19271@1542641581.374575:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.375344:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.376162:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.376996:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.377790:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
    19271@1542641581.378562:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}

I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.

    19271@1542641581.378796:handle_qmp_command mon 0x563e19be4e80 req: {"exec-oob": "migrate-pause"}
    19271@1542641581.378800:monitor_qmp_cmd_out_of_band oob-1
    19271@1542641581.378823:monitor_qmp_respond oob-1

I/O thread receives, executes and responds to oob-1.

    19271@1542641581.379197:monitor_qmp_respond queue-blocks-2
    19271@1542641581.379228:monitor_qmp_cmd_in_band queue-blocks-3
    19271@1542641581.379435:monitor_qmp_respond queue-blocks-3
    19271@1542641581.379477:monitor_qmp_cmd_in_band queue-blocks-4
    19271@1542641581.379597:monitor_qmp_respond queue-blocks-4
    19271@1542641581.379621:monitor_qmp_cmd_in_band queue-blocks-5
    19271@1542641581.379800:monitor_qmp_respond queue-blocks-5
    19271@1542641581.379824:monitor_qmp_cmd_in_band queue-blocks-6
    19271@1542641581.379953:monitor_qmp_respond queue-blocks-6
    19271@1542641581.379992:monitor_qmp_cmd_in_band queue-blocks-7
    19271@1542641581.380132:monitor_qmp_respond queue-blocks-7
    19271@1542641581.380170:monitor_qmp_cmd_in_band queue-blocks-8
    19271@1542641581.380283:monitor_qmp_respond queue-blocks-8

Main thread dequeues, executes and responds to queue-blocks-2,
... queue-blocks-8.

If I make the main thread lose the race by sticking a sleep(1) before
the unblock_blocked_cmd() that unblocks queue-blocks-1, I get:

    22762@1542641707.818838:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}

I/O thread receives and queues queue-blocks-1.

    22762@1542641707.818856:monitor_qmp_cmd_in_band queue-blocks-1

Main thread dequeues qemu-blocks-1 and starts executing it.  We already
lost.

    22762@1542641707.819585:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.820331:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.821072:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.821821:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.822569:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.823314:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
    22762@1542641707.824069:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}

I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.

    22762@1542641707.824253:handle_qmp_command mon 0x55f5b6a5de80 req: {"exec-oob": "migrate-pause"}
    22762@1542641707.824257:monitor_qmp_cmd_out_of_band oob-1
    22762@1542641707.824282:monitor_qmp_respond oob-1

I/O thread receives, executes and responds to oob-1.

Test is going to fail: response to oob-1 sent before response to
queue-blocks-1.

Now let me try your fix.  Here's what I see:

    16585@1542650042.980953:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.981018:monitor_qmp_cmd_in_band queue-blocks-1
    16585@1542650042.981252:monitor_qmp_respond queue-blocks-1
    16585@1542650042.981838:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.981916:monitor_qmp_cmd_in_band queue-blocks-2
    16585@1542650042.982656:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.983406:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.984170:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.984975:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.985778:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.986565:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.987396:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-9", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
    16585@1542650042.987626:handle_qmp_command mon 0x5597b8e0de80 req: {"exec-oob": "migrate-pause"}
    16585@1542650042.987630:monitor_qmp_cmd_out_of_band oob-1
    16585@1542650042.987676:monitor_qmp_respond oob-1
    16585@1542650042.988035:monitor_qmp_respond queue-blocks-2
    16585@1542650042.988066:monitor_qmp_cmd_in_band queue-blocks-3
    16585@1542650042.988329:monitor_qmp_respond queue-blocks-3
    16585@1542650042.988360:monitor_qmp_cmd_in_band queue-blocks-4
    16585@1542650042.988575:monitor_qmp_respond queue-blocks-4
    16585@1542650042.988616:monitor_qmp_cmd_in_band queue-blocks-5
    16585@1542650042.988803:monitor_qmp_respond queue-blocks-5
    16585@1542650042.988826:monitor_qmp_cmd_in_band queue-blocks-6
    16585@1542650042.988977:monitor_qmp_respond queue-blocks-6
    16585@1542650042.989001:monitor_qmp_cmd_in_band queue-blocks-7
    16585@1542650042.989223:monitor_qmp_respond queue-blocks-7
    16585@1542650042.989279:monitor_qmp_cmd_in_band queue-blocks-8
    16585@1542650042.989447:monitor_qmp_respond queue-blocks-8
    16585@1542650042.989469:monitor_qmp_cmd_in_band queue-blocks-9
    16585@1542650042.989582:monitor_qmp_respond queue-blocks-9

Tracepoint monitor_suspend still not hit.  This means the queue does not
fill up.

> Markus, do you want me to repost a new version with this change?  Is
> it still possible to have the oob-default series for 3.1?

We're trying to, but we need to get the test to work.

Two problems:

1. The test doesn't seem to succed at testing "queue full".

2. The test might still be racy.

I suspect the code we test is solid, and it's "only" the test we screwed
up.


diff --git a/monitor.c b/monitor.c
index 431795d686..52112889ef 100644
--- a/monitor.c
+++ b/monitor.c
@@ -4064,6 +4064,7 @@ static int monitor_can_read(void *opaque)
  */
 static void monitor_qmp_respond(Monitor *mon, QDict *rsp, QObject *id)
 {
+    trace_monitor_qmp_respond(qobject_get_try_str(id) ?: "");
     if (rsp) {
         if (id) {
             qdict_put_obj(rsp, "id", qobject_ref(id));
diff --git a/trace-events b/trace-events
index 4fd2cb4b97..57c5f6cc94 100644
--- a/trace-events
+++ b/trace-events
@@ -50,6 +50,7 @@ handle_qmp_command(void *mon, const char *req) "mon %p req: %s"
 monitor_suspend(void *ptr, int cnt) "mon %p: %d"
 monitor_qmp_cmd_in_band(const char *id) "%s"
 monitor_qmp_cmd_out_of_band(const char *id) "%s"
+monitor_qmp_respond(const char *id) "%s"
 
 # dma-helpers.c
 dma_blk_io(void *dbs, void *bs, int64_t offset, bool to_dev) "dbs=%p bs=%p offset=%" PRId64 " to_dev=%d"

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Mon, Nov 19, 2018 at 07:08:13PM +0100, Markus Armbruster wrote:
> Peter Xu <peterx@redhat.com> writes:
> 
> > On Mon, Nov 19, 2018 at 02:17:27PM +0800, Peter Xu wrote:
> >> I reproduced the error with a FreeBSD guest and this change (which
> >> possibly can be squashed into "tests: qmp-test: add queue full test")
> >> worked for me:
> >> 
> >> diff --git a/tests/qmp-test.c b/tests/qmp-test.c
> >> index 6989acbca4..83f353db4f 100644
> >> --- a/tests/qmp-test.c
> >> +++ b/tests/qmp-test.c
> >> @@ -281,8 +281,15 @@ static void test_qmp_oob(void)
> >>       * will only be able to be handled after the queue is shrinked, so
> >>       * it'll be processed only after one existing in-band command
> >>       * finishes.
> >> +     *
> >> +     * NOTE: we need to feed the queue with one extra request to make
> >> +     * sure it'll be stuck since when we have sent the Nth request
> >> +     * it's possible that we have already popped and processing the
> >> +     * 1st request so the Nth request (which could potentially be the
> >> +     * [N-1]th element on the queue) might not trigger the
> >> +     * monitor-full condition deterministically.
> >>       */
> >> -    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> >> +    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
> >>          id = g_strdup_printf("queue-blocks-%d", i);
> >>          send_cmd_that_blocks(qts, id);
> >>          g_free(id);
> >> @@ -291,7 +298,7 @@ static void test_qmp_oob(void)
> >>      unblock_blocked_cmd();
> >>      recv_cmd_id(qts, "queue-blocks-1");
> >>      recv_cmd_id(qts, "oob-1");
> >> -    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> >> +    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
> >>          unblock_blocked_cmd();
> >>          id = g_strdup_printf("queue-blocks-%d", i);
> >>          recv_cmd_id(qts, id);
> >> 
> >> So the problem here is that the queue-block-N command might not really
> >> suspend the monitor everytime if we already popped the 1st request,
> >> which will let the N-th request to be (N-1)th, then the parser will
> >> continue to eat the oob command and it could "preempt" the previous
> >> commands.
> >> 
> >> Maybe FreeBSD is scheduling the threads in some pattern so it happens
> >> only on FreeBSD and very constantly, but anyway it should be a general
> >> fix to the test program.
> 
> I feel particularly dense right now, and need a more detailed analysis
> to understand.  Let me try.
> 
> Here's what the test does before your fix
> 
>     Send QMP_REQ_QUEUE_LEN_MAX "blocking" in-band commands
>     queue-blocks-1, queue-blocks-2, ...  "Blocking" means the command
>     blocks until we explicitly unblock it.
> 
>     Send an out-of-band command oob-1.
> 
>     Unblock queue-blocks-1.
> 
>     Receive response to queue-blocks-1.
> 
>     Receive response to oob-1.
> 
>     Unblock queue-blocks-2, receive response
>     ...
> 
> Here's what test test expects QEMU to do:
> 
>     In I/O thread:
> 
>         Receive and queue queue-blocks-1, ...
> 
>         Queue is full, stop receiving commands.
> 
>     In main thread:
> 
>         Dequeue queue-blocks-1.
> 
>         Execute queue-blocks-1, block for a while, finish and send
>         response.
> 
>     In I/O thread:
> 
>         Queue is no longer full, resume receiving commands.
> 
>         Receive and execute oob-1, send response
> 
>     In main thread:
> 
>         Dequeue queue-blocks-2, execute, block for a while, finish and
>         send response.
>         ...
> 
> No good because the two threads race.  On my Linux box the test passes.
> Let's have a closer look how it does that.  The appended patch that adds
> another tracepoint.  With tracepoints monitor_* and handle_qmp_command
> enabled, I get:
> 
>     19271@1542641581.372890:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> 
> I/O thread receives and queues queue-blocks-1.
> 
>     19271@1542641581.372954:monitor_qmp_cmd_in_band queue-blocks-1
> 
> Main thread dequeues qemu-blocks-1 and starts executing it.
> 
> We already lost: the queue won't actually fill up.  The test passes
> anyway, but it doesn't actually test "queue full".  But why does it
> pass?  Let's see.
> 
>     19271@1542641581.373211:monitor_qmp_respond queue-blocks-1
> 
> Main thread sends response to queue-blocks-1.  This means queue-blocks-1
> has been unblocked already.  This is possible, because qmp-test sends
> all the commands and then immediately unblocks queue-blocks-1, and the
> main thread can win the race with the I/O thread.
> 
>     19271@1542641581.373826:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.373864:monitor_qmp_cmd_in_band queue-blocks-2
>     19271@1542641581.374575:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.375344:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.376162:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.376996:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.377790:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>     19271@1542641581.378562:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> 
> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
> 
>     19271@1542641581.378796:handle_qmp_command mon 0x563e19be4e80 req: {"exec-oob": "migrate-pause"}
>     19271@1542641581.378800:monitor_qmp_cmd_out_of_band oob-1
>     19271@1542641581.378823:monitor_qmp_respond oob-1
> 
> I/O thread receives, executes and responds to oob-1.
> 
>     19271@1542641581.379197:monitor_qmp_respond queue-blocks-2
>     19271@1542641581.379228:monitor_qmp_cmd_in_band queue-blocks-3
>     19271@1542641581.379435:monitor_qmp_respond queue-blocks-3
>     19271@1542641581.379477:monitor_qmp_cmd_in_band queue-blocks-4
>     19271@1542641581.379597:monitor_qmp_respond queue-blocks-4
>     19271@1542641581.379621:monitor_qmp_cmd_in_band queue-blocks-5
>     19271@1542641581.379800:monitor_qmp_respond queue-blocks-5
>     19271@1542641581.379824:monitor_qmp_cmd_in_band queue-blocks-6
>     19271@1542641581.379953:monitor_qmp_respond queue-blocks-6
>     19271@1542641581.379992:monitor_qmp_cmd_in_band queue-blocks-7
>     19271@1542641581.380132:monitor_qmp_respond queue-blocks-7
>     19271@1542641581.380170:monitor_qmp_cmd_in_band queue-blocks-8
>     19271@1542641581.380283:monitor_qmp_respond queue-blocks-8
> 
> Main thread dequeues, executes and responds to queue-blocks-2,
> ... queue-blocks-8.
> 
> If I make the main thread lose the race by sticking a sleep(1) before
> the unblock_blocked_cmd() that unblocks queue-blocks-1, I get:
> 
>     22762@1542641707.818838:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> 
> I/O thread receives and queues queue-blocks-1.
> 
>     22762@1542641707.818856:monitor_qmp_cmd_in_band queue-blocks-1
> 
> Main thread dequeues qemu-blocks-1 and starts executing it.  We already
> lost.
> 
>     22762@1542641707.819585:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.820331:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.821072:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.821821:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.822569:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.823314:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>     22762@1542641707.824069:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> 
> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
> 
>     22762@1542641707.824253:handle_qmp_command mon 0x55f5b6a5de80 req: {"exec-oob": "migrate-pause"}
>     22762@1542641707.824257:monitor_qmp_cmd_out_of_band oob-1
>     22762@1542641707.824282:monitor_qmp_respond oob-1
> 
> I/O thread receives, executes and responds to oob-1.
> 
> Test is going to fail: response to oob-1 sent before response to
> queue-blocks-1.
> 
> Now let me try your fix.  Here's what I see:
> 
>     16585@1542650042.980953:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.981018:monitor_qmp_cmd_in_band queue-blocks-1
>     16585@1542650042.981252:monitor_qmp_respond queue-blocks-1
>     16585@1542650042.981838:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.981916:monitor_qmp_cmd_in_band queue-blocks-2
>     16585@1542650042.982656:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.983406:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.984170:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.984975:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.985778:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.986565:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.987396:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-9", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>     16585@1542650042.987626:handle_qmp_command mon 0x5597b8e0de80 req: {"exec-oob": "migrate-pause"}
>     16585@1542650042.987630:monitor_qmp_cmd_out_of_band oob-1
>     16585@1542650042.987676:monitor_qmp_respond oob-1
>     16585@1542650042.988035:monitor_qmp_respond queue-blocks-2
>     16585@1542650042.988066:monitor_qmp_cmd_in_band queue-blocks-3
>     16585@1542650042.988329:monitor_qmp_respond queue-blocks-3
>     16585@1542650042.988360:monitor_qmp_cmd_in_band queue-blocks-4
>     16585@1542650042.988575:monitor_qmp_respond queue-blocks-4
>     16585@1542650042.988616:monitor_qmp_cmd_in_band queue-blocks-5
>     16585@1542650042.988803:monitor_qmp_respond queue-blocks-5
>     16585@1542650042.988826:monitor_qmp_cmd_in_band queue-blocks-6
>     16585@1542650042.988977:monitor_qmp_respond queue-blocks-6
>     16585@1542650042.989001:monitor_qmp_cmd_in_band queue-blocks-7
>     16585@1542650042.989223:monitor_qmp_respond queue-blocks-7
>     16585@1542650042.989279:monitor_qmp_cmd_in_band queue-blocks-8
>     16585@1542650042.989447:monitor_qmp_respond queue-blocks-8
>     16585@1542650042.989469:monitor_qmp_cmd_in_band queue-blocks-9
>     16585@1542650042.989582:monitor_qmp_respond queue-blocks-9
> 
> Tracepoint monitor_suspend still not hit.  This means the queue does not
> fill up.

You are right.  I think I figured out one thing but I missed another
point here that "sent the command" does not mean "received by the QMP
server": we can never identify when the queue is full, meanwhile
that's what we need to write a unit test for it.

For example: in this test what we want to achieve is:

  for i in 1 .. N:
      send blocking commands Bi
  ... wait until queue is full ...  [1]
  send oob command O1
  unblock blocking command B1
  receive response B1
  receive response O1
  for i in 2 .. N:
      unblock blocking command Bi
      receive response Bi

All looks sane except the assumption at [1].  In the code we didn't do
anything for [1] assuming that it's naturally happening.  However it's
not since when finishing the first for loop we only queued the
commands into the send buffer, but we can't guarantee that the
commands are well received and further queued in the qmp request list
on the server side.  Now when the server qmp request queue gets full
it will only suspend the monitor, and that event is totally unseen
from the client POV, so IMHO we don't have a good way to guarantee
this.  E.g., we can do a very long sleep(100) at [1] to pretty make
sure the queue full is happened, however it might still break on a
super slow machine.

In other words, I don't see a good way to automate the testing of
queue full for now (but I'm pretty sure the queue full is working
there since if you really insert a sleep you'll definitely see the
monitor_suspend tracepoint).  We might need something like an event to
make sure the queue full happened and then the client can detect this
and insert the next out-of-band command, but then we're going backword
and I don't see much point to introduce a new event only for testing
purpose...

> 
> > Markus, do you want me to repost a new version with this change?  Is
> > it still possible to have the oob-default series for 3.1?
> 
> We're trying to, but we need to get the test to work.
> 
> Two problems:
> 
> 1. The test doesn't seem to succed at testing "queue full".
> 
> 2. The test might still be racy.
> 
> I suspect the code we test is solid, and it's "only" the test we screwed
> up.

I agree.  Do you have better idea to test queue full?  I'd be more
than glad to try any suggestions here, otherwise I am thinking whether
we can just simply drop the queue full test (which is the last patch
of the oob series) for now but merge the rest.  We can introduce new
queue full test after 3.1 if we want, though again I really doubt
whether we can without new things introduced into the procedure.

Thoughts?

> 
> 
> diff --git a/monitor.c b/monitor.c
> index 431795d686..52112889ef 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -4064,6 +4064,7 @@ static int monitor_can_read(void *opaque)
>   */
>  static void monitor_qmp_respond(Monitor *mon, QDict *rsp, QObject *id)
>  {
> +    trace_monitor_qmp_respond(qobject_get_try_str(id) ?: "");
>      if (rsp) {
>          if (id) {
>              qdict_put_obj(rsp, "id", qobject_ref(id));
> diff --git a/trace-events b/trace-events
> index 4fd2cb4b97..57c5f6cc94 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -50,6 +50,7 @@ handle_qmp_command(void *mon, const char *req) "mon %p req: %s"
>  monitor_suspend(void *ptr, int cnt) "mon %p: %d"
>  monitor_qmp_cmd_in_band(const char *id) "%s"
>  monitor_qmp_cmd_out_of_band(const char *id) "%s"
> +monitor_qmp_respond(const char *id) "%s"
>  
>  # dma-helpers.c
>  dma_blk_io(void *dbs, void *bs, int64_t offset, bool to_dev) "dbs=%p bs=%p offset=%" PRId64 " to_dev=%d"

Regards,

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

Peter Xu <peterx@redhat.com> writes:

> On Mon, Nov 19, 2018 at 07:08:13PM +0100, Markus Armbruster wrote:
>> Peter Xu <peterx@redhat.com> writes:
>> 
>> > On Mon, Nov 19, 2018 at 02:17:27PM +0800, Peter Xu wrote:
>> >> I reproduced the error with a FreeBSD guest and this change (which
>> >> possibly can be squashed into "tests: qmp-test: add queue full test")
>> >> worked for me:
>> >> 
>> >> diff --git a/tests/qmp-test.c b/tests/qmp-test.c
>> >> index 6989acbca4..83f353db4f 100644
>> >> --- a/tests/qmp-test.c
>> >> +++ b/tests/qmp-test.c
>> >> @@ -281,8 +281,15 @@ static void test_qmp_oob(void)
>> >>       * will only be able to be handled after the queue is shrinked, so
>> >>       * it'll be processed only after one existing in-band command
>> >>       * finishes.
>> >> +     *
>> >> +     * NOTE: we need to feed the queue with one extra request to make
>> >> +     * sure it'll be stuck since when we have sent the Nth request
>> >> +     * it's possible that we have already popped and processing the
>> >> +     * 1st request so the Nth request (which could potentially be the
>> >> +     * [N-1]th element on the queue) might not trigger the
>> >> +     * monitor-full condition deterministically.
>> >>       */
>> >> -    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
>> >> +    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>> >>          id = g_strdup_printf("queue-blocks-%d", i);
>> >>          send_cmd_that_blocks(qts, id);
>> >>          g_free(id);
>> >> @@ -291,7 +298,7 @@ static void test_qmp_oob(void)
>> >>      unblock_blocked_cmd();
>> >>      recv_cmd_id(qts, "queue-blocks-1");
>> >>      recv_cmd_id(qts, "oob-1");
>> >> -    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
>> >> +    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
>> >>          unblock_blocked_cmd();
>> >>          id = g_strdup_printf("queue-blocks-%d", i);
>> >>          recv_cmd_id(qts, id);
>> >> 
>> >> So the problem here is that the queue-block-N command might not really
>> >> suspend the monitor everytime if we already popped the 1st request,
>> >> which will let the N-th request to be (N-1)th, then the parser will
>> >> continue to eat the oob command and it could "preempt" the previous
>> >> commands.
>> >> 
>> >> Maybe FreeBSD is scheduling the threads in some pattern so it happens
>> >> only on FreeBSD and very constantly, but anyway it should be a general
>> >> fix to the test program.
>> 
>> I feel particularly dense right now, and need a more detailed analysis
>> to understand.  Let me try.
>> 
>> Here's what the test does before your fix
>> 
>>     Send QMP_REQ_QUEUE_LEN_MAX "blocking" in-band commands
>>     queue-blocks-1, queue-blocks-2, ...  "Blocking" means the command
>>     blocks until we explicitly unblock it.
>> 
>>     Send an out-of-band command oob-1.
>> 
>>     Unblock queue-blocks-1.
>> 
>>     Receive response to queue-blocks-1.
>> 
>>     Receive response to oob-1.
>> 
>>     Unblock queue-blocks-2, receive response
>>     ...
>> 
>> Here's what test test expects QEMU to do:
>> 
>>     In I/O thread:
>> 
>>         Receive and queue queue-blocks-1, ...
>> 
>>         Queue is full, stop receiving commands.
>> 
>>     In main thread:
>> 
>>         Dequeue queue-blocks-1.
>> 
>>         Execute queue-blocks-1, block for a while, finish and send
>>         response.
>> 
>>     In I/O thread:
>> 
>>         Queue is no longer full, resume receiving commands.
>> 
>>         Receive and execute oob-1, send response
>> 
>>     In main thread:
>> 
>>         Dequeue queue-blocks-2, execute, block for a while, finish and
>>         send response.
>>         ...
>> 
>> No good because the two threads race.  On my Linux box the test passes.
>> Let's have a closer look how it does that.  The appended patch that adds
>> another tracepoint.  With tracepoints monitor_* and handle_qmp_command
>> enabled, I get:
>> 
>>     19271@1542641581.372890:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>> 
>> I/O thread receives and queues queue-blocks-1.
>> 
>>     19271@1542641581.372954:monitor_qmp_cmd_in_band queue-blocks-1
>> 
>> Main thread dequeues qemu-blocks-1 and starts executing it.
>> 
>> We already lost: the queue won't actually fill up.  The test passes
>> anyway, but it doesn't actually test "queue full".  But why does it
>> pass?  Let's see.
>> 
>>     19271@1542641581.373211:monitor_qmp_respond queue-blocks-1
>> 
>> Main thread sends response to queue-blocks-1.  This means queue-blocks-1
>> has been unblocked already.  This is possible, because qmp-test sends
>> all the commands and then immediately unblocks queue-blocks-1, and the
>> main thread can win the race with the I/O thread.
>> 
>>     19271@1542641581.373826:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.373864:monitor_qmp_cmd_in_band queue-blocks-2
>>     19271@1542641581.374575:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.375344:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.376162:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.376996:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.377790:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>>     19271@1542641581.378562:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
>> 
>> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
>> 
>>     19271@1542641581.378796:handle_qmp_command mon 0x563e19be4e80 req: {"exec-oob": "migrate-pause"}
>>     19271@1542641581.378800:monitor_qmp_cmd_out_of_band oob-1
>>     19271@1542641581.378823:monitor_qmp_respond oob-1
>> 
>> I/O thread receives, executes and responds to oob-1.
>> 
>>     19271@1542641581.379197:monitor_qmp_respond queue-blocks-2
>>     19271@1542641581.379228:monitor_qmp_cmd_in_band queue-blocks-3
>>     19271@1542641581.379435:monitor_qmp_respond queue-blocks-3
>>     19271@1542641581.379477:monitor_qmp_cmd_in_band queue-blocks-4
>>     19271@1542641581.379597:monitor_qmp_respond queue-blocks-4
>>     19271@1542641581.379621:monitor_qmp_cmd_in_band queue-blocks-5
>>     19271@1542641581.379800:monitor_qmp_respond queue-blocks-5
>>     19271@1542641581.379824:monitor_qmp_cmd_in_band queue-blocks-6
>>     19271@1542641581.379953:monitor_qmp_respond queue-blocks-6
>>     19271@1542641581.379992:monitor_qmp_cmd_in_band queue-blocks-7
>>     19271@1542641581.380132:monitor_qmp_respond queue-blocks-7
>>     19271@1542641581.380170:monitor_qmp_cmd_in_band queue-blocks-8
>>     19271@1542641581.380283:monitor_qmp_respond queue-blocks-8
>> 
>> Main thread dequeues, executes and responds to queue-blocks-2,
>> ... queue-blocks-8.
>> 
>> If I make the main thread lose the race by sticking a sleep(1) before
>> the unblock_blocked_cmd() that unblocks queue-blocks-1, I get:
>> 
>>     22762@1542641707.818838:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>> 
>> I/O thread receives and queues queue-blocks-1.
>> 
>>     22762@1542641707.818856:monitor_qmp_cmd_in_band queue-blocks-1
>> 
>> Main thread dequeues qemu-blocks-1 and starts executing it.  We already
>> lost.
>> 
>>     22762@1542641707.819585:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.820331:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.821072:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.821821:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.822569:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.823314:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>>     22762@1542641707.824069:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
>> 
>> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
>> 
>>     22762@1542641707.824253:handle_qmp_command mon 0x55f5b6a5de80 req: {"exec-oob": "migrate-pause"}
>>     22762@1542641707.824257:monitor_qmp_cmd_out_of_band oob-1
>>     22762@1542641707.824282:monitor_qmp_respond oob-1
>> 
>> I/O thread receives, executes and responds to oob-1.
>> 
>> Test is going to fail: response to oob-1 sent before response to
>> queue-blocks-1.
>> 
>> Now let me try your fix.  Here's what I see:
>> 
>>     16585@1542650042.980953:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.981018:monitor_qmp_cmd_in_band queue-blocks-1
>>     16585@1542650042.981252:monitor_qmp_respond queue-blocks-1
>>     16585@1542650042.981838:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.981916:monitor_qmp_cmd_in_band queue-blocks-2
>>     16585@1542650042.982656:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.983406:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.984170:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.984975:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.985778:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.986565:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.987396:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-9", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
>>     16585@1542650042.987626:handle_qmp_command mon 0x5597b8e0de80 req: {"exec-oob": "migrate-pause"}
>>     16585@1542650042.987630:monitor_qmp_cmd_out_of_band oob-1
>>     16585@1542650042.987676:monitor_qmp_respond oob-1
>>     16585@1542650042.988035:monitor_qmp_respond queue-blocks-2
>>     16585@1542650042.988066:monitor_qmp_cmd_in_band queue-blocks-3
>>     16585@1542650042.988329:monitor_qmp_respond queue-blocks-3
>>     16585@1542650042.988360:monitor_qmp_cmd_in_band queue-blocks-4
>>     16585@1542650042.988575:monitor_qmp_respond queue-blocks-4
>>     16585@1542650042.988616:monitor_qmp_cmd_in_band queue-blocks-5
>>     16585@1542650042.988803:monitor_qmp_respond queue-blocks-5
>>     16585@1542650042.988826:monitor_qmp_cmd_in_band queue-blocks-6
>>     16585@1542650042.988977:monitor_qmp_respond queue-blocks-6
>>     16585@1542650042.989001:monitor_qmp_cmd_in_band queue-blocks-7
>>     16585@1542650042.989223:monitor_qmp_respond queue-blocks-7
>>     16585@1542650042.989279:monitor_qmp_cmd_in_band queue-blocks-8
>>     16585@1542650042.989447:monitor_qmp_respond queue-blocks-8
>>     16585@1542650042.989469:monitor_qmp_cmd_in_band queue-blocks-9
>>     16585@1542650042.989582:monitor_qmp_respond queue-blocks-9
>> 
>> Tracepoint monitor_suspend still not hit.  This means the queue does not
>> fill up.
>
> You are right.  I think I figured out one thing but I missed another
> point here that "sent the command" does not mean "received by the QMP
> server": we can never identify when the queue is full, meanwhile
> that's what we need to write a unit test for it.
>
> For example: in this test what we want to achieve is:
>
>   for i in 1 .. N:
>       send blocking commands Bi
>   ... wait until queue is full ...  [1]
>   send oob command O1
>   unblock blocking command B1
>   receive response B1
>   receive response O1
>   for i in 2 .. N:
>       unblock blocking command Bi
>       receive response Bi
>
> All looks sane except the assumption at [1].  In the code we didn't do
> anything for [1] assuming that it's naturally happening.  However it's
> not since when finishing the first for loop we only queued the
> commands into the send buffer, but we can't guarantee that the
> commands are well received and further queued in the qmp request list
> on the server side.  Now when the server qmp request queue gets full
> it will only suspend the monitor, and that event is totally unseen
> from the client POV, so IMHO we don't have a good way to guarantee
> this.  E.g., we can do a very long sleep(100) at [1] to pretty make
> sure the queue full is happened, however it might still break on a
> super slow machine.
>
> In other words, I don't see a good way to automate the testing of
> queue full for now (but I'm pretty sure the queue full is working
> there since if you really insert a sleep you'll definitely see the
> monitor_suspend tracepoint).  We might need something like an event to
> make sure the queue full happened and then the client can detect this
> and insert the next out-of-band command, but then we're going backword
> and I don't see much point to introduce a new event only for testing
> purpose...

We want the test to drive QEMU into the "queue full" state with an
out-of-band command unreceived, then watch the queue drain and the
out-of-band command overtaking part of it.

Driving QEMU into this state is easy enough: we can use a blocking
in-band command to plug the queue's drain.

Once we have QEMU in this state, we can unblock that command and watch
the show.  But we really have to wait until QEMU reaches this state
before we unblock.

Our problem is the test can't easily observe when QEMU reaches this
state.

You mentioned sending a "queue full" event, and that adding such an
event just for testing is hard to justify.  I agree.  Could such an
event have a non-testing use?  All I can think of is letting the
management application detect "we mismanaged the queue and compromised
monitor availability for out-of-band commands".  Doesn't sound
particularly convincing to me, but we can talk with libvirt guys to see
whether they want it.

Can the test observe the monitor is suspended just from the behavior of
its monitor socket?  Not reliably: sending lots of input eventually
fails with EAGAIN when the monitor is suspended, but it can also fail
when the monitor reads the input too slowly.

Can the test observe the monitor_suspend trace point?  Awkward, because
the trace backends are configurable.  We could have the test monitor the
"simple" backend's output file, skipping the test when "simple" isn't
available.  Hmm.

Here comes the heavy hammer: extend the qtest protocol.  When the
monitor suspends / resumes, send a suitable asynchronous message to the
qtest socket.  Have libqtest use that to track monitor suspend state.
The test can then busy-wait for the state to flip to suspended.

Other ideas?

>> > Markus, do you want me to repost a new version with this change?  Is
>> > it still possible to have the oob-default series for 3.1?
>> 
>> We're trying to, but we need to get the test to work.
>> 
>> Two problems:
>> 
>> 1. The test doesn't seem to succed at testing "queue full".
>> 
>> 2. The test might still be racy.
>> 
>> I suspect the code we test is solid, and it's "only" the test we screwed
>> up.
>
> I agree.  Do you have better idea to test queue full?  I'd be more
> than glad to try any suggestions here, otherwise I am thinking whether
> we can just simply drop the queue full test (which is the last patch
> of the oob series) for now but merge the rest.  We can introduce new
> queue full test after 3.1 if we want, though again I really doubt
> whether we can without new things introduced into the procedure.
>
> Thoughts?

I'm afraid dropping the test (for now?) is what we have to do.

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Peter Xu]

On Tue, Nov 20, 2018 at 06:44:27PM +0100, Markus Armbruster wrote:
> Peter Xu <peterx@redhat.com> writes:
> 
> > On Mon, Nov 19, 2018 at 07:08:13PM +0100, Markus Armbruster wrote:
> >> Peter Xu <peterx@redhat.com> writes:
> >> 
> >> > On Mon, Nov 19, 2018 at 02:17:27PM +0800, Peter Xu wrote:
> >> >> I reproduced the error with a FreeBSD guest and this change (which
> >> >> possibly can be squashed into "tests: qmp-test: add queue full test")
> >> >> worked for me:
> >> >> 
> >> >> diff --git a/tests/qmp-test.c b/tests/qmp-test.c
> >> >> index 6989acbca4..83f353db4f 100644
> >> >> --- a/tests/qmp-test.c
> >> >> +++ b/tests/qmp-test.c
> >> >> @@ -281,8 +281,15 @@ static void test_qmp_oob(void)
> >> >>       * will only be able to be handled after the queue is shrinked, so
> >> >>       * it'll be processed only after one existing in-band command
> >> >>       * finishes.
> >> >> +     *
> >> >> +     * NOTE: we need to feed the queue with one extra request to make
> >> >> +     * sure it'll be stuck since when we have sent the Nth request
> >> >> +     * it's possible that we have already popped and processing the
> >> >> +     * 1st request so the Nth request (which could potentially be the
> >> >> +     * [N-1]th element on the queue) might not trigger the
> >> >> +     * monitor-full condition deterministically.
> >> >>       */
> >> >> -    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> >> >> +    for (i = 1; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
> >> >>          id = g_strdup_printf("queue-blocks-%d", i);
> >> >>          send_cmd_that_blocks(qts, id);
> >> >>          g_free(id);
> >> >> @@ -291,7 +298,7 @@ static void test_qmp_oob(void)
> >> >>      unblock_blocked_cmd();
> >> >>      recv_cmd_id(qts, "queue-blocks-1");
> >> >>      recv_cmd_id(qts, "oob-1");
> >> >> -    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX; i++) {
> >> >> +    for (i = 2; i <= QMP_REQ_QUEUE_LEN_MAX + 1; i++) {
> >> >>          unblock_blocked_cmd();
> >> >>          id = g_strdup_printf("queue-blocks-%d", i);
> >> >>          recv_cmd_id(qts, id);
> >> >> 
> >> >> So the problem here is that the queue-block-N command might not really
> >> >> suspend the monitor everytime if we already popped the 1st request,
> >> >> which will let the N-th request to be (N-1)th, then the parser will
> >> >> continue to eat the oob command and it could "preempt" the previous
> >> >> commands.
> >> >> 
> >> >> Maybe FreeBSD is scheduling the threads in some pattern so it happens
> >> >> only on FreeBSD and very constantly, but anyway it should be a general
> >> >> fix to the test program.
> >> 
> >> I feel particularly dense right now, and need a more detailed analysis
> >> to understand.  Let me try.
> >> 
> >> Here's what the test does before your fix
> >> 
> >>     Send QMP_REQ_QUEUE_LEN_MAX "blocking" in-band commands
> >>     queue-blocks-1, queue-blocks-2, ...  "Blocking" means the command
> >>     blocks until we explicitly unblock it.
> >> 
> >>     Send an out-of-band command oob-1.
> >> 
> >>     Unblock queue-blocks-1.
> >> 
> >>     Receive response to queue-blocks-1.
> >> 
> >>     Receive response to oob-1.
> >> 
> >>     Unblock queue-blocks-2, receive response
> >>     ...
> >> 
> >> Here's what test test expects QEMU to do:
> >> 
> >>     In I/O thread:
> >> 
> >>         Receive and queue queue-blocks-1, ...
> >> 
> >>         Queue is full, stop receiving commands.
> >> 
> >>     In main thread:
> >> 
> >>         Dequeue queue-blocks-1.
> >> 
> >>         Execute queue-blocks-1, block for a while, finish and send
> >>         response.
> >> 
> >>     In I/O thread:
> >> 
> >>         Queue is no longer full, resume receiving commands.
> >> 
> >>         Receive and execute oob-1, send response
> >> 
> >>     In main thread:
> >> 
> >>         Dequeue queue-blocks-2, execute, block for a while, finish and
> >>         send response.
> >>         ...
> >> 
> >> No good because the two threads race.  On my Linux box the test passes.
> >> Let's have a closer look how it does that.  The appended patch that adds
> >> another tracepoint.  With tracepoints monitor_* and handle_qmp_command
> >> enabled, I get:
> >> 
> >>     19271@1542641581.372890:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >> 
> >> I/O thread receives and queues queue-blocks-1.
> >> 
> >>     19271@1542641581.372954:monitor_qmp_cmd_in_band queue-blocks-1
> >> 
> >> Main thread dequeues qemu-blocks-1 and starts executing it.
> >> 
> >> We already lost: the queue won't actually fill up.  The test passes
> >> anyway, but it doesn't actually test "queue full".  But why does it
> >> pass?  Let's see.
> >> 
> >>     19271@1542641581.373211:monitor_qmp_respond queue-blocks-1
> >> 
> >> Main thread sends response to queue-blocks-1.  This means queue-blocks-1
> >> has been unblocked already.  This is possible, because qmp-test sends
> >> all the commands and then immediately unblocks queue-blocks-1, and the
> >> main thread can win the race with the I/O thread.
> >> 
> >>     19271@1542641581.373826:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.373864:monitor_qmp_cmd_in_band queue-blocks-2
> >>     19271@1542641581.374575:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.375344:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.376162:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.376996:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.377790:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >>     19271@1542641581.378562:handle_qmp_command mon 0x563e19be4e80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-EZroW3/fifo"}}
> >> 
> >> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
> >> 
> >>     19271@1542641581.378796:handle_qmp_command mon 0x563e19be4e80 req: {"exec-oob": "migrate-pause"}
> >>     19271@1542641581.378800:monitor_qmp_cmd_out_of_band oob-1
> >>     19271@1542641581.378823:monitor_qmp_respond oob-1
> >> 
> >> I/O thread receives, executes and responds to oob-1.
> >> 
> >>     19271@1542641581.379197:monitor_qmp_respond queue-blocks-2
> >>     19271@1542641581.379228:monitor_qmp_cmd_in_band queue-blocks-3
> >>     19271@1542641581.379435:monitor_qmp_respond queue-blocks-3
> >>     19271@1542641581.379477:monitor_qmp_cmd_in_band queue-blocks-4
> >>     19271@1542641581.379597:monitor_qmp_respond queue-blocks-4
> >>     19271@1542641581.379621:monitor_qmp_cmd_in_band queue-blocks-5
> >>     19271@1542641581.379800:monitor_qmp_respond queue-blocks-5
> >>     19271@1542641581.379824:monitor_qmp_cmd_in_band queue-blocks-6
> >>     19271@1542641581.379953:monitor_qmp_respond queue-blocks-6
> >>     19271@1542641581.379992:monitor_qmp_cmd_in_band queue-blocks-7
> >>     19271@1542641581.380132:monitor_qmp_respond queue-blocks-7
> >>     19271@1542641581.380170:monitor_qmp_cmd_in_band queue-blocks-8
> >>     19271@1542641581.380283:monitor_qmp_respond queue-blocks-8
> >> 
> >> Main thread dequeues, executes and responds to queue-blocks-2,
> >> ... queue-blocks-8.
> >> 
> >> If I make the main thread lose the race by sticking a sleep(1) before
> >> the unblock_blocked_cmd() that unblocks queue-blocks-1, I get:
> >> 
> >>     22762@1542641707.818838:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >> 
> >> I/O thread receives and queues queue-blocks-1.
> >> 
> >>     22762@1542641707.818856:monitor_qmp_cmd_in_band queue-blocks-1
> >> 
> >> Main thread dequeues qemu-blocks-1 and starts executing it.  We already
> >> lost.
> >> 
> >>     22762@1542641707.819585:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.820331:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.821072:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.821821:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.822569:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.823314:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >>     22762@1542641707.824069:handle_qmp_command mon 0x55f5b6a5de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-PqO2uz/fifo"}}
> >> 
> >> I/O thread receives and queues queue-blocks-2, ... queue-blocks-8.
> >> 
> >>     22762@1542641707.824253:handle_qmp_command mon 0x55f5b6a5de80 req: {"exec-oob": "migrate-pause"}
> >>     22762@1542641707.824257:monitor_qmp_cmd_out_of_band oob-1
> >>     22762@1542641707.824282:monitor_qmp_respond oob-1
> >> 
> >> I/O thread receives, executes and responds to oob-1.
> >> 
> >> Test is going to fail: response to oob-1 sent before response to
> >> queue-blocks-1.
> >> 
> >> Now let me try your fix.  Here's what I see:
> >> 
> >>     16585@1542650042.980953:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-1", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.981018:monitor_qmp_cmd_in_band queue-blocks-1
> >>     16585@1542650042.981252:monitor_qmp_respond queue-blocks-1
> >>     16585@1542650042.981838:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-2", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.981916:monitor_qmp_cmd_in_band queue-blocks-2
> >>     16585@1542650042.982656:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-3", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.983406:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-4", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.984170:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-5", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.984975:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-6", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.985778:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-7", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.986565:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-8", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.987396:handle_qmp_command mon 0x5597b8e0de80 req: {"execute": "blockdev-add", "arguments": {"image": {"driver": "null-co"}, "node-name": "queue-blocks-9", "driver": "blkdebug", "config": "/tmp/qmp-test-8YRbOJ/fifo"}}
> >>     16585@1542650042.987626:handle_qmp_command mon 0x5597b8e0de80 req: {"exec-oob": "migrate-pause"}
> >>     16585@1542650042.987630:monitor_qmp_cmd_out_of_band oob-1
> >>     16585@1542650042.987676:monitor_qmp_respond oob-1
> >>     16585@1542650042.988035:monitor_qmp_respond queue-blocks-2
> >>     16585@1542650042.988066:monitor_qmp_cmd_in_band queue-blocks-3
> >>     16585@1542650042.988329:monitor_qmp_respond queue-blocks-3
> >>     16585@1542650042.988360:monitor_qmp_cmd_in_band queue-blocks-4
> >>     16585@1542650042.988575:monitor_qmp_respond queue-blocks-4
> >>     16585@1542650042.988616:monitor_qmp_cmd_in_band queue-blocks-5
> >>     16585@1542650042.988803:monitor_qmp_respond queue-blocks-5
> >>     16585@1542650042.988826:monitor_qmp_cmd_in_band queue-blocks-6
> >>     16585@1542650042.988977:monitor_qmp_respond queue-blocks-6
> >>     16585@1542650042.989001:monitor_qmp_cmd_in_band queue-blocks-7
> >>     16585@1542650042.989223:monitor_qmp_respond queue-blocks-7
> >>     16585@1542650042.989279:monitor_qmp_cmd_in_band queue-blocks-8
> >>     16585@1542650042.989447:monitor_qmp_respond queue-blocks-8
> >>     16585@1542650042.989469:monitor_qmp_cmd_in_band queue-blocks-9
> >>     16585@1542650042.989582:monitor_qmp_respond queue-blocks-9
> >> 
> >> Tracepoint monitor_suspend still not hit.  This means the queue does not
> >> fill up.
> >
> > You are right.  I think I figured out one thing but I missed another
> > point here that "sent the command" does not mean "received by the QMP
> > server": we can never identify when the queue is full, meanwhile
> > that's what we need to write a unit test for it.
> >
> > For example: in this test what we want to achieve is:
> >
> >   for i in 1 .. N:
> >       send blocking commands Bi
> >   ... wait until queue is full ...  [1]
> >   send oob command O1
> >   unblock blocking command B1
> >   receive response B1
> >   receive response O1
> >   for i in 2 .. N:
> >       unblock blocking command Bi
> >       receive response Bi
> >
> > All looks sane except the assumption at [1].  In the code we didn't do
> > anything for [1] assuming that it's naturally happening.  However it's
> > not since when finishing the first for loop we only queued the
> > commands into the send buffer, but we can't guarantee that the
> > commands are well received and further queued in the qmp request list
> > on the server side.  Now when the server qmp request queue gets full
> > it will only suspend the monitor, and that event is totally unseen
> > from the client POV, so IMHO we don't have a good way to guarantee
> > this.  E.g., we can do a very long sleep(100) at [1] to pretty make
> > sure the queue full is happened, however it might still break on a
> > super slow machine.
> >
> > In other words, I don't see a good way to automate the testing of
> > queue full for now (but I'm pretty sure the queue full is working
> > there since if you really insert a sleep you'll definitely see the
> > monitor_suspend tracepoint).  We might need something like an event to
> > make sure the queue full happened and then the client can detect this
> > and insert the next out-of-band command, but then we're going backword
> > and I don't see much point to introduce a new event only for testing
> > purpose...
> 
> We want the test to drive QEMU into the "queue full" state with an
> out-of-band command unreceived, then watch the queue drain and the
> out-of-band command overtaking part of it.
> 
> Driving QEMU into this state is easy enough: we can use a blocking
> in-band command to plug the queue's drain.
> 
> Once we have QEMU in this state, we can unblock that command and watch
> the show.  But we really have to wait until QEMU reaches this state
> before we unblock.
> 
> Our problem is the test can't easily observe when QEMU reaches this
> state.
> 
> You mentioned sending a "queue full" event, and that adding such an
> event just for testing is hard to justify.  I agree.  Could such an
> event have a non-testing use?  All I can think of is letting the
> management application detect "we mismanaged the queue and compromised
> monitor availability for out-of-band commands".  Doesn't sound
> particularly convincing to me, but we can talk with libvirt guys to see
> whether they want it.
> 
> Can the test observe the monitor is suspended just from the behavior of
> its monitor socket?  Not reliably: sending lots of input eventually
> fails with EAGAIN when the monitor is suspended, but it can also fail
> when the monitor reads the input too slowly.
> 
> Can the test observe the monitor_suspend trace point?  Awkward, because
> the trace backends are configurable.  We could have the test monitor the
> "simple" backend's output file, skipping the test when "simple" isn't
> available.  Hmm.
> 
> Here comes the heavy hammer: extend the qtest protocol.  When the
> monitor suspends / resumes, send a suitable asynchronous message to the
> qtest socket.  Have libqtest use that to track monitor suspend state.
> The test can then busy-wait for the state to flip to suspended.
> 
> Other ideas?

I don't have more to add (already a lot of ideas! :-).  I'd say I
would prefer to start with the queue full event and we can discuss
with libvirt on that after 3.1 when proper.  And besides libvirt
(which I am not quite sure whether this event could be really useful
in the near future) maybe it can also be used as a hint for any new
QMP client when people want to complain about "hey, why my QMP client
didn't get any respond from QEMU" - if the client didn't get any
response but however it sees this event then we know the answer even
before debugging more.

> 
> >> > Markus, do you want me to repost a new version with this change?  Is
> >> > it still possible to have the oob-default series for 3.1?
> >> 
> >> We're trying to, but we need to get the test to work.
> >> 
> >> Two problems:
> >> 
> >> 1. The test doesn't seem to succed at testing "queue full".
> >> 
> >> 2. The test might still be racy.
> >> 
> >> I suspect the code we test is solid, and it's "only" the test we screwed
> >> up.
> >
> > I agree.  Do you have better idea to test queue full?  I'd be more
> > than glad to try any suggestions here, otherwise I am thinking whether
> > we can just simply drop the queue full test (which is the last patch
> > of the oob series) for now but merge the rest.  We can introduce new
> > queue full test after 3.1 if we want, though again I really doubt
> > whether we can without new things introduced into the procedure.
> >
> > Thoughts?
> 
> I'm afraid dropping the test (for now?) is what we have to do.

Agreed.

Thanks,

-- 
Peter Xu

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

Peter Xu <peterx@redhat.com> writes:

> On Tue, Nov 20, 2018 at 06:44:27PM +0100, Markus Armbruster wrote:
>> 
>> We want the test to drive QEMU into the "queue full" state with an
>> out-of-band command unreceived, then watch the queue drain and the
>> out-of-band command overtaking part of it.
>> 
>> Driving QEMU into this state is easy enough: we can use a blocking
>> in-band command to plug the queue's drain.
>> 
>> Once we have QEMU in this state, we can unblock that command and watch
>> the show.  But we really have to wait until QEMU reaches this state
>> before we unblock.
>> 
>> Our problem is the test can't easily observe when QEMU reaches this
>> state.
>> 
>> You mentioned sending a "queue full" event, and that adding such an
>> event just for testing is hard to justify.  I agree.  Could such an
>> event have a non-testing use?  All I can think of is letting the
>> management application detect "we mismanaged the queue and compromised
>> monitor availability for out-of-band commands".  Doesn't sound
>> particularly convincing to me, but we can talk with libvirt guys to see
>> whether they want it.
>> 
>> Can the test observe the monitor is suspended just from the behavior of
>> its monitor socket?  Not reliably: sending lots of input eventually
>> fails with EAGAIN when the monitor is suspended, but it can also fail
>> when the monitor reads the input too slowly.
>> 
>> Can the test observe the monitor_suspend trace point?  Awkward, because
>> the trace backends are configurable.  We could have the test monitor the
>> "simple" backend's output file, skipping the test when "simple" isn't
>> available.  Hmm.
>> 
>> Here comes the heavy hammer: extend the qtest protocol.  When the
>> monitor suspends / resumes, send a suitable asynchronous message to the
>> qtest socket.  Have libqtest use that to track monitor suspend state.
>> The test can then busy-wait for the state to flip to suspended.
>> 
>> Other ideas?
>
> I don't have more to add (already a lot of ideas! :-).  I'd say I
> would prefer to start with the queue full event and we can discuss
> with libvirt on that after 3.1 when proper.  And besides libvirt
> (which I am not quite sure whether this event could be really useful
> in the near future) maybe it can also be used as a hint for any new
> QMP client when people want to complain about "hey, why my QMP client
> didn't get any respond from QEMU" - if the client didn't get any
> response but however it sees this event then we know the answer even
> before debugging more.

Good point.

Say we implement full flow control, i.e. we also suspend when the output
buffer becomes too large.  Then the event won't really help, because the
client won't see it until it fixed the situation by draining the output
buffer.  But it won't really hurt, either: even a client that misbehaves
in a really unfortunate way can't trigger many events without also
generating much more other output.  Orders of magnitude more.

>> >> > Markus, do you want me to repost a new version with this change?  Is
>> >> > it still possible to have the oob-default series for 3.1?
>> >> 
>> >> We're trying to, but we need to get the test to work.
>> >> 
>> >> Two problems:
>> >> 
>> >> 1. The test doesn't seem to succed at testing "queue full".
>> >> 
>> >> 2. The test might still be racy.
>> >> 
>> >> I suspect the code we test is solid, and it's "only" the test we screwed
>> >> up.
>> >
>> > I agree.  Do you have better idea to test queue full?  I'd be more
>> > than glad to try any suggestions here, otherwise I am thinking whether
>> > we can just simply drop the queue full test (which is the last patch
>> > of the oob series) for now but merge the rest.  We can introduce new
>> > queue full test after 3.1 if we want, though again I really doubt
>> > whether we can without new things introduced into the procedure.
>> >
>> > Thoughts?
>> 
>> I'm afraid dropping the test (for now?) is what we have to do.
>
> Agreed.

Okay, I'll prepare the pull request later today.

Re: [Qemu-devel] [PULL 0/8] Monitor patches for 2018-10-30

[Markus Armbruster]

Markus Armbruster <armbru@redhat.com> writes:

> Peter Xu <peterx@redhat.com> writes:
>
>> On Tue, Nov 20, 2018 at 06:44:27PM +0100, Markus Armbruster wrote:
>>> 
>>> We want the test to drive QEMU into the "queue full" state with an
>>> out-of-band command unreceived, then watch the queue drain and the
>>> out-of-band command overtaking part of it.
>>> 
>>> Driving QEMU into this state is easy enough: we can use a blocking
>>> in-band command to plug the queue's drain.
>>> 
>>> Once we have QEMU in this state, we can unblock that command and watch
>>> the show.  But we really have to wait until QEMU reaches this state
>>> before we unblock.
>>> 
>>> Our problem is the test can't easily observe when QEMU reaches this
>>> state.
>>> 
>>> You mentioned sending a "queue full" event, and that adding such an
>>> event just for testing is hard to justify.  I agree.  Could such an
>>> event have a non-testing use?  All I can think of is letting the
>>> management application detect "we mismanaged the queue and compromised
>>> monitor availability for out-of-band commands".  Doesn't sound
>>> particularly convincing to me, but we can talk with libvirt guys to see
>>> whether they want it.
>>> 
>>> Can the test observe the monitor is suspended just from the behavior of
>>> its monitor socket?  Not reliably: sending lots of input eventually
>>> fails with EAGAIN when the monitor is suspended, but it can also fail
>>> when the monitor reads the input too slowly.
>>> 
>>> Can the test observe the monitor_suspend trace point?  Awkward, because
>>> the trace backends are configurable.  We could have the test monitor the
>>> "simple" backend's output file, skipping the test when "simple" isn't
>>> available.  Hmm.
>>> 
>>> Here comes the heavy hammer: extend the qtest protocol.  When the
>>> monitor suspends / resumes, send a suitable asynchronous message to the
>>> qtest socket.  Have libqtest use that to track monitor suspend state.
>>> The test can then busy-wait for the state to flip to suspended.
>>> 
>>> Other ideas?
>>
>> I don't have more to add (already a lot of ideas! :-).  I'd say I
>> would prefer to start with the queue full event and we can discuss
>> with libvirt on that after 3.1 when proper.  And besides libvirt
>> (which I am not quite sure whether this event could be really useful
>> in the near future) maybe it can also be used as a hint for any new
>> QMP client when people want to complain about "hey, why my QMP client
>> didn't get any respond from QEMU" - if the client didn't get any
>> response but however it sees this event then we know the answer even
>> before debugging more.
>
> Good point.
>
> Say we implement full flow control, i.e. we also suspend when the output
> buffer becomes too large.  Then the event won't really help, because the
> client won't see it until it fixed the situation by draining the output
> buffer.  But it won't really hurt, either: even a client that misbehaves
> in a really unfortunate way can't trigger many events without also
> generating much more other output.  Orders of magnitude more.
>
>>> >> > Markus, do you want me to repost a new version with this change?  Is
>>> >> > it still possible to have the oob-default series for 3.1?
>>> >> 
>>> >> We're trying to, but we need to get the test to work.
>>> >> 
>>> >> Two problems:
>>> >> 
>>> >> 1. The test doesn't seem to succed at testing "queue full".
>>> >> 
>>> >> 2. The test might still be racy.
>>> >> 
>>> >> I suspect the code we test is solid, and it's "only" the test we screwed
>>> >> up.
>>> >
>>> > I agree.  Do you have better idea to test queue full?  I'd be more
>>> > than glad to try any suggestions here, otherwise I am thinking whether
>>> > we can just simply drop the queue full test (which is the last patch
>>> > of the oob series) for now but merge the rest.  We can introduce new
>>> > queue full test after 3.1 if we want, though again I really doubt
>>> > whether we can without new things introduced into the procedure.
>>> >
>>> > Thoughts?
>>> 
>>> I'm afraid dropping the test (for now?) is what we have to do.
>>
>> Agreed.
>
> Okay, I'll prepare the pull request later today.

I didn't.  I decided it's too late for 3.1.  Sigh...

I'm keeping it queued for 4.0.