changeset 37044:d3a9036d9ae9

util: don't log low-level I/O calls for HTTP peer

`hg debugwireproto` is useful for testing HTTP interactions. Possibly
more useful than `get-with-headers.py`. But one thing that makes it
annoying for mid-level tests is that it logs all API calls, such
as readline(). This makes output - especially headers - overly
verbose.

This commit teaches our file and socket observers to not log API
calls on functions dealing with data.

We change the behavior of `hg debugwireproto` to enable this mode
by default. --debug can be added to restore the previous behavior.

As the test changes demonstrate, this makes tests much easier to
read. As a bonus, it also removes some required (glob) over lengths
in system call results.

One thing that's lacking is knowing which side sent data. But we can
fix this in a follow-up once it becomes a problem.

Differential Revision: https://phab.mercurial-scm.org/D2842

--- a/mercurial/debugcommands.py	Wed Mar 21 09:56:41 2018 -0700
+++ b/mercurial/debugcommands.py	Tue Mar 13 11:20:07 2018 -0700
@@ -2839,9 +2839,13 @@
                 r'loggingname': b's',
                 r'loggingopts': {
                     r'logdata': True,
+                    r'logdataapis': False,
                 },
             }
 
+        if ui.debugflag:
+            openerargs[r'loggingopts'][r'logdataapis'] = True
+
         opener = urlmod.opener(ui, authinfo, **openerargs)
 
         if opts['peer'] == 'raw':

--- a/mercurial/util.py	Wed Mar 21 09:56:41 2018 -0700
+++ b/mercurial/util.py	Tue Mar 13 11:20:07 2018 -0700
@@ -762,7 +762,8 @@
         return makeloggingfileobject(observer.fh, res, observer.name,
                                      reads=observer.reads,
                                      writes=observer.writes,
-                                     logdata=observer.logdata)
+                                     logdata=observer.logdata,
+                                     logdataapis=observer.logdataapis)
 
     def recv(self, *args, **kwargs):
         return object.__getattribute__(self, r'_observedcall')(
@@ -825,18 +826,24 @@
 class baseproxyobserver(object):
     def _writedata(self, data):
         if not self.logdata:
-            self.fh.write('\n')
-            self.fh.flush()
+            if self.logdataapis:
+                self.fh.write('\n')
+                self.fh.flush()
             return
 
         # Simple case writes all data on a single line.
         if b'\n' not in data:
-            self.fh.write(': %s\n' % escapedata(data))
+            if self.logdataapis:
+                self.fh.write(': %s\n' % escapedata(data))
+            else:
+                self.fh.write('%s>     %s\n' % (self.name, escapedata(data)))
             self.fh.flush()
             return
 
         # Data with newlines is written to multiple lines.
-        self.fh.write(':\n')
+        if self.logdataapis:
+            self.fh.write(':\n')
+
         lines = data.splitlines(True)
         for line in lines:
             self.fh.write('%s>     %s\n' % (self.name, escapedata(line)))
@@ -844,10 +851,12 @@
 
 class fileobjectobserver(baseproxyobserver):
     """Logs file object activity."""
-    def __init__(self, fh, name, reads=True, writes=True, logdata=False):
+    def __init__(self, fh, name, reads=True, writes=True, logdata=False,
+                 logdataapis=True):
         self.fh = fh
         self.name = name
         self.logdata = logdata
+        self.logdataapis = logdataapis
         self.reads = reads
         self.writes = writes
 
@@ -858,22 +867,28 @@
         if res is None:
             res = ''
 
-        self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res)))
+        if self.logdataapis:
+            self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res)))
+
         self._writedata(res)
 
     def readline(self, res, limit=-1):
         if not self.reads:
             return
 
-        self.fh.write('%s> readline() -> %d' % (self.name, len(res)))
+        if self.logdataapis:
+            self.fh.write('%s> readline() -> %d' % (self.name, len(res)))
+
         self._writedata(res)
 
     def readinto(self, res, dest):
         if not self.reads:
             return
 
-        self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest),
-                                                  res))
+        if self.logdataapis:
+            self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest),
+                                                      res))
+
         data = dest[0:res] if res is not None else b''
         self._writedata(data)
 
@@ -886,7 +901,9 @@
         if res is None and data:
             res = len(data)
 
