annotate tests/test-logtoprocess.t @ 37048:fc5e261915b9

wireproto: require POST for all HTTPv2 requests

Wire protocol version 1 transfers argument data via request
headers by default. This has historically caused problems because
servers institute limits on the length of individual HTTP headers
as well as the total size of all request headers. Mercurial servers
can advertise the maximum length of an individual header. But
there's no guarantee any intermediate HTTP agents will accept
headers up to that length.

In the existing wire protocol, server operators typically also
key off the HTTP request method to implement authentication.
For example, GET requests translate to read-only requests and
can be allowed. But read-write commands must use POST and require
authentication. This has typically worked because the only wire
protocol commands that use POST modify the repo (e.g. the
"unbundle" command).

There is an experimental feature to enable clients to transmit
argument data via POST request bodies. This is technically a
better and more robust solution. But we can't enable it by default
because of servers assuming POST means write access.

In version 2 of the wire protocol, the permissions of a request
are encoded in the URL. And with it being a new protocol in a new
URL space, we're not constrained by backwards compatibility
requirements.

This commit adopts the technically superior mechanism of using
HTTP request bodies to send argument data by requiring POST for
all commands. Strictly speaking, it may be possible to send
request bodies on GET requests. But my experience is that not all
HTTP stacks support this. POST pretty much always works. Using POST
for read-only operations does sacrifice some RESTful design
purity. But this API cares about practicality, not about being
in Roy T. Fielding's REST ivory tower.

There's a chance we may relax this restriction in the future. But
for now, I want to see how far we can get with a POST only API.

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

#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)