sshpeer: add support for request tracing

The new 'devel.debug.peer-request' option now also display some information
about request going through ssh peer.

mercurial/sshpeer.py

@@ -1,362 +1,373 b''
 # sshpeer.py - ssh repository proxy class for mercurial
 #
 # Copyright 2005, 2006 Matt Mackall <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 from __future__ import absolute_import
 
 import re
 
 from .i18n import _
 from . import (
     error,
     pycompat,
     util,
     wireproto,
 )
 
 def _serverquote(s):
     """quote a string for the remote shell ... which we assume is sh"""
     if not s:
         return s
     if re.match('[a-zA-Z0-9@%_+=:,./-]*$', s):
         return s
     return "'%s'" % s.replace("'", "'\\''")
 
 def _forwardoutput(ui, pipe):
     """display all data currently available on pipe as remote output.
 
     This is non blocking."""
     s = util.readpipe(pipe)
     if s:
         for l in s.splitlines():
             ui.status(_("remote: "), l, '\n')
 
 class doublepipe(object):
     """Operate a side-channel pipe in addition of a main one
 
     The side-channel pipe contains server output to be forwarded to the user
     input. The double pipe will behave as the "main" pipe, but will ensure the
     content of the "side" pipe is properly processed while we wait for blocking
     call on the "main" pipe.
 
     If large amounts of data are read from "main", the forward will cease after
     the first bytes start to appear. This simplifies the implementation
     without affecting actual output of sshpeer too much as we rarely issue
     large read for data not yet emitted by the server.
 
     The main pipe is expected to be a 'bufferedinputpipe' from the util module
     that handle all the os specific bits. This class lives in this module
     because it focus on behavior specific to the ssh protocol."""
 
     def __init__(self, ui, main, side):
         self._ui = ui
         self._main = main
         self._side = side
 
     def _wait(self):
         """wait until some data are available on main or side
 
         return a pair of boolean (ismainready, issideready)
 
         (This will only wait for data if the setup is supported by `util.poll`)
         """
         if getattr(self._main, 'hasbuffer', False): # getattr for classic pipe
             return (True, True) # main has data, assume side is worth poking at.
         fds = [self._main.fileno(), self._side.fileno()]
         try:
             act = util.poll(fds)
         except NotImplementedError:
             # non supported yet case, assume all have data.
             act = fds
         return (self._main.fileno() in act, self._side.fileno() in act)
 
     def write(self, data):
         return self._call('write', data)
 
     def read(self, size):
         r = self._call('read', size)
         if size != 0 and not r:
             # We've observed a condition that indicates the
             # stdout closed unexpectedly. Check stderr one
             # more time and snag anything that's there before
             # letting anyone know the main part of the pipe
             # closed prematurely.
             _forwardoutput(self._ui, self._side)
         return r
 
     def readline(self):
         return self._call('readline')
 
     def _call(self, methname, data=None):
         """call <methname> on "main", forward output of "side" while blocking
         """
         # data can be '' or 0
         if (data is not None and not data) or self._main.closed:
             _forwardoutput(self._ui, self._side)
             return ''
         while True:
             mainready, sideready = self._wait()
             if sideready:
                 _forwardoutput(self._ui, self._side)
             if mainready:
                 meth = getattr(self._main, methname)
                 if data is None:
                     return meth()
                 else:
                     return meth(data)
 
     def close(self):
         return self._main.close()
 
     def flush(self):
         return self._main.flush()
 
 class sshpeer(wireproto.wirepeer):
     def __init__(self, ui, path, create=False):
         self._url = path
         self._ui = ui
         self._pipeo = self._pipei = self._pipee = None
 
         u = util.url(path, parsequery=False, parsefragment=False)
         if u.scheme != 'ssh' or not u.host or u.path is None:
             self._abort(error.RepoError(_("couldn't parse location %s") % path))
 
         util.checksafessh(path)
 
         if u.passwd is not None:
             self._abort(error.RepoError(_("password in URL not supported")))
 
         self._user = u.user
         self._host = u.host
         self._port = u.port
         self._path = u.path or '.'
 
         sshcmd = self.ui.config("ui", "ssh")
         remotecmd = self.ui.config("ui", "remotecmd")
         sshaddenv = dict(self.ui.configitems("sshenv"))
         sshenv = util.shellenviron(sshaddenv)
 
         args = util.sshargs(sshcmd, self._host, self._user, self._port)
 
         if create:
             cmd = '%s %s %s' % (sshcmd, args,
                 util.shellquote("%s init %s" %
                     (_serverquote(remotecmd), _serverquote(self._path))))
             ui.debug('running %s\n' % cmd)
             res = ui.system(cmd, blockedtag='sshpeer', environ=sshenv)
             if res != 0:
                 self._abort(error.RepoError(_("could not create remote repo")))
 
         self._validaterepo(sshcmd, args, remotecmd, sshenv)
 
     # Begin of _basepeer interface.
 
     @util.propertycache
     def ui(self):
         return self._ui
 
     def url(self):
         return self._url
 
     def local(self):
         return None
 
     def peer(self):
         return self
 
     def canpush(self):
         return True
 
     def close(self):
         pass
 
     # End of _basepeer interface.
 
     # Begin of _basewirecommands interface.
 
     def capabilities(self):
         return self._caps
 
     # End of _basewirecommands interface.
 
     def _validaterepo(self, sshcmd, args, remotecmd, sshenv=None):
         # cleanup up previous run
         self._cleanup()
 
         cmd = '%s %s %s' % (sshcmd, args,
             util.shellquote("%s -R %s serve --stdio" %
                 (_serverquote(remotecmd), _serverquote(self._path))))
         self.ui.debug('running %s\n' % cmd)
         cmd = util.quotecommand(cmd)
 
         # while self._subprocess isn't used, having it allows the subprocess to
         # to clean up correctly later
         #
         # no buffer allow the use of 'select'
         # feel free to remove buffering and select usage when we ultimately
         # move to threading.
         sub = util.popen4(cmd, bufsize=0, env=sshenv)
         self._pipeo, self._pipei, self._pipee, self._subprocess = sub
 
         self._pipei = util.bufferedinputpipe(self._pipei)
         self._pipei = doublepipe(self.ui, self._pipei, self._pipee)
         self._pipeo = doublepipe(self.ui, self._pipeo, self._pipee)
 
         def badresponse():
             msg = _("no suitable response from remote hg")
             hint = self.ui.config("ui", "ssherrorhint")
             self._abort(error.RepoError(msg, hint=hint))
 
         try:
             # skip any noise generated by remote shell
             self._callstream("hello")
             r = self._callstream("between", pairs=("%s-%s" % ("0"*40, "0"*40)))
         except IOError:
             badresponse()
 
         lines = ["", "dummy"]
         max_noise = 500
         while lines[-1] and max_noise:
             try:
                 l = r.readline()
                 self._readerr()
                 if lines[-1] == "1\n" and l == "\n":
                     break
                 if l:
                     self.ui.debug("remote: ", l)
                 lines.append(l)
                 max_noise -= 1
             except IOError:
                 badresponse()
         else:
             badresponse()
 
         self._caps = set()
         for l in reversed(lines):
             if l.startswith("capabilities:"):
                 self._caps.update(l[:-1].split(":")[1].split())
                 break
 
     def _readerr(self):
         _forwardoutput(self.ui, self._pipee)
 
     def _abort(self, exception):
         self._cleanup()
         raise exception
 
     def _cleanup(self):
         if self._pipeo is None:
             return
         self._pipeo.close()
         self._pipei.close()
         try:
             # read the error descriptor until EOF
             for l in self._pipee:
                 self.ui.status(_("remote: "), l)
         except (IOError, ValueError):
             pass
         self._pipee.close()
 
     __del__ = _cleanup
 
     def _submitbatch(self, req):
         rsp = self._callstream("batch", cmds=wireproto.encodebatchcmds(req))
         available = self._getamount()
         # TODO this response parsing is probably suboptimal for large
         # batches with large responses.
         toread = min(available, 1024)
         work = rsp.read(toread)
         available -= toread
         chunk = work
         while chunk:
             while ';' in work:
                 one, work = work.split(';', 1)
                 yield wireproto.unescapearg(one)
             toread = min(available, 1024)
             chunk = rsp.read(toread)
             available -= toread
             work += chunk
         yield wireproto.unescapearg(work)
 
     def _callstream(self, cmd, **args):
         args = pycompat.byteskwargs(args)
