[Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Wei Yang]

Current qemu fails tests/test-util-filemonitor.

By bisect, it shows this commit introduced the error. 

commit ff3dc8fefe953fd3650279e064bf63b212c5699a
Author: Daniel P. Berrang茅 <berrange@redhat.com>
Date:   Wed Mar 13 17:36:18 2019 +0000

    filemon: ensure watch IDs are unique to QFileMonitor scope
    
    The watch IDs are mistakenly only unique within the scope of the
    directory being monitored. This is not useful for clients which are
    monitoring multiple directories. They require watch IDs to be unique
    globally within the QFileMonitor scope.

After revert 

"filemon: ensure watch IDs are unique to QFileMonitor scope"
"filemon: fix watch IDs to avoid potential wraparound issues"

The test pass.

-- 
Wei Yang
Help you, Help me

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Daniel P. Berrangé]

On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
> Current qemu fails tests/test-util-filemonitor.

You'll need to provide more info. The test works for me and passes in all
the QEMU CI environments.


Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Wei Yang]

On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé wrote:
>On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
>> Current qemu fails tests/test-util-filemonitor.
>
>You'll need to provide more info. The test works for me and passes in all
>the QEMU CI environments.
>

The error message from my side is:

/util/filemonitor: Expected watch id 200000000 but got 100000000
**
ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)

What else you'd prefer to have?

>
>Regards,
>Daniel
>-- 
>|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
>|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
>|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

-- 
Wei Yang
Help you, Help me

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Daniel P. Berrangé]

On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:
> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé wrote:
> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
> >> Current qemu fails tests/test-util-filemonitor.
> >
> >You'll need to provide more info. The test works for me and passes in all
> >the QEMU CI environments.
> >
> 
> The error message from my side is:
> 
> /util/filemonitor: Expected watch id 200000000 but got 100000000
> **
> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
> 
> What else you'd prefer to have?

Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
the test - it will print out lots more info

Also what operating system are you using, and what kernel version

Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Wei Yang]

On Thu, Aug 08, 2019 at 10:22:13AM +0100, Daniel P. Berrangé wrote:
>On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:
>> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé wrote:
>> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
>> >> Current qemu fails tests/test-util-filemonitor.
>> >
>> >You'll need to provide more info. The test works for me and passes in all
>> >the QEMU CI environments.
>> >
>> 
>> The error message from my side is:
>> 
>> /util/filemonitor: Expected watch id 200000000 but got 100000000
>> **
>> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
>> 
>> What else you'd prefer to have?
>
>Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
>the test - it will print out lots more info
>

