[PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Jason Andryuk]

Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
it is set to &qmp_cap_negotiation_commands.  After capability
negotiation, it is set to &qmp_commands.  If the chardev is closed,
CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
chardev is re-opened with CHR_EVENT_OPENED, is it reset to
&qmp_cap_negotiation_commands.

monitor_qapi_event_emit compares mon->commands to
&qmp_cap_negotiation_commands, and skips sending events when they are
equal.  In the case of a closed chardev, QMP events are still sent down
to the closed chardev which needs to drop them.

Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
since that is how mon->commands is set for a newly opened connections.

Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
---
 monitor/qmp.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/monitor/qmp.c b/monitor/qmp.c
index 9d9e5d8b27..5e2073c5eb 100644
--- a/monitor/qmp.c
+++ b/monitor/qmp.c
@@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
          * is closed.
          */
         monitor_qmp_cleanup_queues(mon);
+        mon->commands = &qmp_cap_negotiation_commands;
         json_message_parser_destroy(&mon->parser);
         json_message_parser_init(&mon->parser, handle_qmp_command,
                                  mon, NULL);
-- 
2.21.0

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Marc-André Lureau]

Hi

On Wed, Nov 6, 2019 at 5:04 PM Jason Andryuk <jandryuk@gmail.com> wrote:
>
> Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
> it is set to &qmp_cap_negotiation_commands.  After capability
> negotiation, it is set to &qmp_commands.  If the chardev is closed,
> CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
> chardev is re-opened with CHR_EVENT_OPENED, is it reset to
> &qmp_cap_negotiation_commands.
>
> monitor_qapi_event_emit compares mon->commands to
> &qmp_cap_negotiation_commands, and skips sending events when they are
> equal.  In the case of a closed chardev, QMP events are still sent down
> to the closed chardev which needs to drop them.

This is a minor improvement, not really a bug fix or do I read that incorrectly?

>
> Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
> to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
> since that is how mon->commands is set for a newly opened connections.
>
> Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
> ---
>  monitor/qmp.c | 1 +
>  1 file changed, 1 insertion(+)
>
> diff --git a/monitor/qmp.c b/monitor/qmp.c
> index 9d9e5d8b27..5e2073c5eb 100644
> --- a/monitor/qmp.c
> +++ b/monitor/qmp.c
> @@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
>           * is closed.
>           */
>          monitor_qmp_cleanup_queues(mon);
> +        mon->commands = &qmp_cap_negotiation_commands;
>          json_message_parser_destroy(&mon->parser);
>          json_message_parser_init(&mon->parser, handle_qmp_command,
>                                   mon, NULL);
> --
> 2.21.0
>
>

Looks good to me,
Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>


-- 
Marc-André Lureau

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Jason Andryuk]

On Wed, Nov 6, 2019 at 9:53 AM Marc-André Lureau
<marcandre.lureau@gmail.com> wrote:
>
> Hi
>
> On Wed, Nov 6, 2019 at 5:04 PM Jason Andryuk <jandryuk@gmail.com> wrote:
> >
> > Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
> > it is set to &qmp_cap_negotiation_commands.  After capability
> > negotiation, it is set to &qmp_commands.  If the chardev is closed,
> > CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
> > chardev is re-opened with CHR_EVENT_OPENED, is it reset to
> > &qmp_cap_negotiation_commands.
> >
> > monitor_qapi_event_emit compares mon->commands to
> > &qmp_cap_negotiation_commands, and skips sending events when they are
> > equal.  In the case of a closed chardev, QMP events are still sent down
> > to the closed chardev which needs to drop them.
>
> This is a minor improvement, not really a bug fix or do I read that incorrectly?

Yes, it is more of a minor improvement since disconnected chardevs
already drop the QMP events.  This will just stop generating them in
the first place.

