Re: test-blockjob: intermittent CI failures in msys2-64bit job

[Hanna Czenczek <hreitz@redhat.com>]

On 24.04.23 20:32, Vladimir Sementsov-Ogievskiy wrote:
> On 24.04.23 16:36, Emanuele Giuseppe Esposito wrote:
>>
>>
>> Am 21/04/2023 um 12:13 schrieb Vladimir Sementsov-Ogievskiy:
>>> On 17.03.23 15:35, Thomas Huth wrote:
>>>> On 17/03/2023 11.17, Peter Maydell wrote:
>>>>> On Mon, 6 Mar 2023 at 11:16, Peter Maydell <peter.maydell@linaro.org>
>>>>> wrote:
>>>>>>
>>>>>> On Fri, 3 Mar 2023 at 18:36, Peter Maydell
>>>>>> <peter.maydell@linaro.org> wrote:
>>>>>>>
>>>>>>> I've noticed that test-blockjob seems to fail intermittently
>>>>>>> on the msys2-64bit job:
>>>>>>>
>>>>>>> https://gitlab.com/qemu-project/qemu/-/jobs/3872508803
>>>>>>> https://gitlab.com/qemu-project/qemu/-/jobs/3871061024
>>>>>>> https://gitlab.com/qemu-project/qemu/-/jobs/3865312440
>>>>>>>
>>>>>>> Sample output:
>>>>>>> | 53/89
>>>>>>> ERROR:../tests/unit/test-blockjob.c:499:test_complete_in_standby:
>>>>>>> assertion failed: (job->status == JOB_STATUS_STANDBY) ERROR
>>>>>>> 53/89 qemu:unit / test-blockjob ERROR 0.08s exit status 3
>>>>>
>>>>>> Here's an intermittent failure from my macos x86 machine:
>>>>>>
>>>>>> 172/621 qemu:unit / test-blockjob
>>>>>>              ERROR           0.26s   killed by signal 6 SIGABRT
>>>>>
>>>>> And an intermittent on the freebsd 13 CI job:
>>>>> https://gitlab.com/qemu-project/qemu/-/jobs/3950667240
>>>>>
>>>>>>>> MALLOC_PERTURB_=197
>>>>>>>> G_TEST_BUILDDIR=/tmp/cirrus-ci-build/build/tests/unit
>>>>>>>> G_TEST_SRCDIR=/tmp/cirrus-ci-build/tests/unit
>>>>>>>> /tmp/cirrus-ci-build/build/tests/unit/test-blockjob --tap -k
>>>>> ▶ 178/650 /blockjob/ids
>>>>>              OK
>>>>> 178/650 qemu:unit / test-blockjob
>>>>>              ERROR           0.31s   killed by signal 6 SIGABRT
>>>>> ――――――――――――――――――――――――――――――――――――― ✀
>>>>> ―――――――――――――――――――――――――――――――――――――
>>>>> stderr:
>>>>> Assertion failed: (job->status == JOB_STATUS_STANDBY), function
>>>>> test_complete_in_standby, file ../tests/unit/test-blockjob.c, line
>>>>> 499.
>>>>>
>>>>>
>>>>> TAP parsing error: Too few tests run (expected 9, got 1)
>>>>> (test program exited with status code -6)
>>>>> ―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― 
>>>>>
>>>>>
>>>>> Anybody in the block team looking at these, or shall we just
>>>>> disable this test entirely ?
>>>>
>>>> I ran into this issue today, too:
>>>>
>>>>    https://gitlab.com/thuth/qemu/-/jobs/3954367101
>>>>
>>>> ... if nobody is interested in fixing this test, I think we should
>>>> disable it...
>>>>
>>>>    Thomas
>>>>
>>>
>>> I'm looking at this now, and seems that it's broken since
>>> 6f592e5aca1a27fe1c1f6 "job.c: enable job lock/unlock and remove
>>> Aiocontext locks", as it stops critical section by new
>>> aio_context_release() call exactly after bdrv_drain_all_and(), so it's
>>> not a surprise that job may start at that moment and the following
>>> assertion fires.
>>>
>>> Emanuele could please look at it?
>>>
>> Well if I understood correctly, the only thing that was preventing the
>> job from continuing was the aiocontext lock held.
>>
>> The failing assertion even mentions that:
>> /* Lock the IO thread to prevent the job from being run */
>> [...]
>> /* But the job cannot run, so it will remain on standby */
>> assert(job->status == JOB_STATUS_STANDBY);
>>
>> Essentially bdrv_drain_all_end() would wake up the job coroutine, but it
>> would anyways block somewhere after since the aiocontext lock was taken
>> by the test.
>>
>> Now that we got rid of aiocontext lock in job code, nothing prevents the
>> test from resuming.
>> Mixing job lock and aiocontext acquire/release is not a good idea, and
>> it would anyways block job_resume() called by bdrv_drain_all_end(), so
>> the test itself would deadlock.
>>
>> So unless @Kevin has a better idea, this seems to be just an "hack" to
>> test stuff that is not possible to do now anymore. What I would suggest
>> is to get rid of that test, or at least of that assert function. I
>> unfortunately cannot reproduce the failure, but I think the remaining
>> functions called by the test should run as expected.
>>
>
> Thanks! I agree. Probably, alternatively we could just expand the 
> drained section, like
>
> @@ -488,12 +488,6 @@ static void test_complete_in_standby(void)
>      bdrv_drain_all_begin();
>      assert_job_status_is(job, JOB_STATUS_STANDBY);
>
> -    /* Lock the IO thread to prevent the job from being run */
> -    aio_context_acquire(ctx);
> -    /* This will schedule the job to resume it */
> -    bdrv_drain_all_end();
> -    aio_context_release(ctx);
> -
>      WITH_JOB_LOCK_GUARD() {
>          /* But the job cannot run, so it will remain on standby */
>          assert(job->status == JOB_STATUS_STANDBY);
> @@ -511,6 +505,7 @@ static void test_complete_in_standby(void)
>          job_dismiss_locked(&job, &error_abort);
>      }
>
> +    bdrv_drain_all_end();
>      aio_context_acquire(ctx);
>      destroy_blk(blk);
>      aio_context_release(ctx);
>
>
> But, seems that test wanted to specifically test job, that still in 
> STANDBY exactly after drained section...
>
> [cc: Hanna]
>
> Hanna, it was your test (added in 
> c2c731a4d35062295cd3260e66b3754588a2fad4, two years ago). Don't you 
> remember was important to catch STANDBY job *after* a drained section?

I’m not quite sure, but I think the idea was that we basically try to 
get as close to something that might come in over QMP.  Over QMP, you 
can’t issue a job-complete while keeping everything drained, so I 
wouldn’t just extend the drained section.

Getting rid of the assert function also seems pointless.  If we want to 
test whether job-complete works on tests in standby, we must put the 
test in standby, and verify this.  We can get rid of the test, of 
course, but it is a regression test, so it isn’t like it was added just 
for fun.  Then again, it’s now already effectively commented out via 
environment variable, so it doesn’t seem like a loss in practice to to 
fully drop it.

Anyway – the thing I wonder about is, if this is to test whether jobs in 
standby can be completed…  Why don’t we just pause the job instead of 
going through the context lock hassle?  I.e. just put a job_pause() 
right after bdrv_drain_all_begin().

If I’m not mistaken, reproducing the bug in the test seems really simple 
by adding a sleep(1) right before WITH_JOB_LOCK_GUARD(); and doing that 
works just fine if only you have a job_pause() in the drained section.  
(And dropping the aio_context_acquire()/release() calls, because they 
don’t do anything anymore.)

Hanna