Here is the output with more info.

    $ FILEMONITOR_DEBUG=1 QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 tests/test-util-filemonitor
    /util/filemonitor: Add watch /tmp/test-util-filemonitor-151B6Z (null)
    Watch ID 100000000
    Add watch /tmp/test-util-filemonitor-151B6Z one.txt
    Watch ID 100000001
    Add watch /tmp/test-util-filemonitor-151B6Z two.txt
    Watch ID 100000002
    Create /tmp/test-util-filemonitor-151B6Z/one.txt
    Event id=100000000 event=0 file=one.txt
    Event id=100000001 event=0 file=one.txt
    Create /tmp/test-util-filemonitor-151B6Z/two.txt
    Event id=100000000 event=0 file=two.txt
    Event id=100000002 event=0 file=two.txt
    Create /tmp/test-util-filemonitor-151B6Z/three.txt
    Event id=100000000 event=0 file=three.txt
    Unlink /tmp/test-util-filemonitor-151B6Z/three.txt
    Event id=100000000 event=2 file=three.txt
    Rename /tmp/test-util-filemonitor-151B6Z/one.txt -> /tmp/test-util-filemonitor-151B6Z/two.txt
    Event id=100000000 event=2 file=one.txt
    Event id=100000001 event=2 file=one.txt
    Event id=100000000 event=0 file=two.txt
    Event id=100000002 event=0 file=two.txt
    Append /tmp/test-util-filemonitor-151B6Z/two.txt
    Event id=100000000 event=1 file=two.txt
    Event id=100000002 event=1 file=two.txt
    Touch /tmp/test-util-filemonitor-151B6Z/two.txt
    Event id=100000000 event=3 file=two.txt
    Event id=100000002 event=3 file=two.txt
    Del watch /tmp/test-util-filemonitor-151B6Z 100000001
    Add watch /tmp/test-util-filemonitor-151B6Z one.txt
    Watch ID 100000003
    Create /tmp/test-util-filemonitor-151B6Z/one.txt
    Event id=100000000 event=0 file=one.txt
    Event id=100000003 event=0 file=one.txt
    Del watch /tmp/test-util-filemonitor-151B6Z 100000003
    Unlink /tmp/test-util-filemonitor-151B6Z/one.txt
    Event id=100000000 event=2 file=one.txt
    Mkdir /tmp/test-util-filemonitor-151B6Z/fish
    Event id=100000000 event=0 file=fish
    Add watch /tmp/test-util-filemonitor-151B6Z fish/
    Watch ID 200000000
    Add watch /tmp/test-util-filemonitor-151B6Z fish/one.txt
    Watch ID 200000001
    Create /tmp/test-util-filemonitor-151B6Z/fish/one.txt
    Event id=200000000 event=0 file=one.txt
    Event id=200000001 event=0 file=one.txt
    Del watch /tmp/test-util-filemonitor-151B6Z 200000001
    Rename /tmp/test-util-filemonitor-151B6Z/fish/one.txt -> /tmp/test-util-filemonitor-151B6Z/two.txt
    Event id=200000000 event=2 file=one.txt
    Event id=100000000 event=0 file=two.txt
    Event id=100000002 event=0 file=two.txt
    Rmdir /tmp/test-util-filemonitor-151B6Z/fish
    Event id=200000000 event=4 file=
    Expected watch id 200000000 but got 100000000
    **
    ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
    Aborted (core dumped)


>Also what operating system are you using, and what kernel version
>

OS: Ubuntu 18.04.2 LTS
Kernel: I built the kernel whose last commit is bed38c3e2dca.

>Regards,
>Daniel
>-- 
>|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
>|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
>|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

-- 
Wei Yang
Help you, Help me

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Daniel P. Berrangé]

On Fri, Aug 09, 2019 at 08:06:09AM +0800, Wei Yang wrote:
> On Thu, Aug 08, 2019 at 10:22:13AM +0100, Daniel P. Berrangé wrote:
> >On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:
> >> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé wrote:
> >> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
> >> >> Current qemu fails tests/test-util-filemonitor.
> >> >
> >> >You'll need to provide more info. The test works for me and passes in all
> >> >the QEMU CI environments.
> >> >
> >> 
> >> The error message from my side is:
> >> 
> >> /util/filemonitor: Expected watch id 200000000 but got 100000000
> >> **
> >> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
> >> 
> >> What else you'd prefer to have?
> >
> >Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
> >the test - it will print out lots more info
> >
> 
> Here is the output with more info.
> 
>     $ FILEMONITOR_DEBUG=1 QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 tests/test-util-filemonitor

>     Rmdir /tmp/test-util-filemonitor-151B6Z/fish
>     Event id=200000000 event=4 file=
>     Expected watch id 200000000 but got 100000000
>     **

Ok, so the kernel is sending the events in an unexpected order

>     ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
>     Aborted (core dumped)
> 
> 
> >Also what operating system are you using, and what kernel version
> >
> 
> OS: Ubuntu 18.04.2 LTS
> Kernel: I built the kernel whose last commit is bed38c3e2dca.

Does it work if you use the normal LTS kernel package instead.


Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Wei Yang]

