virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Cole Robinson]

Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
suite. rc0, rc1, rc2 have been consistently affected, it reproduces
consistently in parts of Fedora's build system. Here's an example build
log for rc2 x86 against Fedora 32

https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0-0.6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz

The full test error:

...
PASS 26 qtest-arm/qos-test
/arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/synth/readdir/split_128
PASS 27 qtest-arm/qos-test
/arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/local/config
Received response 7 (RLERROR) instead of 73 (RMKDIR)
ERROR qtest-arm/qos-test - Bail out!
ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
failed (hdr.id == id): (7 == 73)
Rlerror has errno 95 (Operation not supported)
**
ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
failed (hdr.id == id): (7 == 73)
make: *** [Makefile.mtest:1257: run-test-155] Error 1
error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)


Thanks,
Cole

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Greg Kurz]

Fixed maintainer's address: s/oss@crudebyte.com/qemu_oss@crudebyte.com

On Sat, 21 Nov 2020 17:03:14 -0500
Cole Robinson <crobinso@redhat.com> wrote:

> Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
> suite. rc0, rc1, rc2 have been consistently affected, it reproduces
> consistently in parts of Fedora's build system. Here's an example build
> log for rc2 x86 against Fedora 32
> 
> https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0-0.6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz
> 
> The full test error:
> 
> ...
> PASS 26 qtest-arm/qos-test
> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/synth/readdir/split_128
> PASS 27 qtest-arm/qos-test
> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/local/config

Ok so the next test is supposed to be:

/arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/local/create_dir

This was added recently. This configures the virtio-9p device in QEMU
to serve a real test directory from the host. This test directory is
created under the current directory of the test process. The purpose
of the test is then to ask the 9p server to create a directory within
the test directory.

> Received response 7 (RLERROR) instead of 73 (RMKDIR)
> ERROR qtest-arm/qos-test - Bail out!
> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> failed (hdr.id == id): (7 == 73)
> Rlerror has errno 95 (Operation not supported)

So this basically means that QEMU got ENOTSUP/EOPNOTSUPP when calling
mkdir() into the test directory... not sure what could cause that. I'd
need more details on the filesystem setup for the build.

Anyway, we already experienced some breakage in upstream CI because of
the same family of tests that do real access to the host filesystem.
Since they're being introduced in QEMU 5.2, I'll try to see if I can
disable them to be run by default for RC3.

Cheers,

--
Greg

> **
> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> failed (hdr.id == id): (7 == 73)
> make: *** [Makefile.mtest:1257: run-test-155] Error 1
> error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)
> 
> 
> Thanks,
> Cole
> 

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Christian Schoenebeck]

On Montag, 23. November 2020 14:17:34 CET Greg Kurz wrote:
> Fixed maintainer's address: s/oss@crudebyte.com/qemu_oss@crudebyte.com
> 
> On Sat, 21 Nov 2020 17:03:14 -0500
> 
> Cole Robinson <crobinso@redhat.com> wrote:
> > Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
> > suite. rc0, rc1, rc2 have been consistently affected, it reproduces
> > consistently in parts of Fedora's build system. Here's an example build
> > log for rc2 x86 against Fedora 32
> > 
> > https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0-0.
> > 6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz
> > 
> > The full test error:
> > 
> > ...
> > PASS 26 qtest-arm/qos-test
> > /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-test
> > s/synth/readdir/split_128 PASS 27 qtest-arm/qos-test
> > /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-test
> > s/local/config
> Ok so the next test is supposed to be:
> 
> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-tests/
> local/create_dir
> 
> This was added recently. This configures the virtio-9p device in QEMU
> to serve a real test directory from the host. This test directory is
> created under the current directory of the test process. The purpose
> of the test is then to ask the 9p server to create a directory within
> the test directory.
> 
> > Received response 7 (RLERROR) instead of 73 (RMKDIR)
> > ERROR qtest-arm/qos-test - Bail out!
> > ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> > failed (hdr.id == id): (7 == 73)
> > Rlerror has errno 95 (Operation not supported)
> 
> So this basically means that QEMU got ENOTSUP/EOPNOTSUPP when calling
> mkdir() into the test directory... not sure what could cause that. I'd
> need more details on the filesystem setup for the build.
> 
> Anyway, we already experienced some breakage in upstream CI because of
> the same family of tests that do real access to the host filesystem.
> Since they're being introduced in QEMU 5.2, I'll try to see if I can
> disable them to be run by default for RC3.
> 
> Cheers,
> 
> --
> Greg
> 
> > **
> > ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> > failed (hdr.id == id): (7 == 73)
> > make: *** [Makefile.mtest:1257: run-test-155] Error 1
> > error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)
> > 
> > 
> > Thanks,
> > Cole

