This is an archive of the discontinued Mercurial Phabricator instance.

Differential D1702

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

Authored by lothiraldan on Dec 15 2017, 5:15 AM.

Details

Reviewers
yuja
Group Reviewers
hg-reviewers
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?

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

lothiraldan created this revision.Dec 15 2017, 5:15 AM
yuja requested changes to this revision.Dec 15 2017, 9:05 AM
yuja added a subscriber: yuja.

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?

tests/test-logtoprocess.t
50

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

This revision now requires changes to proceed.Dec 15 2017, 9:05 AM
lothiraldan added a comment.Oct 1 2018, 6:20 AM

I've finally reworked this patch and sends it as an independent series here: https://phab.mercurial-scm.org/D4815

The test seems stable locally and on gcc112, with and without chg and with and without parallelization

lothiraldan abandoned this revision.Oct 1 2018, 6:20 AM

Revision Contents
Changeset List

Diff 4470

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
$ cat $TESTTMP/command.log | sort
yujaUnsubmitted
Not Done

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

yuja: IIUC, here `command.log` might not be written yet because the logging process runs…
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
(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 waiting on ltp" || echo "FAIL Pager is waiting on ltp"
FAIL Pager is waiting on ltp