On Fri, Aug 09, 2019 at 10:12:14AM +0100, Daniel P. Berrangé wrote:
>On Fri, Aug 09, 2019 at 08:06:09AM +0800, Wei Yang wrote:
>> On Thu, Aug 08, 2019 at 10:22:13AM +0100, Daniel P. Berrangé wrote:
>> >On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:
>> >> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé wrote:
>> >> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:
>> >> >> Current qemu fails tests/test-util-filemonitor.
>> >> >
>> >> >You'll need to provide more info. The test works for me and passes in all
>> >> >the QEMU CI environments.
>> >> >
>> >> 
>> >> The error message from my side is:
>> >> 
>> >> /util/filemonitor: Expected watch id 200000000 but got 100000000
>> >> **
>> >> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
>> >> 
>> >> What else you'd prefer to have?
>> >
>> >Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
>> >the test - it will print out lots more info
>> >
>> 
>> Here is the output with more info.
>> 
>>     $ FILEMONITOR_DEBUG=1 QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 tests/test-util-filemonitor
>
>>     Rmdir /tmp/test-util-filemonitor-151B6Z/fish
>>     Event id=200000000 event=4 file=
>>     Expected watch id 200000000 but got 100000000
>>     **
>
>Ok, so the kernel is sending the events in an unexpected order
>
>>     ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events: assertion failed: (err == 0)
>>     Aborted (core dumped)
>> 
>> 
>> >Also what operating system are you using, and what kernel version
>> >
>> 
>> OS: Ubuntu 18.04.2 LTS
>> Kernel: I built the kernel whose last commit is bed38c3e2dca.
>
>Does it work if you use the normal LTS kernel package instead.
>

It looks good on LTS kernel.

$ uname -a
Linux richard 4.15.0-55-generic #60-Ubuntu SMP Tue Jul 2 18:22:20 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

$ QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 tests/test-util-filemonitor
/util/filemonitor: OK


>
>Regards,
>Daniel
>-- 
>|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
>|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
>|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

-- 
Wei Yang
Help you, Help me

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Miguel Arruga Vivas]

Hi Daniel,

I've been trying to open a bug in launchpad about exactly this, but it
always raises an error when trying to log in.  Then I found this
thread diving into the archives, so I'll try to kindly ask here about
it.

Daniel P. Berrangé <berrange@redhat.com> wrote:
> On Fri, Aug 09, 2019 at 08:06:09AM +0800, Wei Yang wrote:
> > On Thu, Aug 08, 2019 at 10:22:13AM +0100, Daniel P. Berrangé
> > wrote:  
> > >On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:  
> > >> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé
> > >> wrote:  
> > >> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:  
> > >> >> Current qemu fails tests/test-util-filemonitor.  
> > >> >
> > >> >You'll need to provide more info. The test works for me and
> > >> >passes in all the QEMU CI environments.
> > >> >  
> > >> 
> > >> The error message from my side is:
> > >> 
> > >> /util/filemonitor: Expected watch id 200000000 but got 100000000
> > >> **
> > >> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events:
> > >> assertion failed: (err == 0)
> > >> 
> > >> What else you'd prefer to have?  
> > >
> > >Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
> > >the test - it will print out lots more info
> > >  
> > 
> > Here is the output with more info.
> > 
> >     $ FILEMONITOR_DEBUG=1
> > QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64
> > tests/test-util-filemonitor  
> 
> >     Rmdir /tmp/test-util-filemonitor-151B6Z/fish
> >     Event id=200000000 event=4 file=
> >     Expected watch id 200000000 but got 100000000
> >     **  
> 
> Ok, so the kernel is sending the events in an unexpected order

