Patchwork D1702: logtoprocess: add a test to show pager and ltp bad interaction

login
register
mail settings
Submitter phabricator
Date Dec. 15, 2017, 10:15 a.m.
Message ID <differential-rev-PHID-DREV-2vy67vqtxh5qrurxqqm3-req@phab.mercurial-scm.org>
Download mbox | patch
Permalink /patch/26300/
State New
Headers show

Comments

phabricator - Dec. 15, 2017, 10:15 a.m.
lothiraldan created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  The next changeset will fix the bad interaction between the pager and log-to-
  process. Add a test first to make the next changeset easier to understand.
  
  XXX-REVIEW: I tried making the test file compatible with chg but it seems
  flaky. The output is different when running only this test without parallelism
  (rt test-logtoprocess.t) vs running all tests with parallelism (rt -j 4).
  Could someone with more chg experience gives me a hand stabilizing this
  test file?

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1702

AFFECTED FILES
  tests/test-logtoprocess.t

CHANGE DETAILS




To: lothiraldan, #hg-reviewers
Cc: mercurial-devel
phabricator - Dec. 15, 2017, 2:05 p.m.
yuja requested changes to this revision.
yuja added a comment.
This revision now requires changes to proceed.


  > XXX-REVIEW: I tried making the test file compatible with chg but it seems
  >  flaky. The output is different when running only this test without parallelism
  >  (rt test-logtoprocess.t) vs running all tests with parallelism (rt -j 4).
  
  Can you at least disable the broken tests on chg?

INLINE COMMENTS

> test-logtoprocess.t:50
> +  $ hg foo
> +  $ cat $TESTTMP/command.log | sort
>    

IIUC, here `command.log` might not be written yet because the
logging process runs asynchronously.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1702

To: lothiraldan, #hg-reviewers, yuja
Cc: yuja, mercurial-devel

Patch

diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -27,59 +27,99 @@ 
   > logtoprocess=
   > foocommand=$TESTTMP/foocommand.py
   > [logtoprocess]
-  > command=echo 'logtoprocess command output:';
+  > command=(echo 'logtoprocess command output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
-  >     echo "\$MSG2"
-  > commandfinish=echo 'logtoprocess commandfinish output:';
+  >     echo "\$MSG2") > $TESTTMP/command.log
+  > commandfinish=(echo 'logtoprocess commandfinish output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
   >     echo "\$MSG2";
-  >     echo "\$MSG3"
-  > foo=echo 'logtoprocess foo output:';
+  >     echo "\$MSG3") > $TESTTMP/commandfinish.log
+  > foo=(echo 'logtoprocess foo output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
-  >     echo "\$OPT_BAR"
+  >     echo "\$OPT_BAR") > $TESTTMP/foo.log
   > EOF
 
 Running a command triggers both a ui.log('command') and a
 ui.log('commandfinish') call. The foo command also uses ui.log.
 
 Use sort to avoid ordering issues between the various processes we spawn:
-  $ hg foo | cat | sort
-  
-  
+  $ hg foo
+  $ cat $TESTTMP/command.log | sort
   
-   (chg !)
+  command
+  foo (no-chg !)
+  foo (no-chg !)
+  logtoprocess command output:
+  serve --cmdserver chgunix * (glob) (chg !)
+  serve --cmdserver chgunix * (glob) (chg !)
+
+#if no-chg
+  $ cat $TESTTMP/commandfinish.log | sort
+  
   0
-  a message: spam
-  command
-  command (chg !)
   commandfinish
   foo
-  foo
-  foo
+  foo exited 0 after * seconds (glob)
+  logtoprocess commandfinish output:
+  $ cat $TESTTMP/foo.log | sort
+  
+  a message: spam
   foo
-  foo exited 0 after * seconds (glob)
-  logtoprocess command output:
-  logtoprocess command output: (chg !)
-  logtoprocess commandfinish output:
   logtoprocess foo output:
-  serve --cmdserver chgunix * (glob) (chg !)
-  serve --cmdserver chgunix * (glob) (chg !)
   spam
+#endif
 
 Confirm that logging blocked time catches stdio properly:
   $ cp $HGRCPATH.bak $HGRCPATH
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > logtoprocess=
   > pager=
   > [logtoprocess]
-  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
+  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > $TESTTMP/uiblocked.log
   > [ui]
   > logblockedtimes=True
   > EOF
 
-  $ hg log | cat
+  $ hg log
+  $ sleep 0.2
+  $ cat $TESTTMP/uiblocked.log
   uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
+
+Try to confirm that pager wait on logtoprocess:
+
+Add a script that wait on a file to appears for 5 seconds, if it sees it touch
+another file or die after 5 seconds. If the scripts is awaited by hg, the
+script will die after the timeout before we could touch the file and the
+resulting file will not exists. If not, we will touch the file and see it.
+
+  $ cat > $TESTTMP/wait-output.sh << EOF
+  > #!/bin/sh
+  > for i in \`$TESTDIR/seq.py 50\`; do
+  >   if [ -f "$TESTTMP/wait-for-touched" ];
+  >   then
+  >     touch "$TESTTMP/touched";
+  >     break;
+  >   else
+  >     sleep 0.1;
+  >   fi
+  > done
+  > EOF
+  $ chmod +x $TESTTMP/wait-output.sh
+
+  $ cat >> $HGRCPATH << EOF
+  > [extensions]
+  > logtoprocess=
+  > pager=
+  > [logtoprocess]
+  > commandfinish=$TESTTMP/wait-output.sh
+  > EOF
+  $ hg version -q --pager=always
+  Mercurial Distributed SCM (version *) (glob)
+  $ touch $TESTTMP/wait-for-touched
+  $ sleep 0.2
+  $ test -f $TESTTMP/touched && echo "SUCCESS Pager is waiting on ltp" || echo "FAIL Pager is waiting on ltp"
+  FAIL Pager is waiting on ltp