tests/test-logtoprocess.t
author Boris Feld <boris.feld@octobus.net>
Mon, 22 Oct 2018 15:51:01 +0200
changeset 40402 106adc261492
parent 40401 6bd477ee7294
child 40621 175b590b1f51
permissions -rw-r--r--
logtoprocess: sends the canonical command name to the subprocess One of the use-case of logtoprocess is to monitor command duration. With the current code, we only get whatever command name the user typed (either abbreviated or aliased). This makes analytics on the collected data more difficult. Stores the canonical command name in the request object. Pass the stored canonical name in the `req.ui.log("commandfinish", ...)` call as keyword argument to not break potential string formatting. Pass the value as the environment variable named `LTP_COMMAND` to the called script. Differential Revision: https://phab.mercurial-scm.org/D4820
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
32915
0afc4206d02b test-logtoprocess: don't run on Windows
Matt Harbison <matt_harbison@yahoo.com>
parents: 32337
diff changeset
     1
#require no-windows
0afc4206d02b test-logtoprocess: don't run on Windows
Matt Harbison <matt_harbison@yahoo.com>
parents: 32337
diff changeset
     2
30991
3844b3299a53 test-logtoprocess: use cat to wait for outputs
Jun Wu <quark@fb.com>
parents: 30978
diff changeset
     3
ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat"
3844b3299a53 test-logtoprocess: use cat to wait for outputs
Jun Wu <quark@fb.com>
parents: 30978
diff changeset
     4
to hg commands, to wait for the output, if you want to test its output.
3844b3299a53 test-logtoprocess: use cat to wait for outputs
Jun Wu <quark@fb.com>
parents: 30978
diff changeset
     5
Otherwise the test will be flaky.
3844b3299a53 test-logtoprocess: use cat to wait for outputs
Jun Wu <quark@fb.com>
parents: 30978
diff changeset
     6
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
     7
Test if logtoprocess correctly captures command-related log calls.
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
     8
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
     9
  $ hg init
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    10
  $ cat > $TESTTMP/foocommand.py << EOF
33966
e98dab3fafbc tests: update test-logtoprocess to pass our import checker
Augie Fackler <raf@durin42.com>
parents: 33097
diff changeset
    11
  > from __future__ import absolute_import
32337
46ba2cdda476 registrar: move cmdutil.command to registrar module (API)
Yuya Nishihara <yuya@tcha.org>
parents: 30991
diff changeset
    12
  > from mercurial import registrar
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    13
  > cmdtable = {}
32337
46ba2cdda476 registrar: move cmdutil.command to registrar module (API)
Yuya Nishihara <yuya@tcha.org>
parents: 30991
diff changeset
    14
  > command = registrar.command(cmdtable)
34764
af43cb56af4e configitems: register the test 'logtoprocess.foo' config
Boris Feld <boris.feld@octobus.net>
parents: 34444
diff changeset
    15
  > configtable = {}
af43cb56af4e configitems: register the test 'logtoprocess.foo' config
Boris Feld <boris.feld@octobus.net>
parents: 34444
diff changeset
    16
  > configitem = registrar.configitem(configtable)
af43cb56af4e configitems: register the test 'logtoprocess.foo' config
Boris Feld <boris.feld@octobus.net>
parents: 34444
diff changeset
    17
  > configitem('logtoprocess', 'foo',
af43cb56af4e configitems: register the test 'logtoprocess.foo' config
Boris Feld <boris.feld@octobus.net>
parents: 34444
diff changeset
    18
  >     default=None,
af43cb56af4e configitems: register the test 'logtoprocess.foo' config
Boris Feld <boris.feld@octobus.net>
parents: 34444
diff changeset
    19
  > )
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    20
  > @command(b'foobar', [])
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    21
  > def foo(ui, repo):
40401
6bd477ee7294 logtoprocess: fix message formatting
Boris Feld <boris.feld@octobus.net>
parents: 40377
diff changeset
    22
  >     ui.log('foo', 'a message: %s\n', 'spam')
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    23
  > EOF
30976
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    24
  $ cp $HGRCPATH $HGRCPATH.bak
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    25
  $ cat >> $HGRCPATH << EOF
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    26
  > [extensions]
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    27
  > logtoprocess=
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    28
  > foocommand=$TESTTMP/foocommand.py
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    29
  > [logtoprocess]
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    30
  > command=(echo 'logtoprocess command output:';
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    31
  >     echo "\$EVENT";
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    32
  >     echo "\$MSG1";
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    33
  >     echo "\$MSG2") > $TESTTMP/command.log
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    34
  > commandfinish=(echo 'logtoprocess commandfinish output:';
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    35
  >     echo "\$EVENT";
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    36
  >     echo "\$MSG1";
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    37
  >     echo "\$MSG2";
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    38
  >     echo "\$MSG3";
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    39
  >     echo "canonical: \$OPT_CANONICAL_COMMAND") > $TESTTMP/commandfinish.log
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    40
  > foo=(echo 'logtoprocess foo output:';
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    41
  >     echo "\$EVENT";
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    42
  >     echo "\$MSG1";
40401
6bd477ee7294 logtoprocess: fix message formatting
Boris Feld <boris.feld@octobus.net>
parents: 40377
diff changeset
    43
  >     echo "\$MSG2") > $TESTTMP/foo.log
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    44
  > EOF
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    45
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    46
Running a command triggers both a ui.log('command') and a
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    47
ui.log('commandfinish') call. The foo command also uses ui.log.
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    48
30991
3844b3299a53 test-logtoprocess: use cat to wait for outputs
Jun Wu <quark@fb.com>
parents: 30978
diff changeset
    49
