Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED
On Wed, Nov 13, 2019 at 8:18 AM Marc-André Lureau wrote: > > Hi > > On Wed, Nov 13, 2019 at 4:41 PM Markus Armbruster wrote: > > > > Jason Andryuk 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 > > > --- > > > 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
Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED
Hi On Wed, Nov 13, 2019 at 4:41 PM Markus Armbruster wrote: > > Jason Andryuk 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 > > --- > > 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 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 > --- > 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
On Wed, Nov 6, 2019 at 8:08 PM wrote: > > Patchew URL: > https://patchew.org/QEMU/20191106130309.6737-1-jandr...@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 === > > TESTiotest-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 > 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 > > real13m1.810s > user0m8.371s > > > The full log is available at > http://patchew.org/logs/20191106130309.6737-1-jandr...@gmail.com/testing.docker-quick@centos7/?type=message. > --- > Email generated automatically by Patchew [https://patchew.org/]. > Please send your feedback to patchew-de...@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
Patchew URL: https://patchew.org/QEMU/20191106130309.6737-1-jandr...@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 === TESTiotest-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 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 real13m1.810s user0m8.371s The full log is available at http://patchew.org/logs/20191106130309.6737-1-jandr...@gmail.com/testing.docker-quick@centos7/?type=message. --- Email generated automatically by Patchew [https://patchew.org/]. Please send your feedback to patchew-de...@redhat.com
Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED
On Wed, Nov 6, 2019 at 9:53 AM Marc-André Lureau wrote: > > Hi > > On Wed, Nov 6, 2019 at 5:04 PM Jason Andryuk 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 > > --- > > 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 Thank you. -Jason
Re: [PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED
Hi On Wed, Nov 6, 2019 at 5:04 PM Jason Andryuk 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 > --- > 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 -- Marc-André Lureau
[PATCH] qmp: Reset mon->commands on CHR_EVENT_CLOSED
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 --- 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