Yeah, looks like the mkdir() call which is supposed to create the 9p test 
directory, is failing there for some reason. The question is how to find that 
out (effectively) without having access to an affected system.

It's now too late for 5.2, but I think for 6.0 it would make sense introducing 
a dedicated 9p option loglevel=..., so we can tell people to enable this to 
capture the precise source location where an error ocurred. That would mean 
spreading a huge bunch of macros all over the 9p code base, but it would 
definitely help a lot understanding the root cause of reported issues in an 
efficient way.

Best regards,
Christian Schoenebeck

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Greg Kurz]

On Mon, 23 Nov 2020 14:48:15 +0100
Christian Schoenebeck <qemu_oss@crudebyte.com> wrote:

> On Montag, 23. November 2020 14:17:34 CET Greg Kurz wrote:

[...]

> 
> Yeah, looks like the mkdir() call which is supposed to create the 9p test 
> directory, is failing there for some reason. The question is how to find that 
> out (effectively) without having access to an affected system.
> 

I'd say through a bug report that provide enough details on the
host system.

> It's now too late for 5.2, but I think for 6.0 it would make sense introducing 
> a dedicated 9p option loglevel=..., so we can tell people to enable this to 
> capture the precise source location where an error ocurred. That would mean 
> spreading a huge bunch of macros all over the 9p code base, but it would 
> definitely help a lot understanding the root cause of reported issues in an 
> efficient way.
> 

Maybe but in any case we still should fix this somehow for 5.2.
The "local" tests are certainly valuable but we can't let them
break automated CI or build systems.

Since this is basically triggered by a 'make check' we can
workaround the issue by marking the "local" tests as "slow".

I'll send a patch ASAP.

> Best regards,
> Christian Schoenebeck
> 
> 

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Christian Schoenebeck]

On Montag, 23. November 2020 14:48:15 CET Christian Schoenebeck wrote:
> On Montag, 23. November 2020 14:17:34 CET Greg Kurz wrote:
> > Fixed maintainer's address: s/oss@crudebyte.com/qemu_oss@crudebyte.com
> > 
> > On Sat, 21 Nov 2020 17:03:14 -0500
> > 
> > Cole Robinson <crobinso@redhat.com> wrote:
> > > Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
> > > suite. rc0, rc1, rc2 have been consistently affected, it reproduces
> > > consistently in parts of Fedora's build system. Here's an example build
> > > log for rc2 x86 against Fedora 32
> > > 
> > > https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0-> > > 0.
> > > 6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz
> > > 
> > > The full test error:
> > > 
> > > ...
> > > PASS 26 qtest-arm/qos-test
> > > /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-te
> > > st
> > > s/synth/readdir/split_128 PASS 27 qtest-arm/qos-test
> > > /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-te
> > > st
> > > s/local/config
> > 
> > Ok so the next test is supposed to be:
> > 
> > /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-test
> > s/ local/create_dir
> > 
> > This was added recently. This configures the virtio-9p device in QEMU
> > to serve a real test directory from the host. This test directory is
> > created under the current directory of the test process. The purpose
> > of the test is then to ask the 9p server to create a directory within
> > the test directory.
> > 
> > > Received response 7 (RLERROR) instead of 73 (RMKDIR)
> > > ERROR qtest-arm/qos-test - Bail out!
> > > ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> > > failed (hdr.id == id): (7 == 73)
> > > Rlerror has errno 95 (Operation not supported)
> > 
> > So this basically means that QEMU got ENOTSUP/EOPNOTSUPP when calling
> > mkdir() into the test directory... not sure what could cause that. I'd
> > need more details on the filesystem setup for the build.
> > 
> > Anyway, we already experienced some breakage in upstream CI because of
> > the same family of tests that do real access to the host filesystem.
> > Since they're being introduced in QEMU 5.2, I'll try to see if I can
> > disable them to be run by default for RC3.
> > 
> > Cheers,
> > 
> > --
> > Greg
> > 
> > > **
> > > ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> > > failed (hdr.id == id): (7 == 73)
> > > make: *** [Makefile.mtest:1257: run-test-155] Error 1
> > > error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)
> > > 
> > > 
> > > Thanks,
> > > Cole
> 
> Yeah, looks like the mkdir() call which is supposed to create the 9p test
> directory, is failing there for some reason. The question is how to find
> that out (effectively) without having access to an affected system.
> 
> It's now too late for 5.2, but I think for 6.0 it would make sense
> introducing a dedicated 9p option loglevel=..., so we can tell people to
> enable this to capture the precise source location where an error ocurred.
> That would mean spreading a huge bunch of macros all over the 9p code base,
> but it would definitely help a lot understanding the root cause of reported
> issues in an efficient way.
> 
> Best regards,
> Christian Schoenebeck

