Patchwork [4,of,4] logtoprocess: drop support for ui.log() call with invalid msg arguments (BC)

login
register
mail settings
Submitter Yuya Nishihara
Date Nov. 13, 2018, 1:42 p.m.
Message ID <2f72218f9cfe87996171.1542116539@mimosa>
Download mbox | patch
Permalink /patch/36544/
State Accepted
Headers show

Comments

Yuya Nishihara - Nov. 13, 2018, 1:42 p.m.
# HG changeset patch
# User Yuya Nishihara <yuya@tcha.org>
# Date 1541908558 -32400
#      Sun Nov 11 12:55:58 2018 +0900
# Node ID 2f72218f9cfe8799617126ab453876f007d13b28
# Parent  355cce9374b1f3ca2ecee3c29957b37447b565a4
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.
Boris Feld - Nov. 15, 2018, 10:58 a.m.
I'm +1 for always trying to format the message but could we continue to
pass the other arguments ($MSG2, $MSG3)?

We are using log-to-process to monitor command execution time by reading
`$MSG4` on the command finish.

Having only the formatted message would be more work as we will need to
parse the formatted message to extract the useful information.

How would the new processlogger works, would we still have access to the
message's arguments?


On 13/11/2018 14:42, Yuya Nishihara wrote:
> # HG changeset patch
> # User Yuya Nishihara <yuya@tcha.org>
> # Date 1541908558 -32400
> #      Sun Nov 11 12:55:58 2018 +0900
> # Node ID 2f72218f9cfe8799617126ab453876f007d13b28
> # Parent  355cce9374b1f3ca2ecee3c29957b37447b565a4
> 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.
>
> diff --git a/hgext/logtoprocess.py b/hgext/logtoprocess.py
> --- a/hgext/logtoprocess.py
> +++ b/hgext/logtoprocess.py
> @@ -9,21 +9,21 @@
>  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.
>  
> @@ -60,25 +60,11 @@ def uisetup(ui):
>              """
>              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())
> diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
> --- a/tests/test-logtoprocess.t
> +++ b/tests/test-logtoprocess.t
> @@ -29,18 +29,14 @@ Test if logtoprocess correctly captures 
>    > [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
> @@ -53,16 +49,13 @@ Use sort to avoid ordering issues betwee
>    
>    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
> @@ -70,7 +63,6 @@ Use sort to avoid ordering issues betwee
>    a message: spam
>    foo
>    logtoprocess foo output:
> -  spam
>  #endif
>  
>  Confirm that logging blocked time catches stdio properly:
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Yuya Nishihara - Nov. 15, 2018, 11:42 a.m.
On Thu, 15 Nov 2018 11:58:44 +0100, Boris FELD wrote:
> I'm +1 for always trying to format the message but could we continue to
> pass the other arguments ($MSG2, $MSG3)?
> 
> We are using log-to-process to monitor command execution time by reading
> `$MSG4` on the command finish.
> 
> Having only the formatted message would be more work as we will need to
> parse the formatted message to extract the useful information.

Perhaps the time value can be passed as a OPT_ variable?

> How would the new processlogger works, would we still have access to the
> message's arguments?

I'm going to drop the *msg argument. It could be passed in to logger.log(),
but I don't think it's correct to expose the *msg structure to users. If
we inserted some more %s parameters, $MSG{n} would be shifted. It can't be
stable.

Patch

diff --git a/hgext/logtoprocess.py b/hgext/logtoprocess.py
--- a/hgext/logtoprocess.py
+++ b/hgext/logtoprocess.py
@@ -9,21 +9,21 @@ 
 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.
 
@@ -60,25 +60,11 @@  def uisetup(ui):
             """
             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())
diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -29,18 +29,14 @@  Test if logtoprocess correctly captures 
   > [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
@@ -53,16 +49,13 @@  Use sort to avoid ordering issues betwee
   
   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
@@ -70,7 +63,6 @@  Use sort to avoid ordering issues betwee
   a message: spam
   foo
   logtoprocess foo output:
-  spam
 #endif
 
 Confirm that logging blocked time catches stdio properly: