[PATCH] ui: add optional timestamp to output

[Matthieu Laneuville]

# HG changeset patch
# User Matthieu Laneuville <mlaneuville at gmail.com>
# Date 1489110756 -32400
#      Fri Mar 10 10:52:36 2017 +0900
# Node ID f7c69a6deb56c856f6896f4f318fb125c3c5da37
# Parent  7433b3bc55eebfa9149280339b406bd4cec64efb
ui: add optional timestamp to output

This patch adds the possibility of having a timestamp prepended to every line.
For now, the feature is controled by an experimental config flag
'debug-timestamp' and format can be changed with debug-timestamp-format (default
is %H:%M:%S.%f).

The feature is still experimental because is still needs:
* win32 support,
* buffer support,
* label for the timestamp,
* a final UI.

A possible final UI would be to trigger this when combining '--debug' with
'--time' or maybe '--debug' and '--profile'. For now we focus on the
implementation.

diff -r 7433b3bc55ee -r f7c69a6deb56 mercurial/ui.py
--- a/mercurial/ui.py	Mon Mar 06 23:21:27 2017 -0800
+++ b/mercurial/ui.py	Fri Mar 10 10:52:36 2017 +0900
@@ -164,6 +164,8 @@ class ui(object):
         self._colormode = None
         self._terminfoparams = {}
         self._styles = {}
+        # keeps track of lines start in _prependtimestamp
+        self._startline = {'std':True, 'err':True}
 
         if src:
             self.fout = src.fout
@@ -788,6 +790,32 @@ class ui(object):
 
         return "".join(self._buffers.pop())
 
+    def _timestampprefix(self):
+        """Checks config if timestamp prefix should be used and return
+           format.
+        """
+        if not self.configbool("experimental", "debug-timestamp"):
+            return None
+        return self.config("experimental", "debug-timestamp-format",
+                           default="%H:%M:%S.f")
+
+    def _prependtimestamp(self, args, tsformat, stream):
+        """Adds timestamp at the beginning of new lines. Both stdout and stderr
+           streams are tracked separately.
+        """
+        timestamp = util.datestr(format=tsformat)
+        timestamp = self.label(timestamp, 'debug.timestamp.stdout')
+        timestamp += ' '
+        msgs = []
+        for element in args:
+            for piece in element.splitlines(True):
+                if self._startline[stream]:
+                    msgs.append(timestamp)
+                msgs.append(piece)
+                self._startline[stream] = piece.endswith('\n')
+
+        return msgs
+
     def write(self, *args, **opts):
         '''write args to output
 
@@ -804,6 +832,7 @@ class ui(object):
         "cmdname.type" is recommended. For example, status issues
         a label of "status.modified" for modified files.
         '''
+        tsformat = self._timestampprefix()
         if self._buffers and not opts.get('prompt', False):
             if self._bufferapplylabels:
                 label = opts.get('label', '')
@@ -819,6 +848,8 @@ class ui(object):
             if self._colormode is not None:
                 label = opts.get('label', '')
                 msgs = [self.label(a, label) for a in args]
+            if tsformat is not None:
+                msgs = self._prependtimestamp(msgs, tsformat, 'std')
             self._write(*msgs, **opts)
 
     def _write(self, *msgs, **opts):
@@ -833,6 +864,7 @@ class ui(object):
                 (util.timer() - starttime) * 1000
 
     def write_err(self, *args, **opts):
+        tsformat = self._timestampprefix()
         self._progclear()
         if self._bufferstates and self._bufferstates[-1][0]:
             self.write(*args, **opts)
@@ -845,6 +877,8 @@ class ui(object):
             if self._colormode is not None:
                 label = opts.get('label', '')
                 msgs = [self.label(a, label) for a in args]
+            if tsformat is not None:
+                msgs = self._prependtimestamp(msgs, tsformat, 'err')
             self._write_err(*msgs, **opts)
 
     def _write_err(self, *msgs, **opts):
