commandserver: switch logging facility to ui.log() interface

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.

--- a/mercurial/chgserver.py	Sat Nov 10 19:00:17 2018 +0900
+++ b/mercurial/chgserver.py	Sat Nov 10 19:09:37 2018 +0900
@@ -66,8 +66,6 @@
     procutil,
 )
 
-_log = commandserver.log
-
 def _hashlist(items):
     """return sha1 hexdigest for a list"""
     return node.hex(hashlib.sha1(str(items)).digest())
@@ -186,7 +184,8 @@
             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):
@@ -300,7 +299,6 @@
                 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)
@@ -344,7 +342,7 @@
         # 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()
@@ -450,7 +448,7 @@
         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):
@@ -462,7 +460,7 @@
         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):
@@ -480,7 +478,7 @@
 
     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):
@@ -505,7 +503,7 @@
             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)
 
@@ -521,7 +519,7 @@
         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
 

--- a/mercurial/commandserver.py	Sat Nov 10 19:00:17 2018 +0900
+++ b/mercurial/commandserver.py	Sat Nov 10 19:09:37 2018 +0900
@@ -36,17 +36,6 @@
     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:
@@ -210,11 +199,6 @@
     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
@@ -225,7 +209,7 @@
             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')
@@ -376,13 +360,7 @@
     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)

--- a/tests/test-chg.t	Sat Nov 10 19:00:17 2018 +0900
+++ b/tests/test-chg.t	Sat Nov 10 19:09:37 2018 +0900
@@ -1,7 +1,19 @@
 #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
@@ -201,5 +213,200 @@
 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: []