This is an archive of the discontinued Mercurial Phabricator instance.

Differential D1427

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

Authored by lothiraldan on Nov 15 2017, 10:44 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.Nov 15 2017, 10:44 AM
durin42 added a subscriber: quark.Nov 17 2017, 5:25 PM
durin42 added a subscriber: durin42.

Jun, any idea why this might be chg-broken?

lothiraldan added a comment.Nov 28 2017, 3:28 PM

Could someone with chg experience give me a hand or a pointer why this test might be flaky with chg?

lothiraldan updated this revision to Diff 3916.Nov 28 2017, 3:36 PM
yuja requested changes to this revision.Nov 29 2017, 8:02 AM
yuja added a subscriber: yuja.
yuja added inline comments.
tests/test-logtoprocess.t
33

This file may be overwritten asynchronously by more than one
logging processes. That's probably why the test result is unstable
especially with chg.

This revision now requires changes to proceed.Nov 29 2017, 8:02 AM
lothiraldan added inline comments.Dec 15 2017, 6:01 AM
tests/test-logtoprocess.t
33

I tried making the file path unique for each call (by adding \$(date +%s)) but it doesn't seems to change anything in the stability unfortunately :(

yuja added inline comments.Dec 15 2017, 7:51 AM
tests/test-logtoprocess.t
33

Can't we just append to the log file and sort the content?

Revision Contents
Changeset List

Diff 3916

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
yujaUnsubmitted
Not Done

This file may be overwritten asynchronously by more than one
logging processes. That's probably why the test result is unstable
especially with chg.

yuja: This file may be overwritten asynchronously by more than one logging processes. That's probably…
lothiraldanAuthorUnsubmitted
Not Done

I tried making the file path unique for each call (by adding \$(date +%s)) but it doesn't seems to change anything in the stability unfortunately :(

lothiraldan: I tried making the file path unique for each call (by adding `\$(date +%s)`) but it doesn't…
yujaUnsubmitted
Not Done

Can't we just append to the log file and sort the content?

yuja: Can't we just append to the log file and sort the content?
> 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
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