view mercurial/hook.py @ 24716:2abbf4750915

hook: forcibly flush stderr for Windows test stability There are a handful of SSH related test failures on Windows. --- c:/Users/Matt/Projects/hg/tests/test-bundle2-exchange.t +++ c:/Users/Matt/Projects/hg/tests/test-bundle2-exchange.t.err @@ -305,16 +305,16 @@ remote: added 1 changesets with 1 changes to 1 files remote: 1 new obsolescence markers updating bookmark book_5fdd + pre-close-tip:02de42196ebe draft book_02de + postclose-tip:02de42196ebe draft book_02de + txnclose hook: HG_SOURCE=push-response HG_TXNNAME=push-response + ssh://user@dummy/other HG_URL=ssh://user@dummy/other remote: pre-close-tip:5fddd98957c8 draft book_5fdd remote: pushkey: lock state after "bookmarks" remote: lock: free remote: wlock: free remote: postclose-tip:5fddd98957c8 draft book_5fdd remote: txnclose hook: (env vars truncated) - pre-close-tip:02de42196ebe draft book_02de - postclose-tip:02de42196ebe draft book_02de - txnclose hook: HG_SOURCE=push-response HG_TXNNAME=push-response - ssh://user@dummy/other HG_URL=ssh://user@dummy/other $ hg -R other log -G o 6:5fddd98957c8 draft Nicolas Dumazet <...> book_5fdd C | --- c:/Users/Matt/Projects/hg/tests/test-ssh.t +++ c:/Users/Matt/Projects/hg/tests/test-ssh.t.err @@ -438,12 +438,12 @@ $ hg push pushing to ssh://user@dummy/remote searching for changes + local stdout remote: adding changesets remote: adding manifests remote: adding file changes remote: added 1 changesets with 1 changes to 1 files - remote: KABOOM - local stdout + remote: KABOOM\r (esc) $ cd .. What is happening is that no data is available in 'sshpeer.pipee' while the command is executing. As the command completes, local output is printed, and then sshpeer.cleanup() is called. When it calls 'self.pipeo.close()', the child process is shutdown, flushing stderr. As an experiment, I printed a line to stdout and another to stderr instead this flush(). The stdout data was immediately available to the hg client, and none of the stderr data was until the child exited. At that point, pipee has all of the buffered data, and it is read out and printed before the pipe is closed in sshpeer.cleanup(). This is probably a known issue, since ui.write_err() mentions that stderr may be buffered, and also flushes stderr. It would be nice if there was a more general fix (there is one more test that fails), but I'm not sure what it is. I've seen (ancient) references [1] to setvbuf() "crashing spectacularly" on some systems if any I/O has been done already, so it seems worth avoiding. https://sourceware.org/ml/gdb-patches/2013-08/msg00422.html [1] https://groups.google.com/forum/#!msg/comp.lang.python/JT8LiYzYDEY/Qg9d1HwyjScJ
author Matt Harbison <matt_harbison@yahoo.com>
date Fri, 10 Apr 2015 22:30:19 -0400
parents 19ebd2f88fc7
children 7046c7e7fcb4
line wrap: on
line source

# hook.py - hook support for mercurial
#
# Copyright 2007 Matt Mackall <mpm@selenic.com>
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.

from i18n import _
import os, sys, time
import extensions, util, demandimport, error

def _pythonhook(ui, repo, name, hname, funcname, args, throw):
    '''call python hook. hook is callable object, looked up as
    name in python module. if callable returns "true", hook
    fails, else passes. if hook raises exception, treated as
    hook failure. exception propagates if throw is "true".

    reason for "true" meaning "hook failed" is so that
    unmodified commands (e.g. mercurial.commands.update) can
    be run as hooks without wrappers to convert return values.'''

    if callable(funcname):
        obj = funcname
        funcname = obj.__module__ + "." + obj.__name__
    else:
        d = funcname.rfind('.')
        if d == -1:
            raise util.Abort(_('%s hook is invalid ("%s" not in '
                               'a module)') % (hname, funcname))
        modname = funcname[:d]
        oldpaths = sys.path
        if util.mainfrozen():
            # binary installs require sys.path manipulation
            modpath, modfile = os.path.split(modname)
            if modpath and modfile:
                sys.path = sys.path[:] + [modpath]
                modname = modfile
        demandimportenabled = demandimport.isenabled()
        if demandimportenabled:
            demandimport.disable()
        try:
            try:
                obj = __import__(modname)
            except ImportError:
                e1 = sys.exc_type, sys.exc_value, sys.exc_traceback
                try:
                    # extensions are loaded with hgext_ prefix
                    obj = __import__("hgext_%s" % modname)
                except ImportError:
                    e2 = sys.exc_type, sys.exc_value, sys.exc_traceback
                    if ui.tracebackflag:
                        ui.warn(_('exception from first failed import '
                                  'attempt:\n'))
                    ui.traceback(e1)
                    if ui.tracebackflag:
                        ui.warn(_('exception from second failed import '
                                  'attempt:\n'))
                    ui.traceback(e2)
                    raise util.Abort(_('%s hook is invalid '
                                       '(import of "%s" failed)') %
                                     (hname, modname))
        finally:
            if demandimportenabled:
                demandimport.enable()
        sys.path = oldpaths
        try:
            for p in funcname.split('.')[1:]:
                obj = getattr(obj, p)
        except AttributeError:
            raise util.Abort(_('%s hook is invalid '
                               '("%s" is not defined)') %
                             (hname, funcname))
        if not callable(obj):
            raise util.Abort(_('%s hook is invalid '
                               '("%s" is not callable)') %
                             (hname, funcname))

    ui.note(_("calling hook %s: %s\n") % (hname, funcname))
    starttime = time.time()

    try:
        try:
            # redirect IO descriptors to the ui descriptors so hooks
            # that write directly to these don't mess up the command
            # protocol when running through the command server
            old = sys.stdout, sys.stderr, sys.stdin
            sys.stdout, sys.stderr, sys.stdin = ui.fout, ui.ferr, ui.fin

            r = obj(ui=ui, repo=repo, hooktype=name, **args)
        except KeyboardInterrupt:
            raise
        except Exception, exc:
            if isinstance(exc, util.Abort):
                ui.warn(_('error: %s hook failed: %s\n') %
                             (hname, exc.args[0]))
            else:
                ui.warn(_('error: %s hook raised an exception: '
                               '%s\n') % (hname, exc))
            if throw:
                raise
            ui.traceback()
            return True
    finally:
        sys.stdout, sys.stderr, sys.stdin = old
        duration = time.time() - starttime
        ui.log('pythonhook', 'pythonhook-%s: %s finished in %0.2f seconds\n',
               name, funcname, duration)
    if r:
        if throw:
            raise error.HookAbort(_('%s hook failed') % hname)
        ui.warn(_('warning: %s hook failed\n') % hname)
    return r

