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

login
register
mail settings
Submitter phabricator
Date March 13, 2018, 7:12 p.m.
Message ID <differential-rev-PHID-DREV-fosnd4gfe5nvwyezyr4y-req@phab.mercurial-scm.org>
Download mbox | patch
Permalink /patch/29457/
State Superseded
Headers show

Comments

phabricator - March 13, 2018, 7:12 p.m.
indygreg created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  `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.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2842

AFFECTED FILES
  mercurial/debugcommands.py
  mercurial/util.py
  tests/test-http-protocol.t

CHANGE DETAILS




To: indygreg, #hg-reviewers
Cc: mercurial-devel
phabricator - March 20, 2018, 1:37 a.m.
durin42 accepted this revision.
durin42 added a comment.
This revision is now accepted and ready to land.


  This one needs rebased, but looks good.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D2842

To: indygreg, #hg-reviewers, durin42
Cc: durin42, mercurial-devel

Patch

diff --git a/tests/test-http-protocol.t b/tests/test-http-protocol.t
--- a/tests/test-http-protocol.t
+++ b/tests/test-http-protocol.t
@@ -175,29 +175,21 @@ 
   > 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
   s>     host: $LOCALIP:$HGPORT\r\n (glob)
   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,28 +220,20 @@ 
   >     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
   s>     user-agent: mercurial/proto-1.0 (Mercurial 42)\r\n (glob)
   s>     x-hgarg-1: namespace=namespaces\r\n
   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	
diff --git a/mercurial/util.py b/mercurial/util.py
--- a/mercurial/util.py
+++ b/mercurial/util.py
@@ -755,7 +755,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')(
@@ -818,26 +819,34 @@ 
 class baseproxyobserver(object):
     def _writedata(self, data):
         if not self.logdata:
-            self.fh.write('\n')
+            if self.logdataapis:
+                self.fh.write('\n')
             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)))
             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)))
 
 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
 
@@ -848,22 +857,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)
 
@@ -876,7 +891,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):
@@ -887,32 +904,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:
@@ -925,32 +954,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):
@@ -965,9 +1001,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):
@@ -979,8 +1017,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):
@@ -1009,11 +1049,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():
diff --git a/mercurial/debugcommands.py b/mercurial/debugcommands.py
--- a/mercurial/debugcommands.py
+++ b/mercurial/debugcommands.py
@@ -2825,9 +2825,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':