Patchwork [V2] logtoprocess: new experimental extension

# HG changeset patch
# User Martijn Pieters <mjpieters@fb.com>
# Date 1459874399 -3600
#      Tue Apr 05 17:39:59 2016 +0100
# Node ID ee2dd1a3f2e15b92b4d7f525443e442c08399ec1
# Parent  1e97bcbb87767e1a96909900595a0b6a7791407b
logtoprocess: new experimental extension

This extension lets you direct specific ui.log() information to shell
commands, spawned in the background. This can be used to, say, capture
timings, commandfailure tracebacks, etc., making the output available
to other command-line tools.

On 04/05/2016 10:31 AM, Martijn Pieters wrote:
> # HG changeset patch
> # User Martijn Pieters <mjpieters@fb.com>
> # Date 1459874399 -3600
> #      Tue Apr 05 17:39:59 2016 +0100
> # Node ID ee2dd1a3f2e15b92b4d7f525443e442c08399ec1
> # Parent  1e97bcbb87767e1a96909900595a0b6a7791407b
> logtoprocess: new experimental extension

We need an entry on the wiki page as a first step:

https://www.mercurial-scm.org/wiki/ExperimentalExtensionsPlan#Current_Candidate_extensions

On Tue, Apr 05, 2016 at 06:31:08PM +0100, Martijn Pieters wrote:
> # HG changeset patch
> # User Martijn Pieters <mjpieters@fb.com>
> # Date 1459874399 -3600
> #      Tue Apr 05 17:39:59 2016 +0100
> # Node ID ee2dd1a3f2e15b92b4d7f525443e442c08399ec1
> # Parent  1e97bcbb87767e1a96909900595a0b6a7791407b
> logtoprocess: new experimental extension

OOC, is this part of the grand blackbox-replacement plan that I
vaguely remember from the sprint?

