view tests/test-logtoprocess.t @ 37295:45b39c69fae0

wireproto: separate commands tables for version 1 and 2 commands

We can't easily reuse existing command handlers for version 2
commands because the response types will be different. e.g. many
commands return nodes encoded as hex. Our new wire protocol is
binary safe, so we'll wish to encode nodes as binary.

We /could/ teach each command handler to look at the protocol
handler and change behavior based on the version in use. However,
this would make logic a bit unwieldy over time and would make
it harder to design a unified protocol handler interface. I think
it's better to create a clean break between version 1 and version 2
of commands on the server.

What I imagine happening is we will have separate @wireprotocommand
functions for each protocol generation. Those functions will parse the
request, dispatch to a common function to process it, then generate
the response in its own, transport-specific manner.

This commit establishes a separate table for tracking version 1
commands from version 2 commands. The HTTP server pieces have been
updated to use this new table.

Most commands are marked as both version 1 and version 2, so there is
little practical impact to this change.

A side-effect of this change is we now rely on transport registration
in wireprototypes.TRANSPORTS and certain properties of the protocol
interface. So a test had to be updated to conform.

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

#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)
  > configtable = {}
  > configitem = registrar.configitem(configtable)
  > configitem('logtoprocess', 'foo',
  >     default=None,
  > )
  > @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
  
  
  
   (chg !)
  0
  a message: spam
  command
  command (chg !)
  commandfinish
  foo
  foo
  foo
  foo
  foo exited 0 after * seconds (glob)
  logtoprocess command output:
  logtoprocess command output: (chg !)
  logtoprocess commandfinish output:
  logtoprocess foo output:
  serve --cmdserver chgunix * (glob) (chg !)
  serve --cmdserver chgunix * (glob) (chg !)
  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)