diff -r 7433b3bc55ee -r f7c69a6deb56 tests/test-debug-timestamp.t
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/tests/test-debug-timestamp.t	Fri Mar 10 10:52:36 2017 +0900
@@ -0,0 +1,142 @@
+  $ hg init
+  $ touch a
+  $ touch b
+
+Checking when the feature is disabled
+
+  $ hg status --config experimental.debug-timestamp=False
+  ? a
+  ? b
+
+Now after enabling it
+
+  $ cat >> $HGRCPATH << EOF
+  > [experimental]
+  > debug-timestamp=True
+  > debug-timestamp-format=%H:%M
+  > EOF
+
+Create an extension to test all cases
+
+  $ cat > $TESTTMP/foocommand.py << EOF
+  > from mercurial import cmdutil
+  > cmdtable = {}
+  > command = cmdutil.command(cmdtable)
+  > 
+  > @command('testsinglestdout', [])
+  > def testsinglestdout(ui, repo):
+  >     '''One stdout'''
+  >     ui.write("stdout\n")
+  > 
+  > @command('testsinglestderr', [])
+  > def testsinglestderr(ui, repo):
+  >     '''One stderr'''
+  >     ui.write_err("stderr\n")
+  > 
+  > @command('testmultiplestdout', [])
+  > def testmultiplestdout(ui, repo):
+  >     '''Multiple stdout, either multiple messages or multiple calls.'''
+  >     ui.write("stdout1\n")
+  >     ui.write("stdout2\n")
+  >     ui.write("stdout3\n", "stdout4\n")
+  > 
+  > @command('testmultiplestderr', [])
+  > def testsmultiplestderr(ui, repo):
+  >     '''Multiple stderr, either multiple messages or multiple calls.'''
+  >     ui.write_err("stderr1\n")
+  >     ui.write_err("stderr2\n")
+  >     ui.write_err("stderr3\n", "stderr4\n")
+  > 
+  > @command('teststdnewline', [])
+  > def teststdnewline(ui, repo):
+  >     '''stdout with multiple newlines in a message.'''
+  >     ui.write("stdout1\nstdout2\n")
+  > 
+  > @command('testerrnewline', [])
+  > def testerrnewline(ui, repo):
+  >     '''stderr with multiple newlines in a message.'''
+  >     ui.write_err("stderr1\nstderr2\n")
+  > 
+  > @command('testouterr', [])
+  > def testouterr(ui, repo):
+  >     '''Test both flux in sequence.'''
+  >     ui.write("stdout1\n")
+  >     ui.write_err("stderr1\n")
+  >     ui.write("stdout2\n")
+  > 
+  > @command('testinterleaved', [])
+  > def testinterleaved(ui, repo):
+  >     '''Test interleaved fluxes.'''
+  >     ui.write("stdout1 ")
+  >     ui.write_err("stderr1\n")
+  >     ui.write("stdout2 ")
+  >     ui.write_err("stderr2\n")
+  >     ui.write("stdout3\n")
+  > 
+  > @command('testnewline2', [])
+  > def testsnewline(ui, repo):
+  >     '''Multiple messages with and without newlines.'''
+  >     ui.write("stdout1 ", "stdout2\n", "stdout3\n")
+  > 
+  > @command('testnewline3', [])
+  > def testsnewline(ui, repo):
+  >     '''Multiple calls with and without newlines.'''
+  >     ui.write("stdout1 ")
+  >     ui.write("stdout2\n")
+  >     ui.write("stdout3\n")
+  > EOF
+
+Add extension to hgrc
+
+  $ cat >> $HGRCPATH << EOF
+  > [extensions]
+  > foocommand=$TESTTMP/foocommand.py
+  > EOF
+
+Now test all cases
+
+  $ hg testsinglestdout
+  *:* stdout (glob)
+
+  $ hg testmultiplestdout
+  *:* stdout1 (glob)
+  *:* stdout2 (glob)
+  *:* stdout3 (glob)
+  *:* stdout4 (glob)
+
+  $ hg testsinglestderr
+  *:* stderr (glob)
+
+  $ hg testmultiplestderr
+  *:* stderr1 (glob)
+  *:* stderr2 (glob)
+  *:* stderr3 (glob)
+  *:* stderr4 (glob)
+
+  $ hg teststdnewline
+  *:* stdout1 (glob)
+  *:* stdout2 (glob)
+
+  $ hg testerrnewline
+  *:* stderr1 (glob)
+  *:* stderr2 (glob)
+
+  $ hg testnewline2
+  *:* stdout1 stdout2 (glob)
+  *:* stdout3 (glob)
+
+  $ hg testnewline3
+  *:* stdout1 stdout2 (glob)
+  *:* stdout3 (glob)
+
+  $ hg testouterr
+  *:* stdout1 (glob)
+  *:* stderr1 (glob)
+  *:* stdout2 (glob)
+
+  $ hg testinterleaved 2> stderr.log
+  *:* stdout1 stdout2 stdout3 (glob)
+
+  $ cat stderr.log
+  *:* stderr1 (glob)
+  *:* stderr2 (glob)