+        if (self.ui.debugflag
+            and self.ui.configbool('devel', 'debug.peer-request')):
+            dbg = self.ui.debug
+            line = 'devel-peer-request: %s\n'
+            dbg(line % cmd)
+            for key, value in sorted(args.items()):
+                if not isinstance(value, dict):
+                    dbg(line % '  %s: %d bytes' % (key, len(value)))
+                else:
+                    for dk, dv in sorted(value.items()):
+                        dbg(line % '  %s-%s: %d' % (key, dk, len(dv)))
         self.ui.debug("sending %s command\n" % cmd)
         self._pipeo.write("%s\n" % cmd)
         _func, names = wireproto.commands[cmd]
         keys = names.split()
         wireargs = {}
         for k in keys:
             if k == '*':
                 wireargs['*'] = args
                 break
             else:
                 wireargs[k] = args[k]
                 del args[k]
         for k, v in sorted(wireargs.iteritems()):
             self._pipeo.write("%s %d\n" % (k, len(v)))
             if isinstance(v, dict):
                 for dk, dv in v.iteritems():
                     self._pipeo.write("%s %d\n" % (dk, len(dv)))
                     self._pipeo.write(dv)
             else:
                 self._pipeo.write(v)
         self._pipeo.flush()
 
         return self._pipei
 
     def _callcompressable(self, cmd, **args):
         return self._callstream(cmd, **args)
 
     def _call(self, cmd, **args):
         self._callstream(cmd, **args)
         return self._recv()
 
     def _callpush(self, cmd, fp, **args):
         r = self._call(cmd, **args)
         if r:
             return '', r
         for d in iter(lambda: fp.read(4096), ''):
             self._send(d)
         self._send("", flush=True)
         r = self._recv()
         if r:
             return '', r
         return self._recv(), ''
 
     def _calltwowaystream(self, cmd, fp, **args):
         r = self._call(cmd, **args)
         if r:
             # XXX needs to be made better
             raise error.Abort(_('unexpected remote reply: %s') % r)
         for d in iter(lambda: fp.read(4096), ''):
             self._send(d)
         self._send("", flush=True)
         return self._pipei
 
     def _getamount(self):
         l = self._pipei.readline()
         if l == '\n':
             self._readerr()
             msg = _('check previous remote output')
             self._abort(error.OutOfBandError(hint=msg))
         self._readerr()
         try:
             return int(l)
         except ValueError:
             self._abort(error.ResponseError(_("unexpected response:"), l))
 
     def _recv(self):
         return self._pipei.read(self._getamount())
 
     def _send(self, data, flush=False):
         self._pipeo.write("%d\n" % len(data))
         if data:
             self._pipeo.write(data)
         if flush:
             self._pipeo.flush()
         self._readerr()
 
 instance = sshpeer

