tests/test-logtoprocess.t

wrapfunction: use functools.partial if possible

Every `extensions.bind` call inserts a frame in traceback:

   ... in closure
     return func(*(args + a), **kw)

which makes traceback noisy.

The Python stdlib has a `functools.partial` which is backed by C code and
does not pollute traceback. However it does not support instancemethod and
sets `args` attribute which could be problematic for alias handling.

This patch makes `wrapfunction` use `functools.partial` if we are wrapping a
function directly exported by a module (so it's impossible to be a class or
instance method), and special handles `wrapfunction` results so alias
handling code could handle `args` just fine.

As an example, `hg rebase -s . -d . --traceback` got 6 lines removed in my
setup:

   File "hg/mercurial/dispatch.py", line 898, in _dispatch
     cmdpats, cmdoptions)
  -File "hg/mercurial/extensions.py", line 333, in closure
  -  return func(*(args + a), **kw)
   File "hg/hgext/journal.py", line 84, in runcommand
     return orig(lui, repo, cmd, fullargs, *args)
  -File "hg/mercurial/extensions.py", line 333, in closure
  -  return func(*(args + a), **kw)
   File "fb-hgext/hgext3rd/fbamend/hiddenoverride.py", line 119, in runcommand
     result = orig(lui, repo, cmd, fullargs, *args)
   File "hg/mercurial/dispatch.py", line 660, in runcommand
     ret = _runcommand(ui, options, cmd, d)
  -File "hg/mercurial/extensions.py", line 333, in closure
  -  return func(*(args + a), **kw)
   File "hg/hgext/pager.py", line 69, in pagecmd
     return orig(ui, options, cmd, cmdfunc)
   ....

Differential Revision: https://phab.mercurial-scm.org/D632

#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 __future__ import absolute_import
  > from mercurial import registrar
  > 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)