> >
> > Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
> > to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
> > since that is how mon->commands is set for a newly opened connections.
> >
> > Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
> > ---
> >  monitor/qmp.c | 1 +
> >  1 file changed, 1 insertion(+)
> >
> > diff --git a/monitor/qmp.c b/monitor/qmp.c
> > index 9d9e5d8b27..5e2073c5eb 100644
> > --- a/monitor/qmp.c
> > +++ b/monitor/qmp.c
> > @@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
> >           * is closed.
> >           */
> >          monitor_qmp_cleanup_queues(mon);
> > +        mon->commands = &qmp_cap_negotiation_commands;
> >          json_message_parser_destroy(&mon->parser);
> >          json_message_parser_init(&mon->parser, handle_qmp_command,
> >                                   mon, NULL);
> > --
> > 2.21.0
> >
> >
>
> Looks good to me,
> Reviewed-by: Marc-André Lureau <marcandre.lureau@redhat.com>

Thank you.

-Jason

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[no-reply]

Patchew URL: https://patchew.org/QEMU/20191106130309.6737-1-jandryuk@gmail.com/



Hi,

This series failed the docker-quick@centos7 build test. Please find the testing commands and
their output below. If you have Docker installed, you can probably reproduce it
locally.

=== TEST SCRIPT BEGIN ===
#!/bin/bash
make docker-image-centos7 V=1 NETWORK=1
time make docker-test-quick@centos7 SHOW_ENV=1 J=14 NETWORK=1
=== TEST SCRIPT END ===

  TEST    iotest-qcow2: 268
Failures: 060 071 176 184
Failed 4 of 108 iotests
make: *** [check-tests/check-block.sh] Error 1
Traceback (most recent call last):
  File "./tests/docker/docker.py", line 662, in <module>
    sys.exit(main())
---
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['sudo', '-n', 'docker', 'run', '--label', 'com.qemu.instance.uuid=cb707bce0c3c456d8ecec70aeb08fddc', '-u', '1003', '--security-opt', 'seccomp=unconfined', '--rm', '-e', 'TARGET_LIST=', '-e', 'EXTRA_CONFIGURE_OPTS=', '-e', 'V=', '-e', 'J=14', '-e', 'DEBUG=', '-e', 'SHOW_ENV=1', '-e', 'CCACHE_DIR=/var/tmp/ccache', '-v', '/home/patchew2/.cache/qemu-docker-ccache:/var/tmp/ccache:z', '-v', '/var/tmp/patchew-tester-tmp-mxl5_jec/src/docker-src.2019-11-06-19.55.47.20736:/var/tmp/qemu:z,ro', 'qemu:centos7', '/var/tmp/qemu/run', 'test-quick']' returned non-zero exit status 2.
filter=--filter=label=com.qemu.instance.uuid=cb707bce0c3c456d8ecec70aeb08fddc
make[1]: *** [docker-run] Error 1
make[1]: Leaving directory `/var/tmp/patchew-tester-tmp-mxl5_jec/src'
make: *** [docker-run-test-quick@centos7] Error 2

real    13m1.810s
user    0m8.371s


The full log is available at
http://patchew.org/logs/20191106130309.6737-1-jandryuk@gmail.com/testing.docker-quick@centos7/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Jason Andryuk]

On Wed, Nov 6, 2019 at 8:08 PM <no-reply@patchew.org> wrote:
>
> Patchew URL: https://patchew.org/QEMU/20191106130309.6737-1-jandryuk@gmail.com/
>
>
>
> Hi,
>
> This series failed the docker-quick@centos7 build test. Please find the testing commands and
> their output below. If you have Docker installed, you can probably reproduce it
> locally.
>
> === TEST SCRIPT BEGIN ===
> #!/bin/bash
> make docker-image-centos7 V=1 NETWORK=1
> time make docker-test-quick@centos7 SHOW_ENV=1 J=14 NETWORK=1
> === TEST SCRIPT END ===
>
>   TEST    iotest-qcow2: 268
> Failures: 060 071 176 184
> Failed 4 of 108 iotests
> make: *** [check-tests/check-block.sh] Error 1
> Traceback (most recent call last):
>   File "./tests/docker/docker.py", line 662, in <module>
>     sys.exit(main())
> ---
>     raise CalledProcessError(retcode, cmd)
> subprocess.CalledProcessError: Command '['sudo', '-n', 'docker', 'run', '--label', 'com.qemu.instance.uuid=cb707bce0c3c456d8ecec70aeb08fddc', '-u', '1003', '--security-opt', 'seccomp=unconfined', '--rm', '-e', 'TARGET_LIST=', '-e', 'EXTRA_CONFIGURE_OPTS=', '-e', 'V=', '-e', 'J=14', '-e', 'DEBUG=', '-e', 'SHOW_ENV=1', '-e', 'CCACHE_DIR=/var/tmp/ccache', '-v', '/home/patchew2/.cache/qemu-docker-ccache:/var/tmp/ccache:z', '-v', '/var/tmp/patchew-tester-tmp-mxl5_jec/src/docker-src.2019-11-06-19.55.47.20736:/var/tmp/qemu:z,ro', 'qemu:centos7', '/var/tmp/qemu/run', 'test-quick']' returned non-zero exit status 2.
> filter=--filter=label=com.qemu.instance.uuid=cb707bce0c3c456d8ecec70aeb08fddc
> make[1]: *** [docker-run] Error 1
> make[1]: Leaving directory `/var/tmp/patchew-tester-tmp-mxl5_jec/src'
> make: *** [docker-run-test-quick@centos7] Error 2
>
> real    13m1.810s
> user    0m8.371s
>
>
> The full log is available at
> http://patchew.org/logs/20191106130309.6737-1-jandryuk@gmail.com/testing.docker-quick@centos7/?type=message.
> ---
> Email generated automatically by Patchew [https://patchew.org/].
> Please send your feedback to patchew-devel@redhat.com

The full logs shows iotest failures:

Failures: 060 071 176 184
Failed 4 of 108 iotests

The failures are the lack of SHUTDOWN events:
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP},
"event": "SHUTDOWN", "data": {"guest": false, "reason":
"host-qmp-quit"}}