tests/test-ssh.t

@@ -1,616 +1,629 b''
 
 This test tries to exercise the ssh functionality with a dummy script
 
   $ cat <<EOF >> $HGRCPATH
   > [format]
   > usegeneraldelta=yes
   > EOF
 
 creating 'remote' repo
 
   $ hg init remote
   $ cd remote
   $ echo this > foo
   $ echo this > fooO
   $ hg ci -A -m "init" foo fooO
 
 insert a closed branch (issue4428)
 
   $ hg up null
   0 files updated, 0 files merged, 2 files removed, 0 files unresolved
   $ hg branch closed
   marked working directory as branch closed
   (branches are permanent and global, did you want a bookmark?)
   $ hg ci -mc0
   $ hg ci --close-branch -mc1
   $ hg up -q default
 
 configure for serving
 
   $ cat <<EOF > .hg/hgrc
   > [server]
   > uncompressed = True
   > 
   > [hooks]
   > changegroup = sh -c "printenv.py changegroup-in-remote 0 ../dummylog"
   > EOF
   $ cd ..
 
 repo not found error
 
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/nonexistent local
   remote: abort: repository nonexistent not found!
   abort: no suitable response from remote hg!
   [255]
 
 non-existent absolute path
 
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/`pwd`/nonexistent local
   remote: abort: repository $TESTTMP/nonexistent not found!
   abort: no suitable response from remote hg!
   [255]
 
 clone remote via stream
 
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" --stream ssh://user@dummy/remote local-stream
   streaming all changes
   4 files to transfer, 602 bytes of data
   transferred 602 bytes in * seconds (*) (glob)
   searching for changes
   no changes found
   updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ cd local-stream
   $ hg verify
   checking changesets
   checking manifests
   crosschecking files in changesets and manifests
   checking files
   2 files, 3 changesets, 2 total revisions
   $ hg branches
   default                        0:1160648e36ce
   $ cd ..
 
 clone bookmarks via stream
 
   $ hg -R local-stream book mybook
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" --stream ssh://user@dummy/local-stream stream2
   streaming all changes
   4 files to transfer, 602 bytes of data
   transferred 602 bytes in * seconds (*) (glob)
   searching for changes
   no changes found
   updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ cd stream2
   $ hg book
      mybook                    0:1160648e36ce
   $ cd ..
   $ rm -rf local-stream stream2
 
 clone remote via pull
 
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/remote local
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 3 changesets with 2 changes to 2 files
   new changesets 1160648e36ce:ad076bfb429d
   updating to branch default
   2 files updated, 0 files merged, 0 files removed, 0 files unresolved
 
 verify
 
   $ cd local
   $ hg verify
   checking changesets
   checking manifests
   crosschecking files in changesets and manifests
   checking files
   2 files, 3 changesets, 2 total revisions
   $ cat >> .hg/hgrc <<EOF
   > [hooks]
   > changegroup = sh -c "printenv.py changegroup-in-local 0 ../dummylog"
   > EOF
 
 empty default pull
 
   $ hg paths
   default = ssh://user@dummy/remote
   $ hg pull -e "\"$PYTHON\" \"$TESTDIR/dummyssh\""
   pulling from ssh://user@dummy/remote
   searching for changes
   no changes found
 
 pull from wrong ssh URL
 
   $ hg pull -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/doesnotexist
   pulling from ssh://user@dummy/doesnotexist
   remote: abort: repository doesnotexist not found!
   abort: no suitable response from remote hg!
   [255]
 
 local change
 
   $ echo bleah > foo
   $ hg ci -m "add"
 
 updating rc
 
   $ echo "default-push = ssh://user@dummy/remote" >> .hg/hgrc
   $ echo "[ui]" >> .hg/hgrc
   $ echo "ssh = \"$PYTHON\" \"$TESTDIR/dummyssh\"" >> .hg/hgrc
 
 find outgoing
 
   $ hg out ssh://user@dummy/remote
   comparing with ssh://user@dummy/remote
   searching for changes
   changeset:   3:a28a9d1a809c
   tag:         tip
   parent:      0:1160648e36ce
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add
   
 
 find incoming on the remote side
 
   $ hg incoming -R ../remote -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/local
   comparing with ssh://user@dummy/local
   searching for changes
   changeset:   3:a28a9d1a809c
   tag:         tip
   parent:      0:1160648e36ce
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add
   
 
 find incoming on the remote side (using absolute path)
 
   $ hg incoming -R ../remote -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" "ssh://user@dummy/`pwd`"
   comparing with ssh://user@dummy/$TESTTMP/local
   searching for changes
   changeset:   3:a28a9d1a809c
   tag:         tip
   parent:      0:1160648e36ce
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add
   
 
 push
 
   $ hg push
   pushing to ssh://user@dummy/remote
   searching for changes
   remote: adding changesets
   remote: adding manifests
   remote: adding file changes
   remote: added 1 changesets with 1 changes to 1 files
   $ cd ../remote
 
 check remote tip
 
   $ hg tip
   changeset:   3:a28a9d1a809c
   tag:         tip
   parent:      0:1160648e36ce
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     add
   
   $ hg verify
   checking changesets
   checking manifests
   crosschecking files in changesets and manifests
   checking files
   2 files, 4 changesets, 3 total revisions
   $ hg cat -r tip foo
   bleah
   $ echo z > z
   $ hg ci -A -m z z
   created new head
 
 test pushkeys and bookmarks
 
   $ cd ../local
   $ hg debugpushkey --config ui.ssh="\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/remote namespaces
   bookmarks	
   namespaces	
   phases	
   $ hg book foo -r 0
   $ hg out -B
   comparing with ssh://user@dummy/remote
   searching for changed bookmarks
      foo                       1160648e36ce
   $ hg push -B foo
   pushing to ssh://user@dummy/remote
   searching for changes
   no changes found
   exporting bookmark foo
   [1]
   $ hg debugpushkey --config ui.ssh="\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/remote bookmarks
   foo	1160648e36cec0054048a7edc4110c6f84fde594
   $ hg book -f foo
   $ hg push --traceback
   pushing to ssh://user@dummy/remote
   searching for changes
   no changes found
   updating bookmark foo
   [1]
   $ hg book -d foo
   $ hg in -B
   comparing with ssh://user@dummy/remote
   searching for changed bookmarks
      foo                       a28a9d1a809c
   $ hg book -f -r 0 foo
   $ hg pull -B foo
   pulling from ssh://user@dummy/remote
   no changes found
   updating bookmark foo
   $ hg book -d foo
   $ hg push -B foo
   pushing to ssh://user@dummy/remote
   searching for changes
   no changes found
   deleting remote bookmark foo
   [1]
 
 a bad, evil hook that prints to stdout
 
   $ cat <<EOF > $TESTTMP/badhook
   > import sys
   > sys.stdout.write("KABOOM\n")
   > EOF
 
   $ cat <<EOF > $TESTTMP/badpyhook.py
   > import sys
   > def hook(ui, repo, hooktype, **kwargs):
   >     sys.stdout.write("KABOOM IN PROCESS\n")
   > EOF
 
   $ cat <<EOF >> ../remote/.hg/hgrc
   > [hooks]
   > changegroup.stdout = $PYTHON $TESTTMP/badhook
   > changegroup.pystdout = python:$TESTTMP/badpyhook.py:hook
   > EOF
   $ echo r > r
   $ hg ci -A -m z r
 
 push should succeed even though it has an unexpected response
 
   $ hg push
   pushing to ssh://user@dummy/remote
   searching for changes
   remote has heads on branch 'default' that are not known locally: 6c0482d977a3
   remote: adding changesets
   remote: adding manifests
   remote: adding file changes
   remote: added 1 changesets with 1 changes to 1 files
   remote: KABOOM
   remote: KABOOM IN PROCESS
   $ hg -R ../remote heads
   changeset:   5:1383141674ec
   tag:         tip
   parent:      3:a28a9d1a809c
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     z
   
   changeset:   4:6c0482d977a3
   parent:      0:1160648e36ce
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   summary:     z
   
 
 clone bookmarks
 
   $ hg -R ../remote bookmark test
   $ hg -R ../remote bookmarks
    * test                      4:6c0482d977a3
   $ hg clone -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" ssh://user@dummy/remote local-bookmarks
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 6 changesets with 5 changes to 4 files (+1 heads)
   new changesets 1160648e36ce:1383141674ec
   updating to branch default
   3 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg -R local-bookmarks bookmarks
      test                      4:6c0482d977a3
 
 passwords in ssh urls are not supported
 (we use a glob here because different Python versions give different
 results here)
 
   $ hg push ssh://user:erroneouspwd@dummy/remote
   pushing to ssh://user:*@dummy/remote (glob)
   abort: password in URL not supported!
   [255]
 
   $ cd ..
 
 hide outer repo
   $ hg init
 
 Test remote paths with spaces (issue2983):
 
   $ hg init --ssh "\"$PYTHON\" \"$TESTDIR/dummyssh\"" "ssh://user@dummy/a repo"
   $ touch "$TESTTMP/a repo/test"
   $ hg -R 'a repo' commit -A -m "test"
   adding test
   $ hg -R 'a repo' tag tag
   $ hg id --ssh "\"$PYTHON\" \"$TESTDIR/dummyssh\"" "ssh://user@dummy/a repo"
   73649e48688a
 
   $ hg id --ssh "\"$PYTHON\" \"$TESTDIR/dummyssh\"" "ssh://user@dummy/a repo#noNoNO"
   abort: unknown revision 'noNoNO'!
   [255]
 
 Test (non-)escaping of remote paths with spaces when cloning (issue3145):
 
   $ hg clone --ssh "\"$PYTHON\" \"$TESTDIR/dummyssh\"" "ssh://user@dummy/a repo"
   destination directory: a repo
   abort: destination 'a repo' is not empty
   [255]
 
 Make sure hg is really paranoid in serve --stdio mode. It used to be
 possible to get a debugger REPL by specifying a repo named --debugger.
   $ hg -R --debugger serve --stdio
   abort: potentially unsafe serve --stdio invocation: ['-R', '--debugger', 'serve', '--stdio']
   [255]
   $ hg -R --config=ui.debugger=yes serve --stdio
   abort: potentially unsafe serve --stdio invocation: ['-R', '--config=ui.debugger=yes', 'serve', '--stdio']
   [255]
 Abbreviations of 'serve' also don't work, to avoid shenanigans.
   $ hg -R narf serv --stdio
   abort: potentially unsafe serve --stdio invocation: ['-R', 'narf', 'serv', '--stdio']
   [255]
 
 Test hg-ssh using a helper script that will restore PYTHONPATH (which might
 have been cleared by a hg.exe wrapper) and invoke hg-ssh with the right
 parameters:
 
   $ cat > ssh.sh << EOF
   > userhost="\$1"
   > SSH_ORIGINAL_COMMAND="\$2"
   > export SSH_ORIGINAL_COMMAND
   > PYTHONPATH="$PYTHONPATH"
   > export PYTHONPATH
   > "$PYTHON" "$TESTDIR/../contrib/hg-ssh" "$TESTTMP/a repo"
   > EOF
 
   $ hg id --ssh "sh ssh.sh" "ssh://user@dummy/a repo"
   73649e48688a
 
   $ hg id --ssh "sh ssh.sh" "ssh://user@dummy/a'repo"
   remote: Illegal repository "$TESTTMP/a'repo"
   abort: no suitable response from remote hg!
   [255]
 
   $ hg id --ssh "sh ssh.sh" --remotecmd hacking "ssh://user@dummy/a'repo"
   remote: Illegal command "hacking -R 'a'\''repo' serve --stdio"
   abort: no suitable response from remote hg!
   [255]
 
   $ SSH_ORIGINAL_COMMAND="'hg' -R 'a'repo' serve --stdio" $PYTHON "$TESTDIR/../contrib/hg-ssh"
   Illegal command "'hg' -R 'a'repo' serve --stdio": No closing quotation
   [255]
 
 Test hg-ssh in read-only mode:
 
   $ cat > ssh.sh << EOF
   > userhost="\$1"
   > SSH_ORIGINAL_COMMAND="\$2"
   > export SSH_ORIGINAL_COMMAND
   > PYTHONPATH="$PYTHONPATH"
   > export PYTHONPATH
   > "$PYTHON" "$TESTDIR/../contrib/hg-ssh" --read-only "$TESTTMP/remote"
   > EOF
 
   $ hg clone --ssh "sh ssh.sh" "ssh://user@dummy/$TESTTMP/remote" read-only-local
   requesting all changes
   adding changesets
   adding manifests
   adding file changes
   added 6 changesets with 5 changes to 4 files (+1 heads)
   new changesets 1160648e36ce:1383141674ec
   updating to branch default
   3 files updated, 0 files merged, 0 files removed, 0 files unresolved
 
   $ cd read-only-local
   $ echo "baz" > bar
   $ hg ci -A -m "unpushable commit" bar
   $ hg push --ssh "sh ../ssh.sh"
   pushing to ssh://user@dummy/*/remote (glob)
   searching for changes
   remote: Permission denied
   remote: pretxnopen.hg-ssh hook failed
   abort: push failed on remote
   [255]
 
   $ cd ..
 
 stderr from remote commands should be printed before stdout from local code (issue4336)
 
   $ hg clone remote stderr-ordering
   updating to branch default
   3 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ cd stderr-ordering
   $ cat >> localwrite.py << EOF
   > from mercurial import exchange, extensions
   > 
   > def wrappedpush(orig, repo, *args, **kwargs):
   >     res = orig(repo, *args, **kwargs)
   >     repo.ui.write('local stdout\n')
   >     return res
   > 
   > def extsetup(ui):
   >     extensions.wrapfunction(exchange, 'push', wrappedpush)
   > EOF
 
   $ cat >> .hg/hgrc << EOF
   > [paths]
   > default-push = ssh://user@dummy/remote
   > [ui]
   > ssh = "$PYTHON" "$TESTDIR/dummyssh"
   > [extensions]
   > localwrite = localwrite.py
   > EOF
 
   $ echo localwrite > foo
   $ hg commit -m 'testing localwrite'
   $ hg push
   pushing to ssh://user@dummy/remote
   searching for changes
   remote: adding changesets
   remote: adding manifests
   remote: adding file changes
   remote: added 1 changesets with 1 changes to 1 files
   remote: KABOOM
   remote: KABOOM IN PROCESS
   local stdout
 
 debug output
 
