commandserver: turn server debug messages into logs

They were ui.debug() just because commandserver.log() was noop if no client
connected.

mercurial/chgserver.py

@@ -1,636 +1,637
 # chgserver.py - command server extension for cHg
 #
 # Copyright 2011 Yuya Nishihara <[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.
 
 """command server extension for cHg
 
 'S' channel (read/write)
     propagate ui.system() request to client
 
 'attachio' command
     attach client's stdio passed by sendmsg()
 
 'chdir' command
     change current directory
 
 'setenv' command
     replace os.environ completely
 
 'setumask' command (DEPRECATED)
 'setumask2' command
     set umask
 
 'validate' command
     reload the config and check if the server is up to date
 
 Config
 ------
 
 ::
 
   [chgserver]
   # how long (in seconds) should an idle chg server exit
   idletimeout = 3600
 
   # whether to skip config or env change checks
   skiphash = False
 """
 
 from __future__ import absolute_import
 
 import hashlib
 import inspect
 import os
 import re
 import socket
 import stat
 import struct
 import time
 
 from .i18n import _
 
 from . import (
     commandserver,
     encoding,
     error,
     extensions,
     node,
     pycompat,
     util,
 )
 
 from .utils import (
     procutil,
 )
 
 def _hashlist(items):
     """return sha1 hexdigest for a list"""
     return node.hex(hashlib.sha1(str(items)).digest())
 
 # sensitive config sections affecting confighash
 _configsections = [
     'alias',  # affects global state commands.table
     'eol',    # uses setconfig('eol', ...)
     'extdiff',  # uisetup will register new commands
     'extensions',
 ]
 
 _configsectionitems = [
     ('commands', 'show.aliasprefix'), # show.py reads it in extsetup
 ]
 
 # sensitive environment variables affecting confighash
 _envre = re.compile(r'''\A(?:
                     CHGHG
                     |HG(?:DEMANDIMPORT|EMITWARNINGS|MODULEPOLICY|PROF|RCPATH)?
                     |HG(?:ENCODING|PLAIN).*
                     |LANG(?:UAGE)?
                     |LC_.*
                     |LD_.*
                     |PATH
                     |PYTHON.*
                     |TERM(?:INFO)?
                     |TZ
                     )\Z''', re.X)
 
 def _confighash(ui):
     """return a quick hash for detecting config/env changes
 
     confighash is the hash of sensitive config items and environment variables.
 
     for chgserver, it is designed that once confighash changes, the server is
     not qualified to serve its client and should redirect the client to a new
     server. different from mtimehash, confighash change will not mark the
     server outdated and exit since the user can have different configs at the
     same time.
     """
     sectionitems = []
     for section in _configsections:
         sectionitems.append(ui.configitems(section))
     for section, item in _configsectionitems:
         sectionitems.append(ui.config(section, item))
     sectionhash = _hashlist(sectionitems)
     # If $CHGHG is set, the change to $HG should not trigger a new chg server
     if 'CHGHG' in encoding.environ:
         ignored = {'HG'}
     else:
         ignored = set()
     envitems = [(k, v) for k, v in encoding.environ.iteritems()
                 if _envre.match(k) and k not in ignored]
     envhash = _hashlist(sorted(envitems))
     return sectionhash[:6] + envhash[:6]
 
 def _getmtimepaths(ui):
     """get a list of paths that should be checked to detect change
 
     The list will include:
     - extensions (will not cover all files for complex extensions)
     - mercurial/__version__.py
     - python binary
     """
     modules = [m for n, m in extensions.extensions(ui)]
     try:
         from . import __version__
         modules.append(__version__)
     except ImportError:
         pass
     files = [pycompat.sysexecutable]
     for m in modules:
         try:
             files.append(inspect.getabsfile(m))
         except TypeError:
             pass
     return sorted(set(files))
 
 def _mtimehash(paths):
     """return a quick hash for detecting file changes
 
     mtimehash calls stat on given paths and calculate a hash based on size and
     mtime of each file. mtimehash does not read file content because reading is
     expensive. therefore it's not 100% reliable for detecting content changes.
     it's possible to return different hashes for same file contents.
     it's also possible to return a same hash for different file contents for
     some carefully crafted situation.
 
     for chgserver, it is designed that once mtimehash changes, the server is
     considered outdated immediately and should no longer provide service.
 
     mtimehash is not included in confighash because we only know the paths of
     extensions after importing them (there is imp.find_module but that faces
     race conditions). We need to calculate confighash without importing.
     """
     def trystat(path):
         try:
             st = os.stat(path)
             return (st[stat.ST_MTIME], st.st_size)
         except OSError:
             # could be ENOENT, EPERM etc. not fatal in any case
             pass
     return _hashlist(map(trystat, paths))[:12]
 
 class hashstate(object):
     """a structure storing confighash, mtimehash, paths used for mtimehash"""
     def __init__(self, confighash, mtimehash, mtimepaths):
         self.confighash = confighash
         self.mtimehash = mtimehash
         self.mtimepaths = mtimepaths
 
     @staticmethod
     def fromui(ui, mtimepaths=None):
         if mtimepaths is None:
             mtimepaths = _getmtimepaths(ui)
         confighash = _confighash(ui)
         mtimehash = _mtimehash(mtimepaths)
         ui.log('cmdserver', 'confighash = %s mtimehash = %s\n',
                confighash, mtimehash)
         return hashstate(confighash, mtimehash, mtimepaths)
 
 def _newchgui(srcui, csystem, attachio):
     class chgui(srcui.__class__):
         def __init__(self, src=None):
             super(chgui, self).__init__(src)
             if src:
                 self._csystem = getattr(src, '_csystem', csystem)
             else:
                 self._csystem = csystem
 
         def _runsystem(self, cmd, environ, cwd, out):
             # fallback to the original system method if
             #  a. the output stream is not stdout (e.g. stderr, cStringIO),
             #  b. or stdout is redirected by protectstdio(),
             # because the chg client is not aware of these situations and
             # will behave differently (i.e. write to stdout).
             if (out is not self.fout
                 or not util.safehasattr(self.fout, 'fileno')
                 or self.fout.fileno() != procutil.stdout.fileno()
                 or self._finoutredirected):
                 return procutil.system(cmd, environ=environ, cwd=cwd, out=out)
             self.flush()
             return self._csystem(cmd, procutil.shellenviron(environ), cwd)
 
         def _runpager(self, cmd, env=None):
             self._csystem(cmd, procutil.shellenviron(env), type='pager',
                           cmdtable={'attachio': attachio})
             return True
 
     return chgui(srcui)
 
 def _loadnewui(srcui, args, cdebug):
     from . import dispatch  # avoid cycle
 
     newui = srcui.__class__.load()
     for a in ['fin', 'fout', 'ferr', 'environ']:
         setattr(newui, a, getattr(srcui, a))
     if util.safehasattr(srcui, '_csystem'):
         newui._csystem = srcui._csystem
 
     # command line args
     options = dispatch._earlyparseopts(newui, args)
     dispatch._parseconfig(newui, options['config'])
 
     # stolen from tortoisehg.util.copydynamicconfig()
     for section, name, value in srcui.walkconfig():
         source = srcui.configsource(section, name)
         if ':' in source or source == '--config' or source.startswith('$'):
             # path:line or command line, or environ
             continue
         newui.setconfig(section, name, value, source)
 
     # load wd and repo config, copied from dispatch.py
     cwd = options['cwd']
     cwd = cwd and os.path.realpath(cwd) or None
     rpath = options['repository']
     path, newlui = dispatch._getlocal(newui, rpath, wd=cwd)
 
     extensions.populateui(newui)
     commandserver.setuplogging(newui, fp=cdebug)
     if newui is not newlui:
         extensions.populateui(newlui)
         commandserver.setuplogging(newlui, fp=cdebug)
 
     return (newui, newlui)
 
 class channeledsystem(object):
     """Propagate ui.system() request in the following format:
 
     payload length (unsigned int),
     type, '\0',
     cmd, '\0',
     cwd, '\0',
     envkey, '=', val, '\0',
     ...
     envkey, '=', val
 
     if type == 'system', waits for:
 
     exitcode length (unsigned int),
     exitcode (int)
 
     if type == 'pager', repetitively waits for a command name ending with '\n'
     and executes it defined by cmdtable, or exits the loop if the command name
     is empty.
     """
     def __init__(self, in_, out, channel):
         self.in_ = in_
         self.out = out
         self.channel = channel
 
     def __call__(self, cmd, environ, cwd=None, type='system', cmdtable=None):
         args = [type, procutil.quotecommand(cmd), os.path.abspath(cwd or '.')]
         args.extend('%s=%s' % (k, v) for k, v in environ.iteritems())
         data = '\0'.join(args)
         self.out.write(struct.pack('>cI', self.channel, len(data)))
         self.out.write(data)
         self.out.flush()
 
         if type == 'system':
             length = self.in_.read(4)
             length, = struct.unpack('>I', length)
             if length != 4:
                 raise error.Abort(_('invalid response'))
             rc, = struct.unpack('>i', self.in_.read(4))
             return rc
         elif type == 'pager':
             while True:
                 cmd = self.in_.readline()[:-1]
                 if not cmd:
                     break
                 if cmdtable and cmd in cmdtable:
                     cmdtable[cmd]()
                 else:
                     raise error.Abort(_('unexpected command: %s') % cmd)
         else:
             raise error.ProgrammingError('invalid S channel type: %s' % type)
 
 _iochannels = [
     # server.ch, ui.fp, mode
     ('cin', 'fin', r'rb'),
     ('cout', 'fout', r'wb'),
     ('cerr', 'ferr', r'wb'),
 ]
 
 class chgcmdserver(commandserver.server):
     def __init__(self, ui, repo, fin, fout, sock, hashstate, baseaddress):
         super(chgcmdserver, self).__init__(
             _newchgui(ui, channeledsystem(fin, fout, 'S'), self.attachio),
             repo, fin, fout)
         self.clientsock = sock
         self._ioattached = False
         self._oldios = []  # original (self.ch, ui.fp, fd) before "attachio"
         self.hashstate = hashstate
         self.baseaddress = baseaddress
         if hashstate is not None:
             self.capabilities = self.capabilities.copy()
             self.capabilities['validate'] = chgcmdserver.validate
 
     def cleanup(self):
         super(chgcmdserver, self).cleanup()
         # dispatch._runcatch() does not flush outputs if exception is not
         # handled by dispatch._dispatch()
         self.ui.flush()
         self._restoreio()
         self._ioattached = False
 
     def attachio(self):
         """Attach to client's stdio passed via unix domain socket; all
         channels except cresult will no longer be used
         """
         # tell client to sendmsg() with 1-byte payload, which makes it
         # distinctive from "attachio\n" command consumed by client.read()
         self.clientsock.sendall(struct.pack('>cI', 'I', 1))
         clientfds = util.recvfds(self.clientsock.fileno())
         self.ui.log('chgserver', 'received fds: %r\n', clientfds)
 
         ui = self.ui
         ui.flush()
         self._saveio()
         for fd, (cn, fn, mode) in zip(clientfds, _iochannels):
             assert fd > 0
             fp = getattr(ui, fn)
             os.dup2(fd, fp.fileno())
             os.close(fd)
             if self._ioattached:
                 continue
             # reset buffering mode when client is first attached. as we want
             # to see output immediately on pager, the mode stays unchanged
             # when client re-attached. ferr is unchanged because it should
             # be unbuffered no matter if it is a tty or not.
             if fn == 'ferr':
                 newfp = fp
             else:
                 # make it line buffered explicitly because the default is
                 # decided on first write(), where fout could be a pager.
                 if fp.isatty():
                     bufsize = 1  # line buffered
                 else:
                     bufsize = -1  # system default
                 newfp = os.fdopen(fp.fileno(), mode, bufsize)
                 setattr(ui, fn, newfp)
             setattr(self, cn, newfp)
 
         self._ioattached = True
         self.cresult.write(struct.pack('>i', len(clientfds)))
 
     def _saveio(self):
         if self._oldios:
             return
         ui = self.ui
         for cn, fn, _mode in _iochannels:
             ch = getattr(self, cn)
             fp = getattr(ui, fn)
             fd = os.dup(fp.fileno())
             self._oldios.append((ch, fp, fd))
 
     def _restoreio(self):
         ui = self.ui
         for (ch, fp, fd), (cn, fn, _mode) in zip(self._oldios, _iochannels):
             newfp = getattr(ui, fn)
             # close newfp while it's associated with client; otherwise it
             # would be closed when newfp is deleted
             if newfp is not fp:
                 newfp.close()
             # restore original fd: fp is open again
             os.dup2(fd, fp.fileno())
             os.close(fd)
             setattr(self, cn, ch)
             setattr(ui, fn, fp)
         del self._oldios[:]
 
     def validate(self):
         """Reload the config and check if the server is up to date
 
         Read a list of '\0' separated arguments.
         Write a non-empty list of '\0' separated instruction strings or '\0'
         if the list is empty.
         An instruction string could be either:
             - "unlink $path", the client should unlink the path to stop the
               outdated server.
             - "redirect $path", the client should attempt to connect to $path
               first. If it does not work, start a new server. It implies
               "reconnect".
             - "exit $n", the client should exit directly with code n.
               This may happen if we cannot parse the config.
             - "reconnect", the client should close the connection and
               reconnect.
         If neither "reconnect" nor "redirect" is included in the instruction
         list, the client can continue with this server after completing all
         the instructions.
         """
         from . import dispatch  # avoid cycle
 
         args = self._readlist()
         try:
             self.ui, lui = _loadnewui(self.ui, args, self.cdebug)
         except error.ParseError as inst:
             dispatch._formatparse(self.ui.warn, inst)
             self.ui.flush()
             self.cresult.write('exit 255')
             return
         except error.Abort as inst:
             self.ui.error(_("abort: %s\n") % inst)
             if inst.hint:
                 self.ui.error(_("(%s)\n") % inst.hint)
             self.ui.flush()
             self.cresult.write('exit 255')
             return
         newhash = hashstate.fromui(lui, self.hashstate.mtimepaths)
         insts = []
         if newhash.mtimehash != self.hashstate.mtimehash:
             addr = _hashaddress(self.baseaddress, self.hashstate.confighash)
             insts.append('unlink %s' % addr)
             # mtimehash is empty if one or more extensions fail to load.
             # to be compatible with hg, still serve the client this time.
             if self.hashstate.mtimehash:
                 insts.append('reconnect')
         if newhash.confighash != self.hashstate.confighash:
             addr = _hashaddress(self.baseaddress, newhash.confighash)
             insts.append('redirect %s' % addr)
         self.ui.log('chgserver', 'validate: %s\n', insts)
         self.cresult.write('\0'.join(insts) or '\0')
 
     def chdir(self):
         """Change current directory
 
         Note that the behavior of --cwd option is bit different from this.
         It does not affect --config parameter.
         """
         path = self._readstr()
         if not path:
             return
         self.ui.log('chgserver', 'chdir to %r\n', path)
         os.chdir(path)
 
     def setumask(self):
         """Change umask (DEPRECATED)"""
         # BUG: this does not follow the message frame structure, but kept for
         # backward compatibility with old chg clients for some time
         self._setumask(self._read(4))
 
     def setumask2(self):
         """Change umask"""
         data = self._readstr()
         if len(data) != 4:
             raise ValueError('invalid mask length in setumask2 request')
         self._setumask(data)
 
     def _setumask(self, data):
         mask = struct.unpack('>I', data)[0]
         self.ui.log('chgserver', 'setumask %r\n', mask)
         os.umask(mask)
 
     def runcommand(self):
         # pager may be attached within the runcommand session, which should
         # be detached at the end of the session. otherwise the pager wouldn't
         # receive EOF.
         globaloldios = self._oldios
         self._oldios = []
         try:
             return super(chgcmdserver, self).runcommand()
         finally:
             self._restoreio()
             self._oldios = globaloldios
 
     def setenv(self):
         """Clear and update os.environ
 
         Note that not all variables can make an effect on the running process.
         """
         l = self._readlist()
         try:
             newenv = dict(s.split('=', 1) for s in l)
         except ValueError:
             raise ValueError('unexpected value in setenv request')
         self.ui.log('chgserver', 'setenv: %r\n', sorted(newenv.keys()))
         encoding.environ.clear()
         encoding.environ.update(newenv)
 
     capabilities = commandserver.server.capabilities.copy()
     capabilities.update({'attachio': attachio,
                          'chdir': chdir,
                          'runcommand': runcommand,
                          'setenv': setenv,
                          'setumask': setumask,
                          'setumask2': setumask2})
 
     if util.safehasattr(procutil, 'setprocname'):
         def setprocname(self):
             """Change process title"""
             name = self._readstr()
             self.ui.log('chgserver', 'setprocname: %r\n', name)
             procutil.setprocname(name)
         capabilities['setprocname'] = setprocname
 
 def _tempaddress(address):
     return '%s.%d.tmp' % (address, os.getpid())
 
 def _hashaddress(address, hashstr):
     # if the basename of address contains '.', use only the left part. this
     # makes it possible for the client to pass 'server.tmp$PID' and follow by
     # an atomic rename to avoid locking when spawning new servers.
     dirname, basename = os.path.split(address)
     basename = basename.split('.', 1)[0]
     return '%s-%s' % (os.path.join(dirname, basename), hashstr)
 
 class chgunixservicehandler(object):
     """Set of operations for chg services"""
 
     pollinterval = 1  # [sec]
 
     def __init__(self, ui):
         self.ui = ui
         self._idletimeout = ui.configint('chgserver', 'idletimeout')
         self._lastactive = time.time()
 
     def bindsocket(self, sock, address):
         self._inithashstate(address)
         self._checkextensions()
         self._bind(sock)
         self._createsymlink()
         # no "listening at" message should be printed to simulate hg behavior
 
     def _inithashstate(self, address):
         self._baseaddress = address
         if self.ui.configbool('chgserver', 'skiphash'):
             self._hashstate = None
             self._realaddress = address
             return
         self._hashstate = hashstate.fromui(self.ui)
         self._realaddress = _hashaddress(address, self._hashstate.confighash)
 
     def _checkextensions(self):
         if not self._hashstate:
             return
         if extensions.notloaded():
             # one or more extensions failed to load. mtimehash becomes
             # meaningless because we do not know the paths of those extensions.
             # set mtimehash to an illegal hash value to invalidate the server.
             self._hashstate.mtimehash = ''
 
     def _bind(self, sock):
         # use a unique temp address so we can stat the file and do ownership
         # check later
         tempaddress = _tempaddress(self._realaddress)
         util.bindunixsocket(sock, tempaddress)
         self._socketstat = os.stat(tempaddress)
         sock.listen(socket.SOMAXCONN)
         # rename will replace the old socket file if exists atomically. the
         # old server will detect ownership change and exit.
         util.rename(tempaddress, self._realaddress)
 
     def _createsymlink(self):
         if self._baseaddress == self._realaddress:
             return
         tempaddress = _tempaddress(self._baseaddress)
         os.symlink(os.path.basename(self._realaddress), tempaddress)
         util.rename(tempaddress, self._baseaddress)
 
     def _issocketowner(self):
         try:
             st = os.stat(self._realaddress)
             return (st.st_ino == self._socketstat.st_ino and
                     st[stat.ST_MTIME] == self._socketstat[stat.ST_MTIME])
         except OSError:
             return False
 
     def unlinksocket(self, address):
         if not self._issocketowner():
             return
         # it is possible to have a race condition here that we may
         # remove another server's socket file. but that's okay
         # since that server will detect and exit automatically and
         # the client will start a new server on demand.
         util.tryunlink(self._realaddress)
 
     def shouldexit(self):
         if not self._issocketowner():