The results are inconsistent though.  On my workstation, for one run I
had test 071 fail, but the others pass.  On another couple of runs,
they all passed.  An a final one, 176 failed.

Looking at 071, they all send a qmp command to exit, but only some of
the tests have an expected shutdown event.  Looking more broadly, it
seems like tests expect shutdown events.

I don't know the code flow, but is it possible on shutdown for the
chardev to be marked closed before the QMP event is generated?  After
this patch, those would not be sent.  If "quit" is expected to always
generate a QMP event, it seems like some ordering needs to be
enforced.

For the tests, the QMP input comes from a shell "here document" ('<<
EOF'), so I suppose stdin could read EOF and mark the chardev closed
before the QMP event is generated.  Before this change, QMP events
would still be generated and stdout would still be connected. Indeed,
chardev/char-fd.c:fd_chr_read() closes the chardev on stdio EOF
regardless of stdout state.

Regards,
Jason

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Markus Armbruster]

Jason Andryuk <jandryuk@gmail.com> writes:

> Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
> it is set to &qmp_cap_negotiation_commands.  After capability
> negotiation, it is set to &qmp_commands.  If the chardev is closed,
> CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
> chardev is re-opened with CHR_EVENT_OPENED, is it reset to
> &qmp_cap_negotiation_commands.
>
> monitor_qapi_event_emit compares mon->commands to
> &qmp_cap_negotiation_commands, and skips sending events when they are
> equal.

The check's purpose is to ensure we don't send events in capabilities
negotiation mode, i.e. between connect and a successful qmp_capabilities
command.

>         In the case of a closed chardev, QMP events are still sent down
> to the closed chardev which needs to drop them.

True, but I wonder how this can happen.  Can you explain?

> Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
> to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
> since that is how mon->commands is set for a newly opened connections.
>
> Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
> ---
>  monitor/qmp.c | 1 +
>  1 file changed, 1 insertion(+)
>
> diff --git a/monitor/qmp.c b/monitor/qmp.c
> index 9d9e5d8b27..5e2073c5eb 100644
> --- a/monitor/qmp.c
> +++ b/monitor/qmp.c
> @@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
       case CHR_EVENT_CLOSED:
           /*
            * Note: this is only useful when the output of the chardev
            * backend is still open.  For example, when the backend is
            * stdio, it's possible that stdout is still open when stdin
>           * is closed.
>           */
>          monitor_qmp_cleanup_queues(mon);
> +        mon->commands = &qmp_cap_negotiation_commands;
>          json_message_parser_destroy(&mon->parser);
>          json_message_parser_init(&mon->parser, handle_qmp_command,
>                                   mon, NULL);

