This is an archive of the discontinued Mercurial Phabricator instance.

Differential D4815

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

Authored by lothiraldan on Oct 1 2018, 6:18 AM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
Commits
rHGdfca83594145: logtoprocess: add a test to show pager and ltp bad interaction
rHG5f040397fcb6: logtoprocess: add a test to show pager and ltp bad interaction
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.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

lothiraldan created this revision.Oct 1 2018, 6:18 AM
yuja added a subscriber: yuja.Oct 1 2018, 7:36 AM

Queued these, thanks.

+ $ hg foo
+ $ sleep 0.2
+ $ cat $TESTTMP/command.log | sort

These sleep 0.2 seems a bit scary, but we can fix them later if they
actually make the test freaky.

Closed by commit rHG5f040397fcb6: logtoprocess: add a test to show pager and ltp bad interaction (authored by lothiraldan). · Explain WhyOct 1 2018, 7:42 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mtests/test-logtoprocess.t (85 lines)

Diff 11510

tests/test-logtoprocess.t

> ui.log('foo', 'a message: %(bar)s\n', bar='spam') > ui.log('foo', 'a message: %(bar)s\n', bar='spam')
> EOF > EOF
$ cp $HGRCPATH $HGRCPATH.bak $ cp $HGRCPATH $HGRCPATH.bak
$ cat >> $HGRCPATH << EOF $ cat >> $HGRCPATH << EOF
> [extensions] > [extensions]
> logtoprocess= > logtoprocess=
> foocommand=$TESTTMP/foocommand.py > foocommand=$TESTTMP/foocommand.py
> [logtoprocess] > [logtoprocess]
> command=echo 'logtoprocess command output:'; > command=(echo 'logtoprocess command output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$MSG2" > echo "\$MSG2") > $TESTTMP/command.log
> commandfinish=echo 'logtoprocess commandfinish output:'; > commandfinish=(echo 'logtoprocess commandfinish output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$MSG2"; > echo "\$MSG2";
> echo "\$MSG3" > echo "\$MSG3") > $TESTTMP/commandfinish.log
> foo=echo 'logtoprocess foo output:'; > foo=(echo 'logtoprocess foo output:';
> echo "\$EVENT"; > echo "\$EVENT";
> echo "\$MSG1"; > echo "\$MSG1";
> echo "\$OPT_BAR" > echo "\$OPT_BAR") > $TESTTMP/foo.log
> EOF > EOF
Running a command triggers both a ui.log('command') and a Running a command triggers both a ui.log('command') and a
ui.log('commandfinish') call. The foo command also uses ui.log. ui.log('commandfinish') call. The foo command also uses ui.log.
Use sort to avoid ordering issues between the various processes we spawn: Use sort to avoid ordering issues between the various processes we spawn:
$ hg foo | cat | sort $ hg foo
$ sleep 0.2
$ cat $TESTTMP/command.log | sort
command
foo
foo
logtoprocess command output:
#if no-chg
$ cat $TESTTMP/commandfinish.log | sort
(chg !)
0 0
a message: spam
command
command (chg !)
commandfinish commandfinish
foo foo
foo
foo
foo
foo exited 0 after * seconds (glob) foo exited 0 after * seconds (glob)
logtoprocess command output:
logtoprocess command output: (chg !)
logtoprocess commandfinish output: logtoprocess commandfinish output:
$ cat $TESTTMP/foo.log | sort
a message: spam
foo
logtoprocess foo output: logtoprocess foo output:
serve --cmdserver chgunix * (glob) (chg !)
serve --cmdserver chgunix * (glob) (chg !)
spam spam
#endif
Confirm that logging blocked time catches stdio properly: Confirm that logging blocked time catches stdio properly:
$ cp $HGRCPATH.bak $HGRCPATH $ cp $HGRCPATH.bak $HGRCPATH
$ cat >> $HGRCPATH << EOF $ cat >> $HGRCPATH << EOF
> [extensions] > [extensions]
> logtoprocess= > logtoprocess=
> pager= > pager=
> [logtoprocess] > [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] > [ui]
> logblockedtimes=True > logblockedtimes=True
> EOF > 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) 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 not waiting on ltp" || echo "FAIL Pager is waiting on ltp"
FAIL Pager is waiting on ltp