logtoprocess: drop support for ui.log() call with invalid msg arguments (BC)

Before, the logtoprocess extension put a formatted message into $MSG1, and
its arguments to $MSG2... If the specified arguments couldn't be formatted
because of a caller bug, an unformatted message was passed in to $MSG1
instead of exploding. This behavior doesn't make sense.

Since I'm planning to formalize the ui.log() interface such that we'll no
longer have to extend the ui class, I want to remove any features not
conforming to the ui.log() API. So this patch removes the support for
ill-formed arguments, and $MSG{n} (where n > 1) parameters which seems
useless as long as the message can be formatted. The $MSG1 variable isn't
renamed for the maximum compatibility.

In future patches, a formatted msg will be passed to a processlogger object,
instead of overriding the ui.log() function.

.. bc::

   The logtoprocess extension no longer supports invalid ``ui.log()``
   arguments. A log message is always formatted and passed in to the
   ``$MSG1`` environment variable.

hgext/logtoprocess.py

@@ -1,90 +1,76 b''
 # 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`.
+Positional arguments construct a log message, which is passed in the `MSG1`
+environment variables. 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`.
+So given a call `ui.log('foo', 'bar %s\n', 'baz', spam='eggs'), a script
+configured for the `foo` event can expect an environment with `MSG1=bar 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
+  commandexception = echo "$MSG1" > /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 os
 
 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):
 
     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:
-                        # 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
                 env = {
                     b'EVENT': event,
                     b'HGPID': os.getpid(),
+                    b'MSG1': msg[0] % msg[1:],
                 }
-                # positional arguments are listed as MSG[N] keys in the
-                # environment
-                env.update((b'MSG%d' % i, m) for i, m in enumerate(messages, 1))
                 # keyword arguments get prefixed with OPT_ and uppercased
                 env.update((b'OPT_%s' % key.upper(), value)
                            for key, value in pycompat.byteskwargs(opts).items())
                 fullenv = procutil.shellenviron(env)
                 procutil.runbgcommand(script, fullenv, shell=True)
             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,126 +1,118 b''
 #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(b'logtoprocess', b'foo',
   >     default=None,
   > )
   > @command(b'foobar', [])
   > def foo(ui, repo):
   >     ui.log(b'foo', b'a message: %s\n', b'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
+  >     echo "\$MSG1") > $TESTTMP/command.log
   > commandfinish=(echo 'logtoprocess commandfinish output:';
   >     echo "\$EVENT";
   >     echo "\$MSG1";
-  >     echo "\$MSG2";
-  >     echo "\$MSG3";
   >     echo "canonical: \$OPT_CANONICAL_COMMAND") > $TESTTMP/commandfinish.log
   > foo=(echo 'logtoprocess foo output:';
   >     echo "\$EVENT";
-  >     echo "\$MSG1";
-  >     echo "\$MSG2") > $TESTTMP/foo.log
+  >     echo "\$MSG1") > $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 fooba
   $ sleep 1
   $ cat $TESTTMP/command.log | sort
   
   command
   fooba
-  fooba
   logtoprocess command output:
 
 #if no-chg
   $ cat $TESTTMP/commandfinish.log | sort
   
-  0
   canonical: foobar
   commandfinish
-  fooba
   fooba 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