commandserver: switch logging facility to ui.log() interface
authorYuya Nishihara <yuya@tcha.org>
Sat, 10 Nov 2018 19:09:37 +0900
changeset 53590 eaabcb689747c7fc99628ec8847a77d217d124f7
parent 53589 82210d88d814172b0317e5e5a1737b695b125a0e
child 53591 1617aa916d8851a344a870bda273928a11b01541
push id1079
push usergszorc@mozilla.com
push dateMon, 10 Dec 2018 19:44:59 +0000
commandserver: switch logging facility to ui.log() interface The "pager subcommand" message is removed since ui isn't accessible there. I think that's okay as cmdtable[cmd]() will call attachio() and some debug message will be printed.
mercurial/chgserver.py
mercurial/commandserver.py
tests/test-chg.t
--- a/mercurial/chgserver.py
+++ b/mercurial/chgserver.py
@@ -61,18 +61,16 @@ from . import (
     pycompat,
     util,
 )
 
 from .utils import (
     procutil,
 )
 
-_log = commandserver.log
-
 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', ...)
@@ -181,17 +179,18 @@ class hashstate(object):
         self.mtimepaths = mtimepaths
 
     @staticmethod
     def fromui(ui, mtimepaths=None):
         if mtimepaths is None:
             mtimepaths = _getmtimepaths(ui)
         confighash = _confighash(ui)
         mtimehash = _mtimehash(mtimepaths)
-        _log('confighash = %s mtimehash = %s\n' % (confighash, mtimehash))
+        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)
@@ -295,17 +294,16 @@ class channeledsystem(object):
             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:
-                    _log('pager subcommand: %s' % cmd)
                     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
@@ -339,17 +337,17 @@ class chgcmdserver(commandserver.server)
     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())
-        _log('received fds: %r\n' % clientfds)
+        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())
@@ -445,29 +443,29 @@ class chgcmdserver(commandserver.server)
             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)
-        _log('validate: %s\n' % insts)
+        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
-        _log('chdir to %r\n' % path)
+        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))
 
@@ -475,17 +473,17 @@ class chgcmdserver(commandserver.server)
         """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]
-        _log('setumask %r\n' % mask)
+        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 = []
@@ -500,33 +498,33 @@ class chgcmdserver(commandserver.server)
 
         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')
-        _log('setenv: %r\n' % sorted(newenv.keys()))
+        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()
-            _log('setprocname: %r\n' % name)
+            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
--- a/mercurial/commandserver.py
+++ b/mercurial/commandserver.py
@@ -31,27 +31,16 @@ from . import (
     util,
     vfs as vfsmod,
 )
 from .utils import (
     cborutil,
     procutil,
 )
 
-logfile = None
-
-def log(*args):
-    if not logfile:
-        return
-
-    for a in args:
-        logfile.write(str(a))
-
-    logfile.flush()
-
 class channeledoutput(object):
     """
     Write data to out in the following format:
 
     data length (unsigned int),
     data
     """
     def __init__(self, out, channel):
@@ -205,32 +194,27 @@ def _selectmessageencoder(ui):
 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 ui.config("cmdserver", "log") == '-':
-            global logfile
-            # switch log stream to the 'd' (debug) channel
-            logfile = channeledoutput(fout, 'd')
-
         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 = logfile
+        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)
@@ -371,23 +355,17 @@ def setuplogging(ui, repo=None, fp=None)
     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
-    tracked = {b'cmdserver'}
-
-    global logfile
-    if logpath == b'-':
-        logfile = ui.ferr
-    else:
-        logfile = open(logpath, 'ab')
+    tracked = {b'chgserver', b'cmdserver'}
 
     if logpath == b'-' and fp:
         logger = loggingutil.fileobjectlogger(fp, tracked)
     elif logpath == b'-':
         logger = loggingutil.fileobjectlogger(ui.ferr, tracked)
     else:
         logpath = os.path.abspath(logpath)
         vfs = vfsmod.vfs(os.path.dirname(logpath))
--- a/tests/test-chg.t
+++ b/tests/test-chg.t
@@ -1,12 +1,24 @@
 #require chg
 
+  $ cat <<EOF >> $HGRCPATH
+  > [cmdserver]
+  > log = $TESTTMP/server.log
+  > 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
@@ -196,10 +208,205 @@ since no server is reachable from socket
 (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:
+
+  $ cat server.log | filterlog
+  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  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'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/foo'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/foo'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/foo'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/editor'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/editor'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  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/editor'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/editor'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  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/editor'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  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'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/pager'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  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/pager'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/pager'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/pager'
+  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)> received fds: ...
+  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/pager'
+  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)> setprocname: ...
+  YYYY/MM/DD HH:MM:SS (PID)> received fds: ...
+  YYYY/MM/DD HH:MM:SS (PID)> chdir to '$TESTTMP/pager'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  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/pager'
+  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)> received fds: ...
+  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'
+  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: ['redirect $TESTTMP.chgsock/server-...']
+  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'
+  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)> confighash = ... mtimehash = ...
+  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)> 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: ['unlink $TESTTMP/extreload/chgsock/server-...', 'reconnect']
+  YYYY/MM/DD HH:MM:SS (PID)> confighash = ... mtimehash = ...
+  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)> 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)> confighash = ... mtimehash = ...
+  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: []