Patchwork [RFC] tests: sleep for a second to let ui get flushed

login
register
mail settings
Submitter Pulkit Goyal
Date July 23, 2020, 9:01 p.m.
Message ID <ebb1da08c3163efac7bc.1595538074@workspace>
Download mbox | patch
Permalink /patch/46854/
State New
Headers show

Comments

Pulkit Goyal - July 23, 2020, 9:01 p.m.
# HG changeset patch
# User Pulkit Goyal <7895pulkit@gmail.com>
# Date 1595538045 -19800
#      Fri Jul 24 02:30:45 2020 +0530
# Node ID ebb1da08c3163efac7bcfe0947c98b1ac01fc603
# Parent  aada79ccce4c3e424e48cc76598e0849be43de56
# EXP-Topic chg-test
[RFC] tests: sleep for a second to let ui get flushed

I was getting following failure on Python 3+chg:

```
Yuya Nishihara - July 24, 2020, 3:37 a.m.
On Fri, 24 Jul 2020 02:31:14 +0530, Pulkit Goyal wrote:
> # HG changeset patch
> # User Pulkit Goyal <7895pulkit@gmail.com>
> # Date 1595538045 -19800
> #      Fri Jul 24 02:30:45 2020 +0530
> # Node ID ebb1da08c3163efac7bcfe0947c98b1ac01fc603
> # Parent  aada79ccce4c3e424e48cc76598e0849be43de56
> # EXP-Topic chg-test
> [RFC] tests: sleep for a second to let ui get flushed

> I added a sleep and debugged some more, it turns out that the command running is
> finished even before the ui was completely flushed.
> 
> I have marked this as an RFC as I think adding code to wait for ui to flush
> before chg exiting will be better.
> However, will be nice to have a chg experienced person to look.
> 
> diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
> --- a/tests/test-blackbox.t
> +++ b/tests/test-blackbox.t
> @@ -354,8 +354,12 @@ Test missing log directory, which should
>    > EOF
>    $ hg log --debug
>    removing $TESTTMP/gone/.hg
> -  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
>    warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
> +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
> +
> +  $ sleep 1
> +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)

I can't reproduce the issue, but maybe the server process would try to
log something and detect that the log directory was gone. Inserting explicit
ui.log() after vfs.rmtree() might help.
Pulkit Goyal - July 24, 2020, 8:14 a.m.
On Fri, Jul 24, 2020 at 9:08 AM Yuya Nishihara <yuya@tcha.org> wrote:
>
> On Fri, 24 Jul 2020 02:31:14 +0530, Pulkit Goyal wrote:
> > # HG changeset patch
> > # User Pulkit Goyal <7895pulkit@gmail.com>
> > # Date 1595538045 -19800
> > #      Fri Jul 24 02:30:45 2020 +0530
> > # Node ID ebb1da08c3163efac7bcfe0947c98b1ac01fc603
> > # Parent  aada79ccce4c3e424e48cc76598e0849be43de56
> > # EXP-Topic chg-test
> > [RFC] tests: sleep for a second to let ui get flushed
>
> > I added a sleep and debugged some more, it turns out that the command running is
> > finished even before the ui was completely flushed.
> >
> > I have marked this as an RFC as I think adding code to wait for ui to flush
> > before chg exiting will be better.
> > However, will be nice to have a chg experienced person to look.
> >
> > diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
> > --- a/tests/test-blackbox.t
> > +++ b/tests/test-blackbox.t
> > @@ -354,8 +354,12 @@ Test missing log directory, which should
> >    > EOF
> >    $ hg log --debug
> >    removing $TESTTMP/gone/.hg
> > -  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
> >    warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
> > +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
> > +
> > +  $ sleep 1
> > +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
>
> I can't reproduce the issue, but maybe the server process would try to
> log something and detect that the log directory was gone. Inserting explicit
> ui.log() after vfs.rmtree() might help.

I was also unable to reproduce until I ran many of them together with
`--runs-per-test 20`.
Pierre-Yves David - July 24, 2020, 10:10 a.m.
Solving race condition with sleep usually just make test slower while 
pushing the race further down the road. Can you think of a way to fix 
this with some explicit synchronisation?

On 7/23/20 11:01 PM, Pulkit Goyal wrote:
> # HG changeset patch
> # User Pulkit Goyal <7895pulkit@gmail.com>
> # Date 1595538045 -19800
> #      Fri Jul 24 02:30:45 2020 +0530
> # Node ID ebb1da08c3163efac7bcfe0947c98b1ac01fc603
> # Parent  aada79ccce4c3e424e48cc76598e0849be43de56
> # EXP-Topic chg-test
> [RFC] tests: sleep for a second to let ui get flushed
> 
> I was getting following failure on Python 3+chg:
> 
> ```
> --- /tmp/mercurial-ci/tests/test-blackbox.t
> +++ /tmp/mercurial-ci/tests/test-blackbox.t.err
> @@ -354,13 +354,13 @@
>     > EOF
>     $ hg log --debug
>     removing $TESTTMP/gone/.hg
> -  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
>     warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
>     $ cd ..
> 
>   blackbox should disable itself if track is empty
> 
>     $ hg --config blackbox.track= init nothing_tracked
> +  warning: cannot write to blackbox.log: $ENOENT$
>     $ cd nothing_tracked
>     $ cat >> .hg/hgrc << EOF
>     > [blackbox]
> ERROR: test-blackbox.t output changed
> ```
> 
> I added a sleep and debugged some more, it turns out that the command running is
> finished even before the ui was completely flushed.
> 
> I have marked this as an RFC as I think adding code to wait for ui to flush
> before chg exiting will be better.
> However, will be nice to have a chg experienced person to look.
> 
> diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
> --- a/tests/test-blackbox.t
> +++ b/tests/test-blackbox.t
> @@ -354,8 +354,12 @@ Test missing log directory, which should
>     > EOF
>     $ hg log --debug
>     removing $TESTTMP/gone/.hg
> -  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
>     warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
> +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
> +
> +  $ sleep 1
> +  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
> +
>     $ cd ..
>   
>   blackbox should disable itself if track is empty
> 
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
>

Patch

--- /tmp/mercurial-ci/tests/test-blackbox.t
+++ /tmp/mercurial-ci/tests/test-blackbox.t.err
@@ -354,13 +354,13 @@ 
   > EOF
   $ hg log --debug
   removing $TESTTMP/gone/.hg
-  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
   warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
   $ cd ..

 blackbox should disable itself if track is empty

   $ hg --config blackbox.track= init nothing_tracked
+  warning: cannot write to blackbox.log: $ENOENT$
   $ cd nothing_tracked
   $ cat >> .hg/hgrc << EOF
   > [blackbox]
ERROR: test-blackbox.t output changed
```

I added a sleep and debugged some more, it turns out that the command running is
finished even before the ui was completely flushed.

I have marked this as an RFC as I think adding code to wait for ui to flush
before chg exiting will be better.
However, will be nice to have a chg experienced person to look.

diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -354,8 +354,12 @@  Test missing log directory, which should
   > EOF
   $ hg log --debug
   removing $TESTTMP/gone/.hg
-  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !)
   warning: cannot write to blackbox.log: $TESTTMP/gone/.hg/blackbox.log: $ENOTDIR$ (windows !)
+  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
+
+  $ sleep 1
+  warning: cannot write to blackbox.log: $ENOENT$ (no-windows !) (?)
+
   $ cd ..
 
 blackbox should disable itself if track is empty