view tests/test-logtoprocess.t @ 36037:8de90e006c78

run-tests: report tests that exception occurred in

We now record the test that an exception occurred in. We put this
information to use by aggregating the count of failures in each
test. For each exception, the exception report now prints the total
number of tests having that exception and the test with the least
number of exceptions exhibiting that failure. The exception list
is now sorted by (total count, tests impacted, count of failures
in least failing test).

This allows us to:

* Assess how widespread a failure is. Some exceptions occur a lot
  in a few tests. Others occur over many tests.
* Easily run a test exhibiting an exception without having to find
  a failure in test output.
* Find and fix low hanging fruit (e.g. exceptions that are the
  only failure in a test).

Here's an example of the new output:

199 (4 tests)   /home/gps/src/hg/hgext/blackbox.py:191: %b requires a bytes-like object, or an object that implements __bytes__, not 'str' (test-devel-warnings.t - 1 total)
142 (19 tests)  /home/gps/src/hg/hgext/mq.py:655: list indices must be integers or slices, not bytes (test-hardlinks.t - 1 total)
140 (20 tests)  /home/gps/src/hg/mercurial/patch.py:296: string argument expected, got 'bytes' (test-audit-subrepo.t - 1 total)
101 (15 tests)  /home/gps/src/hg/hgext/convert/convcmd.py:60: encode() argument 1 must be str, not bytes (test-convert-clonebranches.t - 1 total)
90 (2 tests)    /home/gps/src/hg/hgext/mq.py:456: can't concat str to bytes (test-mq-qqueue.t - 1 total)
87 (2 tests)    /home/gps/src/hg/mercurial/branchmap.py:380: %b requires a bytes-like object, or an object that implements __bytes__, not 'FileNotFoundError' (test-branches.t - 2 total)
85 (22 tests)   /home/gps/src/hg/mercurial/sshpeer.py:223: cannot convert 'UUID' object to bytes (test-bundle2-pushback.t - 1 total)
1 (1 tests)     /home/gps/src/hg/mercurial/formatter.py:254: %b requires a bytes-like object, or an object that implements __bytes__, not 'str' (test-debugextensions.t - 2 total)
1 (1 tests)     /home/gps/src/hg/hgext/convert/convcmd.py:420: startswith first arg must be str or a tuple of str, not bytes (test-convert-authormap.t - 2 total)
1 (1 tests)     /home/gps/src/hg/mercurial/revlog.py:797: '>=' not supported between instances of 'NoneType' and 'int' (test-unionrepo.t - 1 total)
1 (1 tests)     /home/gps/src/hg/hgext/show.py:129: %b requires a bytes-like object, or an object that implements __bytes__, not 'str' (test-show.t - 1 total)

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

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