Patchew reports this loses SHUTDOWN events.  Local testing confirms it
does.  Simplified reproducer:

    $ for ((i=0; i<100; i++)); do printf '{"execute": "qmp_capabilities"}\n{"execute": "quit"}' | upstream-qemu -S -display none -qmp stdio; done | grep -c SHUTDOWN
    84

In this test, the SHUTDOWN event was lost 16 out of 100 times.

Its emission obviously races with the assignment you add.

The comment preceding it provides a clue: after CHR_EVENT_CLOSED, we
know the input direction is gone, and we duly clean up that part of the
monitor.  But the output direction may or may not be gone, so we don't
touch it.  Your assignment touches it.  This is not the correct spot.
I can't tell you offhand where the correct spot is.  Perhaps Marc-André
can.

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Marc-André Lureau]

Hi

On Wed, Nov 13, 2019 at 4:41 PM Markus Armbruster <armbru@redhat.com> wrote:
>
> Jason Andryuk <jandryuk@gmail.com> writes:
>
> > Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
> > it is set to &qmp_cap_negotiation_commands.  After capability
> > negotiation, it is set to &qmp_commands.  If the chardev is closed,
> > CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
> > chardev is re-opened with CHR_EVENT_OPENED, is it reset to
> > &qmp_cap_negotiation_commands.
> >
> > monitor_qapi_event_emit compares mon->commands to
> > &qmp_cap_negotiation_commands, and skips sending events when they are
> > equal.
>
> The check's purpose is to ensure we don't send events in capabilities
> negotiation mode, i.e. between connect and a successful qmp_capabilities
> command.
>
> >         In the case of a closed chardev, QMP events are still sent down
> > to the closed chardev which needs to drop them.
>
> True, but I wonder how this can happen.  Can you explain?
>
> > Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
> > to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
> > since that is how mon->commands is set for a newly opened connections.
> >
> > Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
> > ---
> >  monitor/qmp.c | 1 +
> >  1 file changed, 1 insertion(+)
> >
> > diff --git a/monitor/qmp.c b/monitor/qmp.c
> > index 9d9e5d8b27..5e2073c5eb 100644
> > --- a/monitor/qmp.c
> > +++ b/monitor/qmp.c
> > @@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
>        case CHR_EVENT_CLOSED:
>            /*
>             * Note: this is only useful when the output of the chardev
>             * backend is still open.  For example, when the backend is
>             * stdio, it's possible that stdout is still open when stdin
> >           * is closed.
> >           */
> >          monitor_qmp_cleanup_queues(mon);
> > +        mon->commands = &qmp_cap_negotiation_commands;
> >          json_message_parser_destroy(&mon->parser);
> >          json_message_parser_init(&mon->parser, handle_qmp_command,
> >                                   mon, NULL);
>
> Patchew reports this loses SHUTDOWN events.  Local testing confirms it
> does.  Simplified reproducer:
>
>     $ for ((i=0; i<100; i++)); do printf '{"execute": "qmp_capabilities"}\n{"execute": "quit"}' | upstream-qemu -S -display none -qmp stdio; done | grep -c SHUTDOWN
>     84
>
> In this test, the SHUTDOWN event was lost 16 out of 100 times.
>
> Its emission obviously races with the assignment you add.
>
> The comment preceding it provides a clue: after CHR_EVENT_CLOSED, we
> know the input direction is gone, and we duly clean up that part of the
> monitor.  But the output direction may or may not be gone, so we don't
> touch it.  Your assignment touches it.  This is not the correct spot.
> I can't tell you offhand where the correct spot is.  Perhaps Marc-André
> can.

The same "closed" event is used to signal read-disconnected,
write-disconnected and hup.

To implement half-closed signaling, we would need more events/state
(probably change the chardev API to use input and output streams).
Tbh, I am not sure it's really worth at this point, unless we have a
"visible" bug to fix.





-- 
Marc-André Lureau

Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED

[Jason Andryuk]