Cole, does the affected host system probably not have xattrs enabled on its 
file system?

Best regards,
Christian Schoenebeck

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Cole Robinson]

On 11/23/20 2:45 PM, Christian Schoenebeck wrote:
> On Montag, 23. November 2020 14:48:15 CET Christian Schoenebeck wrote:
>> On Montag, 23. November 2020 14:17:34 CET Greg Kurz wrote:
>>> Fixed maintainer's address: s/oss@crudebyte.com/qemu_oss@crudebyte.com
>>>
>>> On Sat, 21 Nov 2020 17:03:14 -0500
>>>
>>> Cole Robinson <crobinso@redhat.com> wrote:
>>>> Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
>>>> suite. rc0, rc1, rc2 have been consistently affected, it reproduces
>>>> consistently in parts of Fedora's build system. Here's an example build
>>>> log for rc2 x86 against Fedora 32
>>>>
>>>> https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0-> > > 0.
>>>> 6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz
>>>>
>>>> The full test error:
>>>>
>>>> ...
>>>> PASS 26 qtest-arm/qos-test
>>>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-te
>>>> st
>>>> s/synth/readdir/split_128 PASS 27 qtest-arm/qos-test
>>>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-te
>>>> st
>>>> s/local/config
>>>
>>> Ok so the next test is supposed to be:
>>>
>>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-test
>>> s/ local/create_dir
>>>
>>> This was added recently. This configures the virtio-9p device in QEMU
>>> to serve a real test directory from the host. This test directory is
>>> created under the current directory of the test process. The purpose
>>> of the test is then to ask the 9p server to create a directory within
>>> the test directory.
>>>
>>>> Received response 7 (RLERROR) instead of 73 (RMKDIR)
>>>> ERROR qtest-arm/qos-test - Bail out!
>>>> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
>>>> failed (hdr.id == id): (7 == 73)
>>>> Rlerror has errno 95 (Operation not supported)
>>>
>>> So this basically means that QEMU got ENOTSUP/EOPNOTSUPP when calling
>>> mkdir() into the test directory... not sure what could cause that. I'd
>>> need more details on the filesystem setup for the build.
>>>
>>> Anyway, we already experienced some breakage in upstream CI because of
>>> the same family of tests that do real access to the host filesystem.
>>> Since they're being introduced in QEMU 5.2, I'll try to see if I can
>>> disable them to be run by default for RC3.
>>>
>>> Cheers,
>>>
>>> --
>>> Greg
>>>
>>>> **
>>>> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
>>>> failed (hdr.id == id): (7 == 73)
>>>> make: *** [Makefile.mtest:1257: run-test-155] Error 1
>>>> error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)
>>>>
>>>>
>>>> Thanks,
>>>> Cole
>>
>> Yeah, looks like the mkdir() call which is supposed to create the 9p test
>> directory, is failing there for some reason. The question is how to find
>> that out (effectively) without having access to an affected system.
>>
>> It's now too late for 5.2, but I think for 6.0 it would make sense
>> introducing a dedicated 9p option loglevel=..., so we can tell people to
>> enable this to capture the precise source location where an error ocurred.
>> That would mean spreading a huge bunch of macros all over the 9p code base,
>> but it would definitely help a lot understanding the root cause of reported
>> issues in an efficient way.
>>
>> Best regards,
>> Christian Schoenebeck
> 
> Cole, does the affected host system probably not have xattrs enabled on its 
> file system?
> 

Hmm I'm not sure, I will try to investigate.

google tells me David Gilbert also hit this too earlier:
https://www.mail-archive.com/qemu-devel@nongnu.org/msg754556.html

Maybe he remembers details of his setup, CC'd

- Cole

Re: virtio-9p-test.c:300:v9fs_req_recv: assertion failed (hdr.id == id): (7 == 73)

[Christian Schoenebeck]