def _exthook(ui, repo, name, cmd, args, throw):
    ui.note(_("running hook %s: %s\n") % (name, cmd))

    starttime = time.time()
    env = {}
    for k, v in args.iteritems():
        if callable(v):
            v = v()
        if isinstance(v, dict):
            # make the dictionary element order stable across Python
            # implementations
            v = ('{' +
                 ', '.join('%r: %r' % i for i in sorted(v.iteritems())) +
                 '}')
        env['HG_' + k.upper()] = v

    if repo:
        cwd = repo.root
    else:
        cwd = os.getcwd()
    r = ui.system(cmd, environ=env, cwd=cwd)

    duration = time.time() - starttime
    ui.log('exthook', 'exthook-%s: %s finished in %0.2f seconds\n',
           name, cmd, duration)
    if r:
        desc, r = util.explainexit(r)
        if throw:
            raise error.HookAbort(_('%s hook %s') % (name, desc))
        ui.warn(_('warning: %s hook %s\n') % (name, desc))
    return r

def _allhooks(ui):
    hooks = []
    for name, cmd in ui.configitems('hooks'):
        if not name.startswith('priority'):
            priority = ui.configint('hooks', 'priority.%s' % name, 0)
            hooks.append((-priority, len(hooks), name, cmd))
    return [(k, v) for p, o, k, v in sorted(hooks)]

_redirect = False
def redirect(state):
    global _redirect
    _redirect = state

def hook(ui, repo, name, throw=False, **args):
    if not ui.callhooks:
        return False

    r = False
    oldstdout = -1

    try:
        for hname, cmd in _allhooks(ui):
            if hname.split('.')[0] != name or not cmd:
                continue

            if oldstdout == -1 and _redirect:
                try:
                    stdoutno = sys.__stdout__.fileno()
                    stderrno = sys.__stderr__.fileno()
                    # temporarily redirect stdout to stderr, if possible
                    if stdoutno >= 0 and stderrno >= 0:
                        sys.__stdout__.flush()
                        oldstdout = os.dup(stdoutno)
                        os.dup2(stderrno, stdoutno)
                except (OSError, AttributeError):
                    # files seem to be bogus, give up on redirecting (WSGI, etc)
                    pass

            if callable(cmd):
                r = _pythonhook(ui, repo, name, hname, cmd, args, throw) or r
            elif cmd.startswith('python:'):
                if cmd.count(':') >= 2:
                    path, cmd = cmd[7:].rsplit(':', 1)
                    path = util.expandpath(path)
                    if repo:
                        path = os.path.join(repo.root, path)
                    try:
                        mod = extensions.loadpath(path, 'hghook.%s' % hname)
                    except Exception:
                        ui.write(_("loading %s hook failed:\n") % hname)
                        raise
                    hookfn = getattr(mod, cmd)
                else:
                    hookfn = cmd[7:].strip()
                r = _pythonhook(ui, repo, name, hname, hookfn, args, throw) or r
            else:
                r = _exthook(ui, repo, hname, cmd, args, throw) or r

            # The stderr is fully buffered on Windows when connected to a pipe.
            # A forcible flush is required to make small stderr data in the
            # remote side available to the client immediately.
            sys.stderr.flush()
    finally:
        if _redirect and oldstdout >= 0:
            os.dup2(oldstdout, stdoutno)
            os.close(oldstdout)

    return r