On Wed, Nov 13, 2019 at 8:18 AM Marc-André Lureau
<marcandre.lureau@gmail.com> wrote:
>
> Hi
>
> On Wed, Nov 13, 2019 at 4:41 PM Markus Armbruster <armbru@redhat.com> wrote:
> >
> > Jason Andryuk <jandryuk@gmail.com> writes:
> >
> > > Currently, mon->commands is uninitialized until CHR_EVENT_OPENED where
> > > it is set to &qmp_cap_negotiation_commands.  After capability
> > > negotiation, it is set to &qmp_commands.  If the chardev is closed,
> > > CHR_EVENT_CLOSED, mon->commands remains as &qmp_commands.  Only once the
> > > chardev is re-opened with CHR_EVENT_OPENED, is it reset to
> > > &qmp_cap_negotiation_commands.
> > >
> > > monitor_qapi_event_emit compares mon->commands to
> > > &qmp_cap_negotiation_commands, and skips sending events when they are
> > > equal.
> >
> > The check's purpose is to ensure we don't send events in capabilities
> > negotiation mode, i.e. between connect and a successful qmp_capabilities
> > command.
> >
> > >         In the case of a closed chardev, QMP events are still sent down
> > > to the closed chardev which needs to drop them.
> >
> > True, but I wonder how this can happen.  Can you explain?

I was working on QMP over Xen's argo inter-vm communication for the
OpenXT project.  We had a lock up because we weren't properly dropping
QMP events in the chardev, even though we called CHR_EVENT_CLOSED.  We
fixed the argo chardev to drop messages like other chardevs, but my
investigation found QMP was still sending events even through it was
closed.

Xen's libxl opens a UNIX domain QMP socket for the duration of issuing
a command and then closes it.  OpenXT does the same over Argo.  In the
case of connecting and disconnecting, QMP events continue to be
generated after the first connection, even though there is nothing
connected for an unbounded length of time.  I was just trying to
optimize that scenario by skipping QMP events when disconnected.

> > > Set mon->commands to &qmp_cap_negotiation_commands for CHR_EVENT_CLOSED
> > > to stop sending events.  Setting for the CHR_EVENT_OPENED case remains
> > > since that is how mon->commands is set for a newly opened connections.
> > >
> > > Signed-off-by: Jason Andryuk <jandryuk@gmail.com>
> > > ---
> > >  monitor/qmp.c | 1 +
> > >  1 file changed, 1 insertion(+)
> > >
> > > diff --git a/monitor/qmp.c b/monitor/qmp.c
> > > index 9d9e5d8b27..5e2073c5eb 100644
> > > --- a/monitor/qmp.c
> > > +++ b/monitor/qmp.c
> > > @@ -333,6 +333,7 @@ static void monitor_qmp_event(void *opaque, int event)
> >        case CHR_EVENT_CLOSED:
> >            /*
> >             * Note: this is only useful when the output of the chardev
> >             * backend is still open.  For example, when the backend is
> >             * stdio, it's possible that stdout is still open when stdin
> > >           * is closed.
> > >           */
> > >          monitor_qmp_cleanup_queues(mon);
> > > +        mon->commands = &qmp_cap_negotiation_commands;
> > >          json_message_parser_destroy(&mon->parser);
> > >          json_message_parser_init(&mon->parser, handle_qmp_command,
> > >                                   mon, NULL);
> >
> > Patchew reports this loses SHUTDOWN events.  Local testing confirms it
> > does.  Simplified reproducer:
> >
> >     $ for ((i=0; i<100; i++)); do printf '{"execute": "qmp_capabilities"}\n{"execute": "quit"}' | upstream-qemu -S -display none -qmp stdio; done | grep -c SHUTDOWN
> >     84
> >
> > In this test, the SHUTDOWN event was lost 16 out of 100 times.
> >
> > Its emission obviously races with the assignment you add.
> >
> > The comment preceding it provides a clue: after CHR_EVENT_CLOSED, we
> > know the input direction is gone, and we duly clean up that part of the
> > monitor.  But the output direction may or may not be gone, so we don't
> > touch it.  Your assignment touches it.  This is not the correct spot.
> > I can't tell you offhand where the correct spot is.  Perhaps Marc-André
> > can.
>
> The same "closed" event is used to signal read-disconnected,
> write-disconnected and hup.
>
> To implement half-closed signaling, we would need more events/state
> (probably change the chardev API to use input and output streams).
> Tbh, I am not sure it's really worth at this point, unless we have a
> "visible" bug to fix.

Yes, I agree.

Thanks for your time looking at this.

Regards,
Jason