logtoprocess: fix message formatting

The logtoprocess used to try formatting the message using keyword options
instead of always using the rest of the arguments. Update it to match blackbox
behavior.

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

hgext/logtoprocess.py

@@ -1,142 +1,140
 # logtoprocess.py - send ui.log() data to a subprocess
 #
 # Copyright 2016 Facebook, Inc.
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 """send ui.log() data to a subprocess (EXPERIMENTAL)
 
 This extension lets you specify a shell command per ui.log() event,
 sending all remaining arguments to as environment variables to that command.
 
 Each positional argument to the method results in a `MSG[N]` key in the
 environment, starting at 1 (so `MSG1`, `MSG2`, etc.). Each keyword argument
 is set as a `OPT_UPPERCASE_KEY` variable (so the key is uppercased, and
 prefixed with `OPT_`). The original event name is passed in the `EVENT`
 environment variable, and the process ID of mercurial is given in `HGPID`.
 
 So given a call `ui.log('foo', 'bar', 'baz', spam='eggs'), a script configured
 for the `foo` event can expect an environment with `MSG1=bar`, `MSG2=baz`, and
 `OPT_SPAM=eggs`.
 
 Scripts are configured in the `[logtoprocess]` section, each key an event name.
 For example::
 
   [logtoprocess]
   commandexception = echo "$MSG2$MSG3" > /var/log/mercurial_exceptions.log
 
 would log the warning message and traceback of any failed command dispatch.
 
 Scripts are run asynchronously as detached daemon processes; mercurial will
 not ensure that they exit cleanly.
 
 """
 
 from __future__ import absolute_import
 
 import itertools
 import os
 import subprocess
 import sys
 
 from mercurial import (
     pycompat,
 )
 
 from mercurial.utils import (
     procutil,
 )
 
 # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for
 # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should
 # be specifying the version(s) of Mercurial they are tested with, or
 # leave the attribute unspecified.
 testedwith = 'ships-with-hg-core'
 
 def uisetup(ui):
     if pycompat.iswindows:
         # no fork on Windows, but we can create a detached process
         # https://msdn.microsoft.com/en-us/library/windows/desktop/ms684863.aspx
         # No stdlib constant exists for this value
         DETACHED_PROCESS = 0x00000008
         _creationflags = DETACHED_PROCESS | subprocess.CREATE_NEW_PROCESS_GROUP
 
         def runshellcommand(script, env):
             # we can't use close_fds *and* redirect stdin. I'm not sure that we
             # need to because the detached process has no console connection.
             subprocess.Popen(
                 procutil.tonativestr(script),
                 shell=True, env=procutil.tonativeenv(env), close_fds=True,
                 creationflags=_creationflags)
     else:
         def runshellcommand(script, env):
             # double-fork to completely detach from the parent process
             # based on http://code.activestate.com/recipes/278731
             pid = os.fork()
             if pid:
                 # parent
                 return
             # subprocess.Popen() forks again, all we need to add is
             # flag the new process as a new session.
             if sys.version_info < (3, 2):
                 newsession = {'preexec_fn': os.setsid}
             else:
                 newsession = {'start_new_session': True}
             try:
                 # connect std* to devnull to make sure the subprocess can't
                 # muck up these stream for mercurial.
                 # Connect all the streams to be more close to Windows behavior
                 # and pager will wait for scripts to end if we don't do that
                 nullrfd = open(os.devnull, 'r')
                 nullwfd = open(os.devnull, 'w')
                 subprocess.Popen(
                     procutil.tonativestr(script),
                     shell=True, stdin=nullrfd,
                     stdout=nullwfd, stderr=nullwfd,
                     env=procutil.tonativeenv(env),
                     close_fds=True, **newsession)
             finally:
                 # mission accomplished, this child needs to exit and not
                 # continue the hg process here.
                 os._exit(0)
 
     class logtoprocessui(ui.__class__):
         def log(self, event, *msg, **opts):
             """Map log events to external commands
 
             Arguments are passed on as environment variables.
 
             """
             script = self.config('logtoprocess', event)
             if script:
                 if msg:
                     # try to format the log message given the remaining
                     # arguments
                     try:
