view hgext/logtoprocess.py @ 36528:72e487851a53

debugcommands: add debugwireproto command We currently don't have a low-level mechanism for sending arbitrary wire protocol commands. Having a generic and robust mechanism for sending wire protocol commands, examining wire data, etc would make it vastly easier to test the wire protocol and debug server operation. This is a problem I've wanted a solution for numerous times, especially recently as I've been hacking on a new version of the wire protocol. This commit establishes a `hg debugwireproto` command for sending data to a peer. The command invents a mini language for specifying actions to take. This will enable a lot of flexibility for issuing commands and testing variations for how commands are sent. Right now, we only support low-level raw sends and receives. These are probably the least valuable commands to intended users of this command. But they are the most useful commands to implement to bootstrap the feature (I've chosen to reimplement test-ssh-proto.t using this command to prove its usefulness). My eventual goal of `hg debugwireproto` is to allow calling wire protocol commands with a human-friendly interface. Essentially, people can type in a command name and arguments and `hg debugwireproto` will figure out how to send that on the wire. I'd love to eventually be able to save the server's raw response to a file. This would allow us to e.g. call "getbundle" wire protocol commands easily. test-ssh-proto.t has been updated to use the new command in lieu of piping directly to a server process. As part of the transition, test behavior improved. Before, we piped all request data to the server at once. Now, we have explicit control over the ordering of operations. e.g. we can send one command, receive its response, then send another command. This will allow us to more robustly test race conditions, buffering behavior, etc. There were some subtle changes in test behavior. For example, previous behavior would often send trailing newlines to the server. The new mechanism doesn't treat literal newlines specially and requires newlines be escaped in the payload. Because the new logging code is very low level, it is easy to introduce race conditions in tests. For example, the number of bytes returned by a read() may vary depending on load. This is why tests make heavy use of "readline" for consuming data: the result of that operation should be deterministic and not subject to race conditions. There are still some uses of "readavailable." However, those are only for reading from stderr. I was able to reproduce timing issues with my system under load when using "readavailable" globally. But if I "readline" to grab stdout, "readavailable" appears to work deterministically for stderr. I think this is because the server writes to stderr first. As long as the OS delivers writes to pipes in the same order they were made, this should work. If there are timing issues, we can introduce a mechanism to readline from stderr. Differential Revision: https://phab.mercurial-scm.org/D2392
author Gregory Szorc <gregory.szorc@gmail.com>
date Thu, 01 Mar 2018 08:24:54 -0800
parents 52790352dd05
children c31ce080eb75
line wrap: on
line source

# 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 (
    encoding,
    pycompat,
)

# 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(
                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 = 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:])
                    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(encoding.environ.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