view tests/test-logtoprocess.t @ 36426:23d12524a202

http: drop custom http client logic

Eight and a half years ago, as my starter bug on code.google.com, I
investigated a mysterious "broken pipe" error from seemingly random
clients[0]. That investigation revealed a tragic story: the Python
standard library's httplib was (and remains) barely functional. During
large POSTs, if a server responds early with an error (even a
permission denied error!) the client only notices that the server
closed the connection and everything breaks. Such server behavior is
implicitly legal under RFC 2616 (the latest HTTP RFC as of when I was
last working on this), and my understanding is that later RFCs have
made it explicitly legal to respond early with any status code outside
the 2xx range.

I embarked, probably foolishly, on a journey to write a new http
library with better overall behavior. The http library appears to work
well in most cases, but it can get confused in the presence of
proxies, and it depends on select(2) which limits its utility if a lot
of file descriptors are open. I haven't touched the http library in
almost two years, and in the interim the Python community has
discovered a better way[1] of writing network code. In theory some day
urllib3 will have its own home-grown http library built on h11[2], or
we could do that. Either way, it's time to declare our current
confusingly-named "http2" client logic and move on. I do hope to
revisit this some day: it's still garbage that we can't even respond
with a 401 or 403 without reading the entire POST body from the
client, but the goalposts on writing a new http client library have
moved substantially. We're almost certainly better off just switching
to requests and eventually picking up their http fixes than trying to
live with something that realistically only we'll ever use. Another
approach would be to write an adapter so that Mercurial can use pycurl
if it's installed. Neither of those approaches seem like they should
be investigated prior to a release of Mercurial that works on Python
3: that's where the mindshare is going to be for any improvements to
the state of the http client art.

0: http://web.archive.org/web/20130501031801/http://code.google.com/p/support/issues/detail?id=2716
1: http://sans-io.readthedocs.io/
2: https://github.com/njsmith/h11

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

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