-        self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res))
+        if self.logdataapis:
+            self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res))
+
         self._writedata(data)
 
     def flush(self, res):
@@ -897,32 +914,44 @@
 
     # For observedbufferedinputpipe.
     def bufferedread(self, res, size):
-        self.fh.write('%s> bufferedread(%d) -> %d' % (
-            self.name, size, len(res)))
+        if not self.reads:
+            return
+
+        if self.logdataapis:
+            self.fh.write('%s> bufferedread(%d) -> %d' % (
+                self.name, size, len(res)))
+
         self._writedata(res)
 
     def bufferedreadline(self, res):
-        self.fh.write('%s> bufferedreadline() -> %d' % (self.name, len(res)))
+        if not self.reads:
+            return
+
+        if self.logdataapis:
+            self.fh.write('%s> bufferedreadline() -> %d' % (
+                self.name, len(res)))
+
         self._writedata(res)
 
 def makeloggingfileobject(logh, fh, name, reads=True, writes=True,
-                          logdata=False):
+                          logdata=False, logdataapis=True):
     """Turn a file object into a logging file object."""
 
     observer = fileobjectobserver(logh, name, reads=reads, writes=writes,
-                                  logdata=logdata)
+                                  logdata=logdata, logdataapis=logdataapis)
     return fileobjectproxy(fh, observer)
 
 class socketobserver(baseproxyobserver):
     """Logs socket activity."""
     def __init__(self, fh, name, reads=True, writes=True, states=True,
-                 logdata=False):
+                 logdata=False, logdataapis=True):
         self.fh = fh
         self.name = name
         self.reads = reads
         self.writes = writes
         self.states = states
         self.logdata = logdata
+        self.logdataapis = logdataapis
 
     def makefile(self, res, mode=None, bufsize=None):
         if not self.states:
@@ -935,32 +964,39 @@
         if not self.reads:
             return
 
-        self.fh.write('%s> recv(%d, %d) -> %d' % (
-            self.name, size, flags, len(res)))
+        if self.logdataapis:
+            self.fh.write('%s> recv(%d, %d) -> %d' % (
+                self.name, size, flags, len(res)))
         self._writedata(res)
 
     def recvfrom(self, res, size, flags=0):
         if not self.reads:
             return
 
-        self.fh.write('%s> recvfrom(%d, %d) -> %d' % (
-            self.name, size, flags, len(res[0])))
+        if self.logdataapis:
+            self.fh.write('%s> recvfrom(%d, %d) -> %d' % (
+                self.name, size, flags, len(res[0])))
+
         self._writedata(res[0])
 
     def recvfrom_into(self, res, buf, size, flags=0):
         if not self.reads:
             return
 
-        self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % (
-            self.name, size, flags, res[0]))
+        if self.logdataapis:
+            self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % (
+                self.name, size, flags, res[0]))
+
         self._writedata(buf[0:res[0]])
 
     def recv_into(self, res, buf, size=0, flags=0):
         if not self.reads:
             return
 
-        self.fh.write('%s> recv_into(%d, %d) -> %d' % (
-            self.name, size, flags, res))
+        if self.logdataapis:
+            self.fh.write('%s> recv_into(%d, %d) -> %d' % (
+                self.name, size, flags, res))
+
         self._writedata(buf[0:res])
 
     def send(self, res, data, flags=0):
@@ -975,9 +1011,11 @@
         if not self.writes:
             return
 
-        # Returns None on success. So don't bother reporting return value.
-        self.fh.write('%s> sendall(%d, %d)' % (
-            self.name, len(data), flags))
+        if self.logdataapis:
+            # Returns None on success. So don't bother reporting return value.
+            self.fh.write('%s> sendall(%d, %d)' % (
+                self.name, len(data), flags))
+
         self._writedata(data)
 
     def sendto(self, res, data, flagsoraddress, address=None):
@@ -989,8 +1027,10 @@
         else:
             flags = 0
 
-        self.fh.write('%s> sendto(%d, %d, %r) -> %d' % (
-            self.name, len(data), flags, address, res))
+        if self.logdataapis:
+            self.fh.write('%s> sendto(%d, %d, %r) -> %d' % (
+                self.name, len(data), flags, address, res))
+
         self._writedata(data)
 
     def setblocking(self, res, flag):