-                        # Python string formatting with % either uses a
-                        # dictionary *or* tuple, but not both. If we have
-                        # keyword options, assume we need a mapping.
-                        formatted = msg[0] % (opts or msg[1:])
+                        # Format the message as blackbox does
+                        formatted = msg[0] % msg[1:]
                     except (TypeError, KeyError):
                         # Failed to apply the arguments, ignore
                         formatted = msg[0]
                     messages = (formatted,) + msg[1:]
                 else:
                     messages = msg
                 # positional arguments are listed as MSG[N] keys in the
                 # environment
                 msgpairs = (
                     ('MSG{0:d}'.format(i), str(m))
                     for i, m in enumerate(messages, 1))
                 # keyword arguments get prefixed with OPT_ and uppercased
                 optpairs = (
                     ('OPT_{0}'.format(key.upper()), str(value))
                     for key, value in opts.iteritems())
                 env = dict(itertools.chain(procutil.shellenviron().items(),
                                            msgpairs, optpairs),
                            EVENT=event, HGPID=str(os.getpid()))
                 runshellcommand(script, env)
             return super(logtoprocessui, self).log(event, *msg, **opts)
 
     # Replace the class for this instance and all clones created from it:
     ui.__class__ = logtoprocessui

tests/test-logtoprocess.t

@@ -1,124 +1,124
 #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')
+  >     ui.log('foo', 'a message: %s\n', '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") > $TESTTMP/command.log
   > commandfinish=(echo 'logtoprocess commandfinish output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
   >     echo "\$MSG2";
   >     echo "\$MSG3") > $TESTTMP/commandfinish.log
   > foo=(echo 'logtoprocess foo output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
-  >     echo "\$OPT_BAR") > $TESTTMP/foo.log
+  >     echo "\$MSG2") > $TESTTMP/foo.log
   > 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
   $ sleep 1
   $ cat $TESTTMP/command.log | sort
   
   command
   foo
   foo
   logtoprocess command output:
 
 #if no-chg
   $ cat $TESTTMP/commandfinish.log | sort
   
   0
   commandfinish
   foo
   foo exited 0 after * seconds (glob)
   logtoprocess commandfinish output:
   $ cat $TESTTMP/foo.log | sort
   
   a message: spam
   foo
   logtoprocess foo output:
   spam
 #endif
 
 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" > $TESTTMP/uiblocked.log
   > [ui]
   > logblockedtimes=True
   > EOF
 
   $ hg log
   $ sleep 1
   $ cat $TESTTMP/uiblocked.log
   uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
 
 Try to confirm that pager wait on logtoprocess:
 
 Add a script that wait on a file to appears for 5 seconds, if it sees it touch
 another file or die after 5 seconds. If the scripts is awaited by hg, the
 script will die after the timeout before we could touch the file and the
 resulting file will not exists. If not, we will touch the file and see it.
 
   $ cat > $TESTTMP/wait-output.sh << EOF
   > #!/bin/sh
   > for i in \`$TESTDIR/seq.py 50\`; do
   >   if [ -f "$TESTTMP/wait-for-touched" ];
   >   then
   >     touch "$TESTTMP/touched";
   >     break;
   >   else
   >     sleep 0.1;
   >   fi
   > done
   > EOF
   $ chmod +x $TESTTMP/wait-output.sh
 
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > logtoprocess=
   > pager=
   > [logtoprocess]
   > commandfinish=$TESTTMP/wait-output.sh
   > EOF
   $ hg version -q --pager=always
   Mercurial Distributed SCM (version *) (glob)
   $ touch $TESTTMP/wait-for-touched
   $ sleep 0.2
   $ test -f $TESTTMP/touched && echo "SUCCESS Pager is not waiting on ltp" || echo "FAIL Pager is waiting on ltp"
   SUCCESS Pager is not waiting on ltp