I've been reading about the issue and as far as I understand the inotify
man-page[http://man7.org/linux/man-pages/man7/inotify.7.html], section
"Dealing with rename() events", points out that the order nor the
atomicity of the concurrent events is something that should be relied
on.
 
> >     ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events:
> > assertion failed: (err == 0) Aborted (core dumped)
> > 
> >   
> > >Also what operating system are you using, and what kernel version

We have hit this error on GNU Guix master
[http://issues.guix.gnu.org/issue/37860]. I'm using linux-libre 5.3.4
on x86_64.  It does not seem to be something deterministic, but I just
commented out the test the fifth time I've hit the same error.

Is there any way to change the test to not rely on the ordering of the
events from different views of the same fs action?

Best regards,
Miguel

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Daniel P. Berrangé]

On Mon, Nov 04, 2019 at 08:35:23PM +0100, Miguel Arruga Vivas wrote:
> Hi Daniel,
> 
> I've been trying to open a bug in launchpad about exactly this, but it
> always raises an error when trying to log in.  Then I found this
> thread diving into the archives, so I'll try to kindly ask here about
> it.
> 
> Daniel P. Berrangé <berrange@redhat.com> wrote:
> > On Fri, Aug 09, 2019 at 08:06:09AM +0800, Wei Yang wrote:
> > > On Thu, Aug 08, 2019 at 10:22:13AM +0100, Daniel P. Berrangé
> > > wrote:  
> > > >On Thu, Aug 08, 2019 at 04:46:53PM +0800, Wei Yang wrote:  
> > > >> On Thu, Aug 08, 2019 at 09:02:29AM +0100, Daniel P. Berrangé
> > > >> wrote:  
> > > >> >On Thu, Aug 08, 2019 at 10:07:23AM +0800, Wei Yang wrote:  
> > > >> >> Current qemu fails tests/test-util-filemonitor.  
> > > >> >
> > > >> >You'll need to provide more info. The test works for me and
> > > >> >passes in all the QEMU CI environments.
> > > >> >  
> > > >> 
> > > >> The error message from my side is:
> > > >> 
> > > >> /util/filemonitor: Expected watch id 200000000 but got 100000000
> > > >> **
> > > >> ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events:
> > > >> assertion failed: (err == 0)
> > > >> 
> > > >> What else you'd prefer to have?  
> > > >
> > > >Can you set the  "FILEMONITOR_DEBUG=1" env variable before running
> > > >the test - it will print out lots more info
> > > >  
> > > 
> > > Here is the output with more info.
> > > 
> > >     $ FILEMONITOR_DEBUG=1
> > > QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64
> > > tests/test-util-filemonitor  
> > 
> > >     Rmdir /tmp/test-util-filemonitor-151B6Z/fish
> > >     Event id=200000000 event=4 file=
> > >     Expected watch id 200000000 but got 100000000
> > >     **  
> > 
> > Ok, so the kernel is sending the events in an unexpected order
> 
> I've been reading about the issue and as far as I understand the inotify
> man-page[http://man7.org/linux/man-pages/man7/inotify.7.html], section
> "Dealing with rename() events", points out that the order nor the
> atomicity of the concurrent events is something that should be relied
> on.
>  
> > >     ERROR:tests/test-util-filemonitor.c:665:test_file_monitor_events:
> > > assertion failed: (err == 0) Aborted (core dumped)
> > > 
> > >   
> > > >Also what operating system are you using, and what kernel version
> 
> We have hit this error on GNU Guix master
> [http://issues.guix.gnu.org/issue/37860]. I'm using linux-libre 5.3.4
> on x86_64.  It does not seem to be something deterministic, but I just
> commented out the test the fifth time I've hit the same error.
> 
> Is there any way to change the test to not rely on the ordering of the
> events from different views of the same fs action?

This reported bug was already fixed in git master with

  commit bf9e0313c27d8e6ecd7f7de3d63e1cb25d8f6311
  Author: Daniel P. Berrangé <berrange@redhat.com>
  Date:   Wed Aug 21 16:14:27 2019 +0100

    tests: make filemonitor test more robust to event ordering
    

Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [Qemu-devel] [Fail] tests/test-util-filemonitor fails

[Miguel Arruga Vivas]

Hello Daniel,

Daniel P. Berrangé <berrange@redhat.com> wrote:
> This reported bug was already fixed in git master with
> 
>   commit bf9e0313c27d8e6ecd7f7de3d63e1cb25d8f6311
>   Author: Daniel P. Berrangé <berrange@redhat.com>
>   Date:   Wed Aug 21 16:14:27 2019 +0100
> 
>     tests: make filemonitor test more robust to event ordering

Thank you very much for your patch and your quick answer.

Best regards,
Miguel