Re: [PATCH] monitor: Fix order in monitor_cleanup()

[Markus Armbruster]

Kevin Wolf <kwolf@redhat.com> writes:

> Am 29.01.2021 um 13:53 hat Markus Armbruster geschrieben:
>> I ran into odd behavior the other day, and bisected it to this commit.
>> 
>>     $ qemu-system-x86_64 -display none -chardev 
>> socket,id=qmp,path=test-qmp,server=on,wait=off -mon mode=control,chardev=qmp
>> 
>> In another terminal, create a bunch of FIFOs, then use them to have some
>> in-band commands block, with out-of-band commands interleaved just
>> because:
>> 
>>     $ for ((i=0; i<20; i++)); do mkfifo fifo$i; done
>>     $ cat oob-test2
>>     {"execute": "qmp_capabilities", "arguments": {"enable": ["oob"]}}
>>     {"exec-oob": "migrate-pause", "id": 0}
>>     {"execute": "memsave", "id": 1, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo1"}}
>>     {"exec-oob": "migrate-pause", "id": 2}
>>     {"execute": "memsave", "id": 3, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo3"}}
>>     {"exec-oob": "migrate-pause", "id": 4}
>>     {"execute": "memsave", "id": 5, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo5"}}
>>     {"exec-oob": "migrate-pause", "id": 6}
>>     {"execute": "memsave", "id": 7, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo7"}}
>>     {"exec-oob": "migrate-pause", "id": 8}
>>     {"execute": "memsave", "id": 9, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo9"}}
>>     {"exec-oob": "migrate-pause", "id": 10}
>>     {"execute": "memsave", "id": 11, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo11"}}
>>     {"exec-oob": "migrate-pause", "id": 12}
>>     {"execute": "memsave", "id": 13, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo13"}}
>>     {"exec-oob": "migrate-pause", "id": 14}
>>     {"execute": "memsave", "id": 15, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo15"}}
>>     {"exec-oob": "migrate-pause", "id": 16}
>>     {"execute": "memsave", "id": 17, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo17"}}
>>     {"exec-oob": "migrate-pause", "id": 18}
>>     {"execute": "memsave", "id": 19, "arguments": {"val": 0, "size": 4096, 
>> "filename": "fifo19"}}
>>     {"exec-oob": "migrate-pause", "id": 20}
>>     $ socat -t99999 STDIO UNIX-CONNECT:$HOME/work/images/test-qmp <oob-test2
>>     {"QMP": {"version": {"qemu": {"micro": 50, "minor": 1, "major": 5}, 
>> "package": "v5.1.0-2224-g8db1efd3f3"}, "capabilities": ["oob"]}}
>>     {"return": {}}
>>     {"id": 0, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 2, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 4, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 6, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 8, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 10, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 12, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 14, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>>     {"id": 16, "error": {"class": "GenericError", "desc": "migrate-pause is 
>> currently only supported during postcopy-active state"}}
>> 
>> Looking good: the out-of-band commands jump the queue until the queue is
>> too full for jumping.
>> 
>> Now go back to the first terminal, and hit C-c.
>> 
>> Before this commit, the second terminal shows the shutdown event
>> 
>>     {"timestamp": {"seconds": 1611923623, "microseconds": 528169}, "event": 
>> "SHUTDOWN", "data": {"guest": false, "reason": "host-signal"}}
>> 
>> and the first terminal shows
>> 
>>     ^Cqemu-system-x86_64: terminating on signal 2
>> 
>> QEMU terminates with exit status 0.  Good (except for the exit status,
>> but let's ignore that).
>> 
>> After the commit, the second terminal additionally shows the error reply
>> for (in-band) command 1
>> 
>>     {"id": 1, "error": {"class": "GenericError", "desc": "Could not open 
>> 'fifo1': Interrupted system call"}}
>>     {"timestamp": {"seconds": 1611923812, "microseconds": 520891}, "event": 
>> "SHUTDOWN", "data": {"guest": false, "reason": "host-signal"}}
>> 
>> and the first terminal still shows
>> 
>>     ^Cqemu-system-x86_64: terminating on signal 2
>> 
>> However, QEMU does *not* terminate.  When I hit C-c again, the second
>> terminal gives me the next in-band reply
>> 
>>     {"id": 3, "error": {"class": "GenericError", "desc": "Could not open 
>> 'fifo3': Interrupted system call"}}
>> 
>> and the first one another
>> 
>>     ^C
>> 
>> Hitting C-c some more gives me more in-band replies and more ^C.
>
> The problem is that monitor_qmp_dispatcher_co() doesn't check whether it
> should shut down unless it would have to wait for a new request.
>
> So 'memsave' tries to open the FIFO, this blocks and ^C results in EINTR
> for the open(), which makes the 'memsave' command fail.

Perhaps the command should retry after EINTR.  Out of scope here.

>                                                         Then
> monitor_qmp_dispatcher_co() tries to execute the rest of the queued
> commands, i.e. the next 'memsave' that will hang in the same way.
>
> Fixing this is easy enough:
>
> diff --git a/monitor/qmp.c b/monitor/qmp.c
> index 43880fa623..46939537b4 100644
> --- a/monitor/qmp.c
> +++ b/monitor/qmp.c
> @@ -227,6 +227,10 @@ void coroutine_fn monitor_qmp_dispatcher_co(void *data)
>           */
>          qatomic_mb_set(&qmp_dispatcher_co_busy, false);
>
> +        if (qmp_dispatcher_co_shutdown) {
> +            return;
> +        }
> +
>          while (!(req_obj = monitor_qmp_requests_pop_any_with_lock())) {
>              /*
>               * No more requests to process.  Wait to be reentered from
>
>> The ninth C-c gives me the error reply for (in-band) command 17, and a crash:
>> 
>> Terminal 1 now shows
>> 
>>     ^Cqemu-system-x86_64-qemu: terminating on signal 2
>>     ^C^C^C^C^C^C^C^Cqemu-system-x86_64-qemu: ../util/async.c:343: 
>> aio_ctx_finalize: Assertion `flags & BH_DELETED' failed.
>>     Aborted (core dumped)
>
> So all of this happens inside of monitor_cleanup(), while waiting for
> monitor_qmp_dispatcher_co() to shut down:
>
>     AIO_WAIT_WHILE(qemu_get_aio_context(),
>                    (aio_poll(iohandler_get_aio_context(), false),
>                     qatomic_mb_read(&qmp_dispatcher_co_busy)));
>
> Importantly, this is _after_ calling iothread_stop(), which made sure
> that all pending BHs in the monitor iothread are executed.
>
> What now happens is that monitor_qmp_dispatcher_co() wants to resume
> the monitor. This schedules a new BH on the iothread, which was already
> supposed to be inactive.
>
> When finally all requests are handled and monitor_cleanup() continues
> after the polling loop and calls iothread_destroy(), we notice that
> there is a pending BH where there shouldn't be any and abort.
>
> I think this means that the commit should have moved even the
> iothread_stop() call to below the polling loop. I can't reproduce the
> problem any more with the fix above, but I think the current order in
> monitor_cleanup() is still a (possibly latent) bug.
>
> So why did all of that work before 357bda95?
>
> If the old code didn't crash as described in the commit message, it
> would just free all kinds of monitor resources while the coroutine was
> still running. This includes removing all pending requests from the
> queue. I guess this is what accidentally made it "work" previously.

Awesome.

Thanks for writing up your analysis!