-            self.ui.debug('%s is not owned, exiting.\n' % self._realaddress)
+            self.ui.log(b'chgserver', b'%s is not owned, exiting.\n',
+                        self._realaddress)
             return True
         if time.time() - self._lastactive > self._idletimeout:
-            self.ui.debug('being idle too long. exiting.\n')
+            self.ui.log(b'chgserver', b'being idle too long. exiting.\n')
             return True
         return False
 
     def newconnection(self):
         self._lastactive = time.time()
 
     def createcmdserver(self, repo, conn, fin, fout):
         return chgcmdserver(self.ui, repo, fin, fout, conn,
                             self._hashstate, self._baseaddress)
 
 def chgunixservice(ui, repo, opts):
     # CHGINTERNALMARK is set by chg client. It is an indication of things are
     # started by chg so other code can do things accordingly, like disabling
     # demandimport or detecting chg client started by chg client. When executed
     # here, CHGINTERNALMARK is no longer useful and hence dropped to make
     # environ cleaner.
     if 'CHGINTERNALMARK' in encoding.environ:
         del encoding.environ['CHGINTERNALMARK']
 
     if repo:
         # one chgserver can serve multiple repos. drop repo information
         ui.setconfig('bundle', 'mainreporoot', '', 'repo')
     h = chgunixservicehandler(ui)
     return commandserver.unixforkingservice(ui, repo=None, opts=opts, handler=h)