(haven't looked closely at this yet)


>
> This extension lets you direct specific ui.log() information to shell
> commands, spawned in the background. This can be used to, say, capture
> timings, commandfailure tracebacks, etc., making the output available
> to other command-line tools.
>
> diff --git a/hgext/logtoprocess.py b/hgext/logtoprocess.py
> new file mode 100644
> --- /dev/null
> +++ b/hgext/logtoprocess.py
> @@ -0,0 +1,127 @@
> +# 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 asychronously as detached daemon processes; mercurial will
> +not ensure that they exit cleanly.
> +
> +"""
> +
> +import os
> +import platform
> +import subprocess
> +import sys
> +
> +from itertools import chain
> +
> +# Note for extension authors: ONLY specify testedwith = 'internal' 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 = 'internal'
> +
> +def uisetup(ui):
> +    if platform.system() == 'Windows':
> +        # no fork on Windows, but we can create a detached process
> +        # https://msdn.microsoft.com/en-us/library/windows/desktop/ms684863(v=vs.85).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(
> +                script, shell=True, env=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 stdin to devnull to make sure the subprocess can't
> +                # muck up that stream for mercurial.
> +                subprocess.Popen(
> +                    script, shell=True, stdin=open(os.devnull, 'r'), env=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 = ui.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:])
> +                    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(chain(os.environ.items(), msgpairs, optpairs),
> +                           EVENT=event, HGPID=str(os.getpid()))
> +                # Connect stdin to /dev/null to prevent child processes messing
> +                # with mercurial's stdin.
> +                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
> diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
> new file mode 100644
> --- /dev/null
> +++ b/tests/test-logtoprocess.t
> @@ -0,0 +1,54 @@
> +Test if logtoprocess correctly captures command-related log calls.
> +
> +  $ hg init
> +  $ cat > $TESTTMP/foocommand.py << EOF
> +  > from mercurial import cmdutil
> +  > from time import sleep
> +  > cmdtable = {}
> +  > command = cmdutil.command(cmdtable)
> +  > @command('foo', [])
> +  > def foo(ui, repo):
> +  >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
> +  > EOF
> +  $ 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 head to ensure we wait for all lines to be produced, and sort to avoid
> +ordering issues between the various processes we spawn:
> +  $ hg foo | head -n 17 | sort
> +
> +
> +
> +  0
> +  a message: spam
> +  command
> +  commandfinish
> +  foo
> +  foo
> +  foo
> +  foo
> +  foo exited 0 after * seconds (glob)
> +  logtoprocess command output:
> +  logtoprocess commandfinish output:
> +  logtoprocess foo output:
> +  spam
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

On 5 April 2016 at 18:42, Pierre-Yves David
<pierre-yves.david@ens-lyon.org> wrote:
> We need an entry on the wiki page as a first step:
>
> https://www.mercurial-scm.org/wiki/ExperimentalExtensionsPlan#Current_Candidate_extensions

Done.

On 5 April 2016 at 19:10, Augie Fackler <raf@durin42.com> wrote:
> OOC, is this part of the grand blackbox-replacement plan that I
> vaguely remember from the sprint?
>
> (haven't looked closely at this yet)

This is one part of our internal error logging extension that I ripped
apart into constituent parts. I have an email in draft to talk more
about this.

I deliberately kept this separate from blackbox as I felt the goals
where different, but if people want to see this as part of blackbox
anyway then we can discuss that option.

On 04/05/2016 07:10 PM, Augie Fackler wrote:
> OOC, is this part of the grand blackbox-replacement plan that I
> vaguely remember from the sprint?

Let me help you recall :)

At the spring you showed some interest about the errorredirect extension that 
allows a custom external script to send the crash log remotely. I said I will
upstream the extension.

Soon after, we found we actually want a more general extension that "pipe"s
different kinds of logs to external scripts. And then:

Mar 21 16:49:52 <junw>	durin42, about the errorredirect extension, we are 
making it more general so it will be basically allowing hooks for different 
"event"s of ui.log
Mar 21 16:53:09 <junw>	so we can put things like ui.log(service='remotelog', 
...) to get more idea about performance
Mar 21 16:53:45 <junw>	Martijn is working on this (making errorredirect more 
general)
Mar 21 17:21:23 <durin42>	junw: awesome

On Tue, Apr 5, 2016 at 2:35 PM, Jun Wu <quark@fb.com> wrote:
> On 04/05/2016 07:10 PM, Augie Fackler wrote:
>>
>> OOC, is this part of the grand blackbox-replacement plan that I
>> vaguely remember from the sprint?
>
>
> Let me help you recall :)
>
> At the spring you showed some interest about the errorredirect extension
> that allows a custom external script to send the crash log remotely. I said
> I will
> upstream the extension.
>
> Soon after, we found we actually want a more general extension that "pipe"s
> different kinds of logs to external scripts. And then:
>
> Mar 21 16:49:52 <junw>  durin42, about the errorredirect extension, we are
> making it more general so it will be basically allowing hooks for different
> "event"s of ui.log
> Mar 21 16:53:09 <junw>  so we can put things like
> ui.log(service='remotelog', ...) to get more idea about performance
> Mar 21 16:53:45 <junw>  Martijn is working on this (making errorredirect
> more general)
> Mar 21 17:21:23 <durin42>       junw: awesome

Awesome. Thanks for doing my homework for me. :)

On Tue, 2016-04-05 at 18:31 +0100, Martijn Pieters wrote:
> # HG changeset patch
> # User Martijn Pieters <mjpieters@fb.com>
> # Date 1459874399 -3600
> #      Tue Apr 05 17:39:59 2016 +0100
> # Node ID ee2dd1a3f2e15b92b4d7f525443e442c08399ec1
> # Parent  1e97bcbb87767e1a96909900595a0b6a7791407b
> logtoprocess: new experimental extension

Queued for default, thanks. Check-code says hi.

-- 
Mathematics is the supreme nostalgia of our time.

On Tue, 05 Apr 2016 13:31:08 -0400, Martijn Pieters <mj@zopatista.com>  
wrote:

> # HG changeset patch
> # User Martijn Pieters <mjpieters@fb.com>
> # Date 1459874399 -3600
> #      Tue Apr 05 17:39:59 2016 +0100
> # Node ID ee2dd1a3f2e15b92b4d7f525443e442c08399ec1
> # Parent  1e97bcbb87767e1a96909900595a0b6a7791407b
> logtoprocess: new experimental extension
>
> This extension lets you direct specific ui.log() information to shell
> commands, spawned in the background. This can be used to, say, capture
> timings, commandfailure tracebacks, etc., making the output available
> to other command-line tools.
>
...

> +
> +Running a command triggers both a ui.log('command') and a
> +ui.log('commandfinish') call. The foo command also uses ui.log.
> +
> +Use head to ensure we wait for all lines to be produced, and sort to  
> avoid
> +ordering issues between the various processes we spawn:
> +  $ hg foo | head -n 17 | sort
> +
> +
> +
> +  0
> +  a message: spam
> +  command
> +  commandfinish
> +  foo
> +  foo
> +  foo
> +  foo
> +  foo exited 0 after * seconds (glob)
> +  logtoprocess command output:
> +  logtoprocess commandfinish output:
> +  logtoprocess foo output:
> +  spam

FWIW, I'm not seeing any output from this command on Windows 7.  The exit  
code is still 0.

On 16 April 2016 at 04:43, Matt Harbison <mharbison72@gmail.com> wrote:
> FWIW, I'm not seeing any output from this command on Windows 7.  The exit
> code is still 0.

Ah, yes, that'd be because we explicitly disconnect the subprocess
entirely on Windows (there is no forking option). Suggestions on how
to improve on this are most welcome!