-  $ hg pull --debug ssh://user@dummy/remote
+  $ hg pull --debug ssh://user@dummy/remote --config devel.debug.peer-request=yes
   pulling from ssh://user@dummy/remote
   running .* ".*/dummyssh" ['"]user@dummy['"] ('|")hg -R remote serve --stdio('|") (re)
+  devel-peer-request: hello
   sending hello command
+  devel-peer-request: between
+  devel-peer-request:   pairs: 81 bytes
   sending between command
   remote: 384
   remote: capabilities: lookup changegroupsubset branchmap pushkey known getbundle unbundlehash batch streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS$ unbundle=HG10GZ,HG10BZ,HG10UN
   remote: 1
   query 1; heads
+  devel-peer-request: batch
+  devel-peer-request:   cmds: 141 bytes
   sending batch command
   searching for changes
   all remote heads known locally
   no changes found
+  devel-peer-request: getbundle
+  devel-peer-request:   bookmarks: 1 bytes
+  devel-peer-request:   bundlecaps: 233 bytes
+  devel-peer-request:   cg: 1 bytes
+  devel-peer-request:   common: 122 bytes
+  devel-peer-request:   heads: 122 bytes
+  devel-peer-request:   listkeys: 9 bytes
+  devel-peer-request:   phases: 1 bytes
   sending getbundle command
   bundle2-input-bundle: with-transaction
   bundle2-input-part: "bookmarks" supported
   bundle2-input-part: total payload size 26
   bundle2-input-part: "listkeys" (params: 1 mandatory) supported
   bundle2-input-part: total payload size 45
   bundle2-input-part: "phase-heads" supported
   bundle2-input-part: total payload size 72
   bundle2-input-bundle: 2 parts total
   checking for updated bookmarks
 
   $ cd ..
 
   $ cat dummylog
   Got arguments 1:user@dummy 2:hg -R nonexistent serve --stdio
   Got arguments 1:user@dummy 2:hg -R $TESTTMP/nonexistent serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R local-stream serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R doesnotexist serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R local serve --stdio
   Got arguments 1:user@dummy 2:hg -R $TESTTMP/local serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   changegroup-in-remote hook: HG_BUNDLE2=1 HG_HOOKNAME=changegroup HG_HOOKTYPE=changegroup HG_NODE=a28a9d1a809cab7d4e2fde4bee738a9ede948b60 HG_NODE_LAST=a28a9d1a809cab7d4e2fde4bee738a9ede948b60 HG_SOURCE=serve HG_TXNID=TXN:$ID$ HG_URL=remote:ssh:$LOCALIP
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   changegroup-in-remote hook: HG_BUNDLE2=1 HG_HOOKNAME=changegroup HG_HOOKTYPE=changegroup HG_NODE=1383141674ec756a6056f6a9097618482fe0f4a6 HG_NODE_LAST=1383141674ec756a6056f6a9097618482fe0f4a6 HG_SOURCE=serve HG_TXNID=TXN:$ID$ HG_URL=remote:ssh:$LOCALIP
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   Got arguments 1:user@dummy 2:hg init 'a repo'
   Got arguments 1:user@dummy 2:hg -R 'a repo' serve --stdio
   Got arguments 1:user@dummy 2:hg -R 'a repo' serve --stdio
   Got arguments 1:user@dummy 2:hg -R 'a repo' serve --stdio
   Got arguments 1:user@dummy 2:hg -R 'a repo' serve --stdio
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
   changegroup-in-remote hook: HG_BUNDLE2=1 HG_HOOKNAME=changegroup HG_HOOKTYPE=changegroup HG_NODE=65c38f4125f9602c8db4af56530cc221d93b8ef8 HG_NODE_LAST=65c38f4125f9602c8db4af56530cc221d93b8ef8 HG_SOURCE=serve HG_TXNID=TXN:$ID$ HG_URL=remote:ssh:$LOCALIP
   Got arguments 1:user@dummy 2:hg -R remote serve --stdio
 
 remote hook failure is attributed to remote
 
   $ cat > $TESTTMP/failhook << EOF
   > def hook(ui, repo, **kwargs):
   >     ui.write('hook failure!\n')
   >     ui.flush()
   >     return 1
   > EOF
 
   $ echo "pretxnchangegroup.fail = python:$TESTTMP/failhook:hook" >> remote/.hg/hgrc
 
   $ hg -q --config ui.ssh="\"$PYTHON\" $TESTDIR/dummyssh" clone ssh://user@dummy/remote hookout
   $ cd hookout
   $ touch hookfailure
   $ hg -q commit -A -m 'remote hook failure'
   $ hg --config ui.ssh="\"$PYTHON\" $TESTDIR/dummyssh" push
   pushing to ssh://user@dummy/remote
   searching for changes
   remote: adding changesets
   remote: adding manifests
   remote: adding file changes
   remote: added 1 changesets with 1 changes to 1 files
   remote: hook failure!
   remote: transaction abort!
   remote: rollback completed
   remote: pretxnchangegroup.fail hook failed
   abort: push failed on remote
   [255]
 
 abort during pull is properly reported as such
 
   $ echo morefoo >> ../remote/foo
   $ hg -R ../remote commit --message "more foo to be pulled"
   $ cat >> ../remote/.hg/hgrc << EOF
   > [extensions]
   > crash = ${TESTDIR}/crashgetbundler.py
   > EOF
   $ hg --config ui.ssh="\"$PYTHON\" $TESTDIR/dummyssh" pull
   pulling from ssh://user@dummy/remote
   searching for changes
   remote: abort: this is an exercise
   abort: pull failed on remote
   [255]
 
 abort with no error hint when there is a ssh problem when pulling
 
   $ hg pull ssh://brokenrepository -e "\"$PYTHON\" \"$TESTDIR/dummyssh\""
   pulling from ssh://brokenrepository/
   abort: no suitable response from remote hg!
   [255]
 
 abort with configured error hint when there is a ssh problem when pulling
 
   $ hg pull ssh://brokenrepository -e "\"$PYTHON\" \"$TESTDIR/dummyssh\"" \
   > --config ui.ssherrorhint="Please see http://company/internalwiki/ssh.html"
   pulling from ssh://brokenrepository/
   abort: no suitable response from remote hg!
   (Please see http://company/internalwiki/ssh.html)
   [255]
 
 test that custom environment is passed down to ssh executable
   $ cat >>dumpenv <<EOF
   > #! /bin/sh
   > echo \$VAR >&2
   > EOF
   $ chmod +x dumpenv
   $ hg pull ssh://something --config ui.ssh="sh dumpenv"
   pulling from ssh://something/
   remote: 
   abort: no suitable response from remote hg!
   [255]
   $ hg pull ssh://something --config ui.ssh="sh dumpenv" --config sshenv.VAR=17
   pulling from ssh://something/
   remote: 17
   abort: no suitable response from remote hg!
   [255]