mercurial/commandserver.py

@@ -1,623 +1,624
 # commandserver.py - communicate with Mercurial's API over a pipe
 #
 #  Copyright 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 errno
 import gc
 import os
 import random
 import signal
 import socket
 import struct
 import traceback
 
 try:
     import selectors
     selectors.BaseSelector
 except ImportError:
     from .thirdparty import selectors2 as selectors
 
 from .i18n import _
 from . import (
     encoding,
     error,
     loggingutil,
     pycompat,
     util,
     vfs as vfsmod,
 )
 from .utils import (
     cborutil,
     procutil,
 )
 
 class channeledoutput(object):
     """
     Write data to out in the following format:
 
     data length (unsigned int),
     data
     """
     def __init__(self, out, channel):
         self.out = out
         self.channel = channel
 
     @property
     def name(self):
         return '<%c-channel>' % self.channel
 
     def write(self, data):
         if not data:
             return
         # single write() to guarantee the same atomicity as the underlying file
         self.out.write(struct.pack('>cI', self.channel, len(data)) + data)
         self.out.flush()
 
     def __getattr__(self, attr):
         if attr in (r'isatty', r'fileno', r'tell', r'seek'):
             raise AttributeError(attr)
         return getattr(self.out, attr)
 
 class channeledmessage(object):
     """
     Write encoded message and metadata to out in the following format:
 
     data length (unsigned int),
     encoded message and metadata, as a flat key-value dict.
 
     Each message should have 'type' attribute. Messages of unknown type
     should be ignored.
     """
 
     # teach ui that write() can take **opts
     structured = True
 
     def __init__(self, out, channel, encodename, encodefn):
         self._cout = channeledoutput(out, channel)
         self.encoding = encodename
         self._encodefn = encodefn
 
     def write(self, data, **opts):
         opts = pycompat.byteskwargs(opts)
         if data is not None:
             opts[b'data'] = data
         self._cout.write(self._encodefn(opts))
 
     def __getattr__(self, attr):
         return getattr(self._cout, attr)
 
 class channeledinput(object):
     """
     Read data from in_.
 
     Requests for input are written to out in the following format:
     channel identifier - 'I' for plain input, 'L' line based (1 byte)
     how many bytes to send at most (unsigned int),
 
     The client replies with:
     data length (unsigned int), 0 meaning EOF
     data
     """
 
     maxchunksize = 4 * 1024
 
     def __init__(self, in_, out, channel):
         self.in_ = in_
         self.out = out
         self.channel = channel
 
     @property
     def name(self):
         return '<%c-channel>' % self.channel
 
     def read(self, size=-1):
         if size < 0:
             # if we need to consume all the clients input, ask for 4k chunks
             # so the pipe doesn't fill up risking a deadlock
             size = self.maxchunksize
             s = self._read(size, self.channel)
             buf = s
             while s:
                 s = self._read(size, self.channel)
                 buf += s
 
             return buf
         else:
             return self._read(size, self.channel)
 
     def _read(self, size, channel):
         if not size:
             return ''
         assert size > 0
 
         # tell the client we need at most size bytes
         self.out.write(struct.pack('>cI', channel, size))
         self.out.flush()
 
         length = self.in_.read(4)
         length = struct.unpack('>I', length)[0]
         if not length:
             return ''
         else:
             return self.in_.read(length)
 
     def readline(self, size=-1):
         if size < 0:
             size = self.maxchunksize
             s = self._read(size, 'L')
             buf = s
             # keep asking for more until there's either no more or
             # we got a full line
             while s and s[-1] != '\n':
                 s = self._read(size, 'L')
                 buf += s
 
             return buf
         else:
             return self._read(size, 'L')
 
     def __iter__(self):
         return self
 
     def next(self):
         l = self.readline()
         if not l:
             raise StopIteration
         return l
 
     __next__ = next
 
     def __getattr__(self, attr):
         if attr in (r'isatty', r'fileno', r'tell', r'seek'):
             raise AttributeError(attr)
         return getattr(self.in_, attr)
 
 _messageencoders = {
     b'cbor': lambda v: b''.join(cborutil.streamencode(v)),
 }
 
 def _selectmessageencoder(ui):
     # experimental config: cmdserver.message-encodings
     encnames = ui.configlist(b'cmdserver', b'message-encodings')
     for n in encnames:
         f = _messageencoders.get(n)
         if f:
             return n, f
     raise error.Abort(b'no supported message encodings: %s'
                       % b' '.join(encnames))
 
 class server(object):
     """
     Listens for commands on fin, runs them and writes the output on a channel
     based stream to fout.
     """
     def __init__(self, ui, repo, fin, fout):
         self.cwd = encoding.getcwd()
 
         if repo:
             # the ui here is really the repo ui so take its baseui so we don't
             # end up with its local configuration
             self.ui = repo.baseui
             self.repo = repo
             self.repoui = repo.ui
         else:
             self.ui = ui
             self.repo = self.repoui = None
 
         self.cdebug = channeledoutput(fout, 'd')
         self.cerr = channeledoutput(fout, 'e')
         self.cout = channeledoutput(fout, 'o')
         self.cin = channeledinput(fin, fout, 'I')
         self.cresult = channeledoutput(fout, 'r')
 
         if self.ui.config(b'cmdserver', b'log') == b'-':
             # switch log stream of server's ui to the 'd' (debug) channel
             # (don't touch repo.ui as its lifetime is longer than the server)
             self.ui = self.ui.copy()
             setuplogging(self.ui, repo=None, fp=self.cdebug)
 
         # TODO: add this to help/config.txt when stabilized
         # ``channel``
         #   Use separate channel for structured output. (Command-server only)
         self.cmsg = None
         if ui.config(b'ui', b'message-output') == b'channel':
             encname, encfn = _selectmessageencoder(ui)
             self.cmsg = channeledmessage(fout, b'm', encname, encfn)
 
         self.client = fin
 
     def cleanup(self):
         """release and restore resources taken during server session"""
 
     def _read(self, size):
         if not size:
             return ''
 
         data = self.client.read(size)
 
         # is the other end closed?
         if not data:
             raise EOFError
 
         return data
 
     def _readstr(self):
         """read a string from the channel
 
         format:
         data length (uint32), data
         """
         length = struct.unpack('>I', self._read(4))[0]
         if not length:
             return ''
         return self._read(length)
 
     def _readlist(self):
         """read a list of NULL separated strings from the channel"""
         s = self._readstr()
         if s:
             return s.split('\0')
         else:
             return []
 
     def runcommand(self):
         """ reads a list of \0 terminated arguments, executes
         and writes the return code to the result channel """
         from . import dispatch  # avoid cycle
 
         args = self._readlist()
 
         # copy the uis so changes (e.g. --config or --verbose) don't
         # persist between requests
         copiedui = self.ui.copy()
         uis = [copiedui]
         if self.repo:
             self.repo.baseui = copiedui
             # clone ui without using ui.copy because this is protected
             repoui = self.repoui.__class__(self.repoui)
             repoui.copy = copiedui.copy # redo copy protection
             uis.append(repoui)
             self.repo.ui = self.repo.dirstate._ui = repoui
             self.repo.invalidateall()
 
         for ui in uis:
             ui.resetstate()
             # any kind of interaction must use server channels, but chg may
             # replace channels by fully functional tty files. so nontty is
             # enforced only if cin is a channel.
             if not util.safehasattr(self.cin, 'fileno'):
                 ui.setconfig('ui', 'nontty', 'true', 'commandserver')
 
         req = dispatch.request(args[:], copiedui, self.repo, self.cin,
                                self.cout, self.cerr, self.cmsg)
 
         try:
             ret = dispatch.dispatch(req) & 255
             self.cresult.write(struct.pack('>i', int(ret)))
         finally:
             # restore old cwd
             if '--cwd' in args:
                 os.chdir(self.cwd)
 
     def getencoding(self):
         """ writes the current encoding to the result channel """
         self.cresult.write(encoding.encoding)
 
     def serveone(self):
         cmd = self.client.readline()[:-1]
         if cmd:
             handler = self.capabilities.get(cmd)
             if handler:
                 handler(self)
             else:
                 # clients are expected to check what commands are supported by
                 # looking at the servers capabilities
                 raise error.Abort(_('unknown command %s') % cmd)
 
         return cmd != ''
 
     capabilities = {'runcommand': runcommand,
                     'getencoding': getencoding}
 
     def serve(self):
         hellomsg = 'capabilities: ' + ' '.join(sorted(self.capabilities))
         hellomsg += '\n'
         hellomsg += 'encoding: ' + encoding.encoding
         hellomsg += '\n'
         if self.cmsg:
             hellomsg += 'message-encoding: %s\n' % self.cmsg.encoding
         hellomsg += 'pid: %d' % procutil.getpid()
         if util.safehasattr(os, 'getpgid'):
             hellomsg += '\n'
             hellomsg += 'pgid: %d' % os.getpgid(0)
 
         # write the hello msg in -one- chunk
         self.cout.write(hellomsg)
 
         try:
             while self.serveone():
                 pass
         except EOFError:
             # we'll get here if the client disconnected while we were reading
             # its request
             return 1
 
         return 0
 
 def setuplogging(ui, repo=None, fp=None):
     """Set up server logging facility
 
     If cmdserver.log is '-', log messages will be sent to the given fp.
     It should be the 'd' channel while a client is connected, and otherwise
     is the stderr of the server process.
     """
     # developer config: cmdserver.log
     logpath = ui.config(b'cmdserver', b'log')
     if not logpath:
         return
     # developer config: cmdserver.track-log
     tracked = set(ui.configlist(b'cmdserver', b'track-log'))
 
     if logpath == b'-' and fp:
         logger = loggingutil.fileobjectlogger(fp, tracked)
     elif logpath == b'-':
         logger = loggingutil.fileobjectlogger(ui.ferr, tracked)
     else:
         logpath = os.path.abspath(util.expandpath(logpath))
         # developer config: cmdserver.max-log-files
         maxfiles = ui.configint(b'cmdserver', b'max-log-files')
         # developer config: cmdserver.max-log-size
         maxsize = ui.configbytes(b'cmdserver', b'max-log-size')
         vfs = vfsmod.vfs(os.path.dirname(logpath))
         logger = loggingutil.filelogger(vfs, os.path.basename(logpath), tracked,
                                         maxfiles=maxfiles, maxsize=maxsize)
 
     targetuis = {ui}
     if repo:
         targetuis.add(repo.baseui)
         targetuis.add(repo.ui)
     for u in targetuis:
         u.setlogger(b'cmdserver', logger)
 
 class pipeservice(object):
     def __init__(self, ui, repo, opts):
         self.ui = ui
         self.repo = repo
 
     def init(self):
         pass
 
     def run(self):
         ui = self.ui
         # redirect stdio to null device so that broken extensions or in-process
         # hooks will never cause corruption of channel protocol.
         with procutil.protectedstdio(ui.fin, ui.fout) as (fin, fout):
             sv = server(ui, self.repo, fin, fout)
             try:
                 return sv.serve()
             finally:
                 sv.cleanup()
 
 def _initworkerprocess():
     # use a different process group from the master process, in order to:
     # 1. make the current process group no longer "orphaned" (because the
     #    parent of this process is in a different process group while
     #    remains in a same session)
     #    according to POSIX 2.2.2.52, orphaned process group will ignore
     #    terminal-generated stop signals like SIGTSTP (Ctrl+Z), which will
     #    cause trouble for things like ncurses.
     # 2. the client can use kill(-pgid, sig) to simulate terminal-generated
     #    SIGINT (Ctrl+C) and process-exit-generated SIGHUP. our child
     #    processes like ssh will be killed properly, without affecting
     #    unrelated processes.
     os.setpgid(0, 0)
     # change random state otherwise forked request handlers would have a
     # same state inherited from parent.
     random.seed()
 
 def _serverequest(ui, repo, conn, createcmdserver):
     fin = conn.makefile(r'rb')
     fout = conn.makefile(r'wb')
     sv = None
     try:
         sv = createcmdserver(repo, conn, fin, fout)
         try:
             sv.serve()
         # handle exceptions that may be raised by command server. most of
         # known exceptions are caught by dispatch.
         except error.Abort as inst:
             ui.error(_('abort: %s\n') % inst)
         except IOError as inst:
             if inst.errno != errno.EPIPE:
                 raise
         except KeyboardInterrupt:
             pass
         finally:
             sv.cleanup()
     except: # re-raises
         # also write traceback to error channel. otherwise client cannot
         # see it because it is written to server's stderr by default.
         if sv:
             cerr = sv.cerr
         else:
             cerr = channeledoutput(fout, 'e')
         cerr.write(encoding.strtolocal(traceback.format_exc()))
         raise
     finally:
         fin.close()
         try:
             fout.close()  # implicit flush() may cause another EPIPE
         except IOError as inst:
             if inst.errno != errno.EPIPE:
                 raise
 
 class unixservicehandler(object):
     """Set of pluggable operations for unix-mode services
 
     Almost all methods except for createcmdserver() are called in the main
     process. You can't pass mutable resource back from createcmdserver().
     """
 
     pollinterval = None
 
     def __init__(self, ui):
         self.ui = ui
 
     def bindsocket(self, sock, address):
         util.bindunixsocket(sock, address)
         sock.listen(socket.SOMAXCONN)
         self.ui.status(_('listening at %s\n') % address)
         self.ui.flush()  # avoid buffering of status message
 
     def unlinksocket(self, address):
         os.unlink(address)
 
     def shouldexit(self):
         """True if server should shut down; checked per pollinterval"""
         return False
 
     def newconnection(self):
         """Called when main process notices new connection"""
 
     def createcmdserver(self, repo, conn, fin, fout):
         """Create new command server instance; called in the process that
         serves for the current connection"""
         return server(self.ui, repo, fin, fout)
 
 class unixforkingservice(object):
     """
     Listens on unix domain socket and forks server per connection
     """
 
     def __init__(self, ui, repo, opts, handler=None):
         self.ui = ui
         self.repo = repo
         self.address = opts['address']
         if not util.safehasattr(socket, 'AF_UNIX'):
             raise error.Abort(_('unsupported platform'))
         if not self.address:
             raise error.Abort(_('no socket path specified with --address'))
         self._servicehandler = handler or unixservicehandler(ui)
         self._sock = None
         self._oldsigchldhandler = None
         self._workerpids = set()  # updated by signal handler; do not iterate
         self._socketunlinked = None
 
     def init(self):
         self._sock = socket.socket(socket.AF_UNIX)
         self._servicehandler.bindsocket(self._sock, self.address)
         if util.safehasattr(procutil, 'unblocksignal'):
             procutil.unblocksignal(signal.SIGCHLD)
         o = signal.signal(signal.SIGCHLD, self._sigchldhandler)
         self._oldsigchldhandler = o
         self._socketunlinked = False
 
     def _unlinksocket(self):
         if not self._socketunlinked:
             self._servicehandler.unlinksocket(self.address)
             self._socketunlinked = True
 
     def _cleanup(self):
         signal.signal(signal.SIGCHLD, self._oldsigchldhandler)
         self._sock.close()
         self._unlinksocket()
         # don't kill child processes as they have active clients, just wait
         self._reapworkers(0)
 
     def run(self):
         try:
             self._mainloop()
         finally:
             self._cleanup()
 
     def _mainloop(self):
         exiting = False
         h = self._servicehandler
         selector = selectors.DefaultSelector()
         selector.register(self._sock, selectors.EVENT_READ)
         while True:
             if not exiting and h.shouldexit():
                 # clients can no longer connect() to the domain socket, so
                 # we stop queuing new requests.
                 # for requests that are queued (connect()-ed, but haven't been
                 # accept()-ed), handle them before exit. otherwise, clients
                 # waiting for recv() will receive ECONNRESET.
                 self._unlinksocket()
                 exiting = True
             try:
                 ready = selector.select(timeout=h.pollinterval)
             except OSError as inst:
                 # selectors2 raises ETIMEDOUT if timeout exceeded while
                 # handling signal interrupt. That's probably wrong, but
                 # we can easily get around it.
                 if inst.errno != errno.ETIMEDOUT:
                     raise
                 ready = []
             if not ready:
                 # only exit if we completed all queued requests
                 if exiting:
                     break
                 continue
             try:
                 conn, _addr = self._sock.accept()
             except socket.error as inst:
                 if inst.args[0] == errno.EINTR:
                     continue
                 raise
 
             pid = os.fork()
             if pid:
                 try:
-                    self.ui.debug('forked worker process (pid=%d)\n' % pid)
+                    self.ui.log(b'cmdserver',
+                                b'forked worker process (pid=%d)\n', pid)
                     self._workerpids.add(pid)
                     h.newconnection()
                 finally:
                     conn.close()  # release handle in parent process
             else:
                 try:
                     selector.close()
                     self._sock.close()
                     self._runworker(conn)
                     conn.close()
                     os._exit(0)
                 except:  # never return, hence no re-raises
                     try:
                         self.ui.traceback(force=True)
                     finally:
                         os._exit(255)
         selector.close()
 
     def _sigchldhandler(self, signal, frame):
         self._reapworkers(os.WNOHANG)
 
     def _reapworkers(self, options):
         while self._workerpids:
             try:
                 pid, _status = os.waitpid(-1, options)
             except OSError as inst:
                 if inst.errno == errno.EINTR:
                     continue
                 if inst.errno != errno.ECHILD:
                     raise
                 # no child processes at all (reaped by other waitpid()?)
                 self._workerpids.clear()
                 return
             if pid == 0:
                 # no waitable child processes
                 return
-            self.ui.debug('worker process exited (pid=%d)\n' % pid)
+            self.ui.log(b'cmdserver', b'worker process exited (pid=%d)\n', pid)
             self._workerpids.discard(pid)
 
     def _runworker(self, conn):
         signal.signal(signal.SIGCHLD, self._oldsigchldhandler)
         _initworkerprocess()
         h = self._servicehandler
         try:
             _serverequest(self.ui, self.repo, conn, h.createcmdserver)
         finally:
             gc.collect()  # trigger __del__ since worker process uses os._exit

