logtoprocess: execute processes asynchronously

Summary:
Create a Popen() object, and each time ui.log() is called poll these to clear
out any that are done. When dispatch ends, kill any that remain.

Test Plan: Run $HG/tests/run-tests.py test-logtoprocess.t

Reviewers: durham, #sourcecontrol, ttung, quark

Reviewed By: quark

Subscribers: ikostia, simonfar, mjpieters

Differential Revision: https://phabricator.fb.com/D3091363

Signature: t1:3091363:1459781710:4f04e37db3fb1f81abadfe168c5dbc00c376cda7

logtoprocess.py

@@ -11,8 +11,9 @@ 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` argument (so the key is uppercased, and
-prefixed with `OPT_`).
+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
@@ -26,17 +27,55 @@ For example::
 
 would log the warning message and traceback of any failed command dispatch.
 
-Scripts are run sychronously; they should exit ASAP. Preferably the command
-should fork and disown to avoid slowing mercurial down.
+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
 
 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}
+            # 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)
+            # 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
@@ -69,8 +108,11 @@ def uisetup(ui):
                 optpairs = (
                     ('OPT_{0}'.format(key.upper()), str(value))
                     for key, value in opts.iteritems())
-                env = dict(chain(os.environ.items(), msgpairs, optpairs))
-                subprocess.call(script, shell=True, env=env)
+                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:

tests/test-logtoprocess.t

@@ -18,31 +18,39 @@ Test if logtoprocess correctly captures command-related log calls.
   > 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:
+ui.log('commandfinish') call. The foo command also uses ui.log.
 
-  $ hg foo
-  logtoprocess command output:
-  foo
+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
   
-  foo
-  logtoprocess foo output:
-  a message: spam
   
-  spam
-  logtoprocess commandfinish output:
-  foo exited 0 after * seconds (glob)
   
-  foo
   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