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

# 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:

```

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.

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`.

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
>