tests/test-logtoprocess.t

match: express anypats(), not prefix(), in terms of the others

When I added prefix() in 9789b4a7c595 (match: introduce boolean
prefix() method, 2014-10-28), we already had always(), isexact(), and
anypats(), so it made sense to write it in terms of them (a prefix
matcher is one that isn't any of the other types). It's only now that
I realize that it's much more natural to define prefix() explicitly
(it's one that uses path: patterns, roughly speaking) and let
anypats() be defined in terms of the others. Remember that these
methods are all used for determining which fast paths are
possible. anypats() simply means that no fast paths are possible (it
could be called complex() instead). Further evidence is that
rootfilesin:some/dir does not have any patterns, but it's still
considered to be an anypats() matcher. That's because anypats() really
just means that it's not a prefix() matcher (and not always() and not
isexact()).

This patch thus changes prefix() to return False by default and
anypats() to return True only if the other three are False. Having
anypats() be True by default also seems like a good thing, because it
means forgetting to override it will lead only to performance bugs,
not correctness bugs.

Since the base class's implementation changes, we're also forced to
update the subclasses. That change exposed and fixed a bug in the
differencematcher: for example when both its two input matchers were
prefix matchers, we would say that the result was also a prefix
matcher, which is incorrect, because e.g "path:dir - path:dir/foo" no
longer matches everything under "dir" (which is what prefix() means).

#require no-windows

ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat"
to hg commands, to wait for the output, if you want to test its output.
Otherwise the test will be flaky.

Test if logtoprocess correctly captures command-related log calls.

  $ hg init
  $ cat > $TESTTMP/foocommand.py << EOF
  > from mercurial import registrar
  > from time import sleep
  > cmdtable = {}
  > command = registrar.command(cmdtable)
  > @command(b'foo', [])
  > def foo(ui, repo):
  >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
  > EOF
  $ cp $HGRCPATH $HGRCPATH.bak
  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > foocommand=$TESTTMP/foocommand.py
  > [logtoprocess]
  > command=echo 'logtoprocess command output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2"
  > commandfinish=echo 'logtoprocess commandfinish output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2";
  >     echo "\$MSG3"
  > foo=echo 'logtoprocess foo output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$OPT_BAR"
  > 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
  
  
  
  0
  a message: spam
  command
  commandfinish
  foo
  foo
  foo
  foo
  foo exited 0 after * seconds (glob)
  logtoprocess command output:
  logtoprocess commandfinish output:
  logtoprocess foo output:
  spam

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"
  > [ui]
  > logblockedtimes=True
  > EOF

  $ hg log | cat
  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)