Use sort to avoid ordering issues between the various processes we spawn:
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    50
  $ hg fooba
40377
18da306e92b5 tests: sleep longer in test-logtoprocess.t
Augie Fackler <augie@google.com>
parents: 39926
diff changeset
    51
  $ sleep 1
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    52
  $ cat $TESTTMP/command.log | sort
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    53
  
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    54
  command
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    55
  fooba
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    56
  fooba
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    57
  logtoprocess command output:
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    58
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    59
#if no-chg
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    60
  $ cat $TESTTMP/commandfinish.log | sort
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    61
  
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    62
  0
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    63
  canonical: foobar
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    64
  commandfinish
40402
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    65
  fooba
106adc261492 logtoprocess: sends the canonical command name to the subprocess
Boris Feld <boris.feld@octobus.net>
parents: 40401
diff changeset
    66
  fooba exited 0 after * seconds (glob)
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    67
  logtoprocess commandfinish output:
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    68
  $ cat $TESTTMP/foo.log | sort
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    69
  
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    70
  a message: spam
28901
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    71
  foo
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    72
  logtoprocess foo output:
a368da441b32 logtoprocess: new experimental extension
Martijn Pieters <mjpieters@fb.com>
parents:
diff changeset
    73
  spam
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    74
#endif
30976
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    75
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    76
Confirm that logging blocked time catches stdio properly:
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    77
  $ cp $HGRCPATH.bak $HGRCPATH
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    78
  $ cat >> $HGRCPATH << EOF
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    79
  > [extensions]
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    80
  > logtoprocess=
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    81
  > pager=
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    82
  > [logtoprocess]
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    83
  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > $TESTTMP/uiblocked.log
30976
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    84
  > [ui]
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    85
  > logblockedtimes=True
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    86
  > EOF
e92daf156d5c ui: provide a mechanism to track and log blocked time
Simon Farnsworth <simonfar@fb.com>
parents: 28901
diff changeset
    87
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    88
  $ hg log
40377
18da306e92b5 tests: sleep longer in test-logtoprocess.t
Augie Fackler <augie@google.com>
parents: 39926
diff changeset
    89
  $ sleep 1
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    90
  $ cat $TESTTMP/uiblocked.log
30978
fdecd24ca4dc ui: log time spent blocked on stdio
Simon Farnsworth <simonfar@fb.com>
parents: 30976
diff changeset
    91
  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
39925
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    92
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    93
Try to confirm that pager wait on logtoprocess:
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    94
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    95
Add a script that wait on a file to appears for 5 seconds, if it sees it touch
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    96
another file or die after 5 seconds. If the scripts is awaited by hg, the
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    97
script will die after the timeout before we could touch the file and the
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    98
resulting file will not exists. If not, we will touch the file and see it.
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
    99
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   100
  $ cat > $TESTTMP/wait-output.sh << EOF
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   101
  > #!/bin/sh
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   102
  > for i in \`$TESTDIR/seq.py 50\`; do
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   103
  >   if [ -f "$TESTTMP/wait-for-touched" ];
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   104
  >   then
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   105
  >     touch "$TESTTMP/touched";
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   106
  >     break;
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   107
  >   else
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   108
  >     sleep 0.1;
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   109
  >   fi
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   110
  > done
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   111
  > EOF
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   112
  $ chmod +x $TESTTMP/wait-output.sh
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   113
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   114
  $ cat >> $HGRCPATH << EOF
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   115
  > [extensions]
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   116
  > logtoprocess=
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   117
  > pager=
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   118
  > [logtoprocess]
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   119
  > commandfinish=$TESTTMP/wait-output.sh
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   120
  > EOF
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   121
  $ hg version -q --pager=always
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   122
  Mercurial Distributed SCM (version *) (glob)
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   123
  $ touch $TESTTMP/wait-for-touched
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   124
  $ sleep 0.2
dfca83594145 logtoprocess: add a test to show pager and ltp bad interaction
Boris Feld <boris.feld@octobus.net>
parents: 34764
diff changeset
   125
  $ test -f $TESTTMP/touched && echo "SUCCESS Pager is not waiting on ltp" || echo "FAIL Pager is waiting on ltp"
39926
c4a3d3c67c4f logtoprocess: connect all fds to /dev/null to avoid bad interaction with pager
Boris Feld <boris.feld@octobus.net>
parents: 39925
diff changeset
   126
  SUCCESS Pager is not waiting on ltp