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 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': To: indygreg, #hg-reviewers Cc: mercurial-devel _______________________________________________ Mercurial-devel mailing list Mercurial-devel@mercurial-scm.org https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