@@ -1019,11 +1059,12 @@
             self.name, level, optname, value))
 
 def makeloggingsocket(logh, fh, name, reads=True, writes=True, states=True,
-                      logdata=False):
+                      logdata=False, logdataapis=True):
     """Turn a socket into a logging socket."""
 
     observer = socketobserver(logh, name, reads=reads, writes=writes,
-                              states=states, logdata=logdata)
+                              states=states, logdata=logdata,
+                              logdataapis=logdataapis)
     return socketproxy(fh, observer)
 
 def version():

--- a/tests/test-http-protocol.t	Wed Mar 21 09:56:41 2018 -0700
+++ b/tests/test-http-protocol.t	Tue Mar 13 11:20:07 2018 -0700
@@ -175,7 +175,6 @@
   > command listkeys
   >     namespace namespaces
   > EOF
-  s> sendall(*, 0): (glob)
   s>     GET /?cmd=capabilities HTTP/1.1\r\n
   s>     Accept-Encoding: identity\r\n
   s>     accept: application/mercurial-0.1\r\n
@@ -183,21 +182,14 @@
   s>     user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob)
   s>     \r\n
   s> makefile('rb', None)
-  s> readline() -> 36:
   s>     HTTP/1.1 200 Script output follows\r\n
-  s> readline() -> 28:
   s>     Server: testing stub value\r\n
-  s> readline() -> *: (glob)
   s>     Date: $HTTP_DATE$\r\n
-  s> readline() -> 41:
   s>     Content-Type: application/mercurial-0.1\r\n
-  s> readline() -> 21:
   s>     Content-Length: *\r\n (glob)
-  s> readline() -> 2:
   s>     \r\n
-  s> read(*) -> *: lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS_SERVER$ unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024 httpmediatype=0.1rx,0.1tx,0.2tx compression=$BUNDLE2_COMPRESSIONS$ (glob)
+  s>     lookup branchmap pushkey known getbundle unbundlehash batch changegroupsubset streamreqs=generaldelta,revlogv1 $USUAL_BUNDLE2_CAPS_SERVER$ unbundle=HG10GZ,HG10BZ,HG10UN httpheader=1024 httpmediatype=0.1rx,0.1tx,0.2tx compression=$BUNDLE2_COMPRESSIONS$
   sending listkeys command
-  s> sendall(*, 0): (glob)
   s>     GET /?cmd=listkeys HTTP/1.1\r\n
   s>     Accept-Encoding: identity\r\n
   s>     vary: X-HgArg-1,X-HgProto-1\r\n
@@ -208,19 +200,12 @@
   s>     user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob)
   s>     \r\n
   s> makefile('rb', None)
-  s> readline() -> 36:
   s>     HTTP/1.1 200 Script output follows\r\n
-  s> readline() -> 28:
   s>     Server: testing stub value\r\n
-  s> readline() -> *: (glob)
   s>     Date: $HTTP_DATE$\r\n
-  s> readline() -> 41:
   s>     Content-Type: application/mercurial-0.1\r\n
-  s> readline() -> 20:
   s>     Content-Length: 30\r\n
-  s> readline() -> 2:
   s>     \r\n
-  s> read(30) -> 30:
   s>     bookmarks	\n
   s>     namespaces	\n
   s>     phases	
@@ -235,7 +220,6 @@
   >     x-hgarg-1: namespace=namespaces
   > EOF
   using raw connection to peer
-  s> sendall(*, 0): (glob)
   s>     GET /?cmd=listkeys HTTP/1.1\r\n
   s>     Accept-Encoding: identity\r\n
   s>     accept: application/mercurial-0.1\r\n
@@ -244,19 +228,12 @@
   s>     host: $LOCALIP:$HGPORT\r\n (glob)
   s>     \r\n
   s> makefile('rb', None)
-  s> readline() -> 36:
   s>     HTTP/1.1 200 Script output follows\r\n
-  s> readline() -> 28:
   s>     Server: testing stub value\r\n
-  s> readline() -> *: (glob)
   s>     Date: $HTTP_DATE$\r\n
-  s> readline() -> 41:
   s>     Content-Type: application/mercurial-0.1\r\n
-  s> readline() -> 20:
   s>     Content-Length: 30\r\n
-  s> readline() -> 2:
   s>     \r\n
-  s> read(30) -> 30:
   s>     bookmarks	\n
   s>     namespaces	\n
   s>     phases