tests/test-chg.t

@@ -1,242 +1,242
 #require chg
 
   $ mkdir log
   $ cat <<'EOF' >> $HGRCPATH
   > [cmdserver]
   > log = $TESTTMP/log/server.log
   > max-log-files = 1
   > max-log-size = 10 kB
   > EOF
   $ cp $HGRCPATH $HGRCPATH.orig
 
   $ filterlog () {
   >   sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!' \
   >       -e 's!\(setprocname\|received fds\|setenv\): .*!\1: ...!' \
   >       -e 's!\(confighash\|mtimehash\) = [0-9a-f]*!\1 = ...!g' \
   >       -e 's!\(pid\)=[0-9]*!\1=...!g' \
   >       -e 's!\(/server-\)[0-9a-f]*!\1...!g'
   > }
 
 init repo
 
   $ chg init foo
   $ cd foo
 
 ill-formed config
 
   $ chg status
   $ echo '=brokenconfig' >> $HGRCPATH
   $ chg status
   hg: parse error at * (glob)
   [255]
 
   $ cp $HGRCPATH.orig $HGRCPATH
 
 long socket path
 
   $ sockpath=$TESTTMP/this/path/should/be/longer/than/one-hundred-and-seven/characters/where/107/is/the/typical/size/limit/of/unix-domain-socket
   $ mkdir -p $sockpath
   $ bakchgsockname=$CHGSOCKNAME
   $ CHGSOCKNAME=$sockpath/server
   $ export CHGSOCKNAME
   $ chg root
   $TESTTMP/foo
   $ rm -rf $sockpath
   $ CHGSOCKNAME=$bakchgsockname
   $ export CHGSOCKNAME
 
   $ cd ..
 
 editor
 ------
 
   $ cat >> pushbuffer.py <<EOF
   > def reposetup(ui, repo):
   >     repo.ui.pushbuffer(subproc=True)
   > EOF
 
   $ chg init editor
   $ cd editor
 
 by default, system() should be redirected to the client:
 
   $ touch foo
   $ CHGDEBUG= HGEDITOR=cat chg ci -Am channeled --edit 2>&1 \
   > | egrep "HG:|run 'cat"
   chg: debug: * run 'cat "*"' at '$TESTTMP/editor' (glob)
   HG: Enter commit message.  Lines beginning with 'HG:' are removed.
   HG: Leave message empty to abort commit.
   HG: --
   HG: user: test
   HG: branch 'default'
   HG: added foo
 
 but no redirection should be made if output is captured:
 
   $ touch bar
   $ CHGDEBUG= HGEDITOR=cat chg ci -Am bufferred --edit \
   > --config extensions.pushbuffer="$TESTTMP/pushbuffer.py" 2>&1 \
   > | egrep "HG:|run 'cat"
   [1]
 
 check that commit commands succeeded:
 
   $ hg log -T '{rev}:{desc}\n'
   1:bufferred
   0:channeled
 
   $ cd ..
 
 pager
 -----
 
   $ cat >> fakepager.py <<EOF
   > import sys
   > for line in sys.stdin:
   >     sys.stdout.write('paged! %r\n' % line)
   > EOF
 
 enable pager extension globally, but spawns the master server with no tty:
 
   $ chg init pager
   $ cd pager
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > pager =
   > [pager]
   > pager = "$PYTHON" $TESTTMP/fakepager.py
   > EOF
   $ chg version > /dev/null
   $ touch foo
   $ chg ci -qAm foo
 
 pager should be enabled if the attached client has a tty:
 
   $ chg log -l1 -q --config ui.formatted=True
   paged! '0:1f7b0de80e11\n'
   $ chg log -l1 -q --config ui.formatted=False
   0:1f7b0de80e11
 
 chg waits for pager if runcommand raises
 
   $ cat > $TESTTMP/crash.py <<EOF
   > from mercurial import registrar
   > cmdtable = {}
   > command = registrar.command(cmdtable)
   > @command(b'crash')
   > def pagercrash(ui, repo, *pats, **opts):
   >     ui.write('going to crash\n')
   >     raise Exception('.')
   > EOF
 
   $ cat > $TESTTMP/fakepager.py <<EOF
   > from __future__ import absolute_import
   > import sys
   > import time
   > for line in iter(sys.stdin.readline, ''):
   >     if 'crash' in line: # only interested in lines containing 'crash'
   >         # if chg exits when pager is sleeping (incorrectly), the output
   >         # will be captured by the next test case
   >         time.sleep(1)
   >         sys.stdout.write('crash-pager: %s' % line)
   > EOF
 
   $ cat >> .hg/hgrc <<EOF
   > [extensions]
   > crash = $TESTTMP/crash.py
   > EOF
 
   $ chg crash --pager=on --config ui.formatted=True 2>/dev/null
   crash-pager: going to crash
   [255]
 
   $ cd ..
 
 server lifecycle
 ----------------
 
 chg server should be restarted on code change, and old server will shut down
 automatically. In this test, we use the following time parameters:
 
  - "sleep 1" to make mtime different
  - "sleep 2" to notice mtime change (polling interval is 1 sec)
 
 set up repository with an extension:
 
   $ chg init extreload
   $ cd extreload
   $ touch dummyext.py
   $ cat <<EOF >> .hg/hgrc
   > [extensions]
   > dummyext = dummyext.py
   > EOF
 
 isolate socket directory for stable result:
 
   $ OLDCHGSOCKNAME=$CHGSOCKNAME
   $ mkdir chgsock
   $ CHGSOCKNAME=`pwd`/chgsock/server
 
 warm up server:
 
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 new server should be started if extension modified:
 
   $ sleep 1
   $ touch dummyext.py
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
   chg: debug: * instruction: unlink $TESTTMP/extreload/chgsock/server-* (glob)
   chg: debug: * instruction: reconnect (glob)
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 old server will shut down, while new server should still be reachable:
 
   $ sleep 2
   $ CHGDEBUG= chg log 2>&1 | (egrep 'instruction|start' || true)
 
 socket file should never be unlinked by old server:
 (simulates unowned socket by updating mtime, which makes sure server exits
 at polling cycle)
 
   $ ls chgsock/server-*
   chgsock/server-* (glob)
   $ touch chgsock/server-*
   $ sleep 2
   $ ls chgsock/server-*
   chgsock/server-* (glob)
 
 since no server is reachable from socket file, new server should be started:
 (this test makes sure that old server shut down automatically)
 
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
   chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 shut down servers and restore environment:
 
   $ rm -R chgsock
   $ sleep 2
   $ CHGSOCKNAME=$OLDCHGSOCKNAME
   $ cd ..
 
 check that server events are recorded:
 
   $ ls log
   server.log
   server.log.1
 
 print only the last 10 lines, since we aren't sure how many records are
 preserved:
 
   $ cat log/server.log.1 log/server.log | tail -10 | filterlog
-  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
-  YYYY/MM/DD HH:MM:SS (PID)> validate: []
-  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  YYYY/MM/DD HH:MM:SS (PID)> forked worker process (pid=...)
   YYYY/MM/DD HH:MM:SS (PID)> setprocname: ...
   YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
   YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/extreload'
   YYYY/MM/DD HH:MM:SS (PID)> setumask 18
   YYYY/MM/DD HH:MM:SS (PID)> setenv: ...
   YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
   YYYY/MM/DD HH:MM:SS (PID)> validate: []
+  YYYY/MM/DD HH:MM:SS (PID)> worker process exited (pid=...)
+  YYYY/MM/DD HH:MM:SS (PID)> $TESTTMP/extreload/chgsock/server-... is not owned, exiting.