On Dienstag, 24. November 2020 14:25:17 CET Cole Robinson wrote:
> On 11/23/20 2:45 PM, Christian Schoenebeck wrote:
> > On Montag, 23. November 2020 14:48:15 CET Christian Schoenebeck wrote:
> >> On Montag, 23. November 2020 14:17:34 CET Greg Kurz wrote:
> >>> Fixed maintainer's address: s/oss@crudebyte.com/qemu_oss@crudebyte.com
> >>> 
> >>> On Sat, 21 Nov 2020 17:03:14 -0500
> >>> 
> >>> Cole Robinson <crobinso@redhat.com> wrote:
> >>>> Hi, I'm consistently seeing this assertion running the qemu-5.2.0  test
> >>>> suite. rc0, rc1, rc2 have been consistently affected, it reproduces
> >>>> consistently in parts of Fedora's build system. Here's an example build
> >>>> log for rc2 x86 against Fedora 32
> >>>> 
> >>>> https://download.copr.fedorainfracloud.org/results/@kubevirt/qemu-5.2.0
> >>>> -> > > 0. 6.rc2/fedora-32-x86_64/01781514-qemu/builder-live.log.gz
> >>>> 
> >>>> The full test error:
> >>>> 
> >>>> ...
> >>>> PASS 26 qtest-arm/qos-test
> >>>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-t
> >>>> e
> >>>> st
> >>>> s/synth/readdir/split_128 PASS 27 qtest-arm/qos-test
> >>>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-t
> >>>> e
> >>>> st
> >>>> s/local/config
> >>> 
> >>> Ok so the next test is supposed to be:
> >>> 
> >>> /arm/virt/virtio-mmio/virtio-bus/virtio-9p-device/virtio-9p/virtio-9p-te
> >>> st
> >>> s/ local/create_dir
> >>> 
> >>> This was added recently. This configures the virtio-9p device in QEMU
> >>> to serve a real test directory from the host. This test directory is
> >>> created under the current directory of the test process. The purpose
> >>> of the test is then to ask the 9p server to create a directory within
> >>> the test directory.
> >>> 
> >>>> Received response 7 (RLERROR) instead of 73 (RMKDIR)
> >>>> ERROR qtest-arm/qos-test - Bail out!
> >>>> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> >>>> failed (hdr.id == id): (7 == 73)
> >>>> Rlerror has errno 95 (Operation not supported)
> >>> 
> >>> So this basically means that QEMU got ENOTSUP/EOPNOTSUPP when calling
> >>> mkdir() into the test directory... not sure what could cause that. I'd
> >>> need more details on the filesystem setup for the build.
> >>> 
> >>> Anyway, we already experienced some breakage in upstream CI because of
> >>> the same family of tests that do real access to the host filesystem.
> >>> Since they're being introduced in QEMU 5.2, I'll try to see if I can
> >>> disable them to be run by default for RC3.
> >>> 
> >>> Cheers,
> >>> 
> >>> --
> >>> Greg
> >>> 
> >>>> **
> >>>> ERROR:../tests/qtest/virtio-9p-test.c:300:v9fs_req_recv: assertion
> >>>> failed (hdr.id == id): (7 == 73)
> >>>> make: *** [Makefile.mtest:1257: run-test-155] Error 1
> >>>> error: Bad exit status from /var/tmp/rpm-tmp.EG4Dav (%check)
> >>>> 
> >>>> 
> >>>> Thanks,
> >>>> Cole
> >> 
> >> Yeah, looks like the mkdir() call which is supposed to create the 9p test
> >> directory, is failing there for some reason. The question is how to find
> >> that out (effectively) without having access to an affected system.
> >> 
> >> It's now too late for 5.2, but I think for 6.0 it would make sense
> >> introducing a dedicated 9p option loglevel=..., so we can tell people to
> >> enable this to capture the precise source location where an error
> >> ocurred.
> >> That would mean spreading a huge bunch of macros all over the 9p code
> >> base,
> >> but it would definitely help a lot understanding the root cause of
> >> reported
> >> issues in an efficient way.
> >> 
> >> Best regards,
> >> Christian Schoenebeck
> > 
> > Cole, does the affected host system probably not have xattrs enabled on
> > its
> > file system?
> 
> Hmm I'm not sure, I will try to investigate.
> 
> google tells me David Gilbert also hit this too earlier:
> https://www.mail-archive.com/qemu-devel@nongnu.org/msg754556.html
> 
> Maybe he remembers details of his setup, CC'd
> 
> - Cole

No, that was a different issue David had, that's already fixed in git
by SHA-1 136b7af2277. You also see that he got a different error. Many people 
were affected by that issue a month ago.

However the issue you reported did not occur on other systems so far, 
including many CI platforms out there. At least I haven't seen any other 
similar report.

What's the host file system used? ZFS?

Best regards,
Christian Schoenebeck