This is an archive of the discontinued Mercurial Phabricator instance.

Differential D2842

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

Authored by indygreg on Mar 13 2018, 3:11 PM.

Details

Reviewers
durin42
Group Reviewers
hg-reviewers
Commits
rHGd3a9036d9ae9: util: don't log low-level I/O calls for HTTP peer
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.

Diff Detail

Repository
rHG Mercurial
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

indygreg created this revision.Mar 13 2018, 3:11 PM
indygreg updated this revision to Diff 7008.Mar 13 2018, 9:16 PM
durin42 accepted this revision.Mar 19 2018, 9:37 PM
durin42 added a subscriber: durin42.

This one needs rebased, but looks good.

This revision is now accepted and ready to land.Mar 19 2018, 9:37 PM
indygreg updated this revision to Diff 7161.Mar 20 2018, 12:09 PM
durin42 accepted this revision.Mar 21 2018, 3:17 PM
indygreg updated this revision to Diff 7192.Mar 21 2018, 6:19 PM
durin42 accepted this revision.Mar 21 2018, 6:21 PM
Closed by commit rHGd3a9036d9ae9: util: don't log low-level I/O calls for HTTP peer (authored by indygreg). · Explain WhyMar 21 2018, 8:57 PM
This revision was automatically updated to reflect the committed changes.

Revision Contents
Changeset List

PathPackages
Mmercurial/debugcommands.py (4 lines)
Mmercurial/util.py (105 lines)
Mtests/test-http-protocol.t (25 lines)

Diff 7220

mercurial/debugcommands.py

# Turn pipes/sockets into observers so we can log I/O. # Turn pipes/sockets into observers so we can log I/O.
if ui.verbose: if ui.verbose:
openerargs = { openerargs = {
r'loggingfh': ui, r'loggingfh': ui,
r'loggingname': b's', r'loggingname': b's',
r'loggingopts': { r'loggingopts': {
r'logdata': True, r'logdata': True,
r'logdataapis': False,
}, },
} }
if ui.debugflag:
openerargs[r'loggingopts'][r'logdataapis'] = True
opener = urlmod.opener(ui, authinfo, **openerargs) opener = urlmod.opener(ui, authinfo, **openerargs)
if opts['peer'] == 'raw': if opts['peer'] == 'raw':
ui.write(_('using raw connection to peer\n')) ui.write(_('using raw connection to peer\n'))
peer = None peer = None
elif opts['peer']: elif opts['peer']:
raise error.Abort(_('--peer %s not supported with HTTP peers') % raise error.Abort(_('--peer %s not supported with HTTP peers') %
opts['peer']) opts['peer'])

mercurial/util.py

r'makefile', *args, **kwargs) r'makefile', *args, **kwargs)
# The file object may be used for I/O. So we turn it into a # The file object may be used for I/O. So we turn it into a
# proxy using our observer. # proxy using our observer.
observer = object.__getattribute__(self, r'_observer') observer = object.__getattribute__(self, r'_observer')
return makeloggingfileobject(observer.fh, res, observer.name, return makeloggingfileobject(observer.fh, res, observer.name,
reads=observer.reads, reads=observer.reads,
writes=observer.writes, writes=observer.writes,
logdata=observer.logdata) logdata=observer.logdata,
logdataapis=observer.logdataapis)
def recv(self, *args, **kwargs): def recv(self, *args, **kwargs):
return object.__getattribute__(self, r'_observedcall')( return object.__getattribute__(self, r'_observedcall')(
r'recv', *args, **kwargs) r'recv', *args, **kwargs)
def recvfrom(self, *args, **kwargs): def recvfrom(self, *args, **kwargs):
return object.__getattribute__(self, r'_observedcall')( return object.__getattribute__(self, r'_observedcall')(
r'recvfrom', *args, **kwargs) r'recvfrom', *args, **kwargs)
if isinstance(s, bytearray): if isinstance(s, bytearray):
s = bytes(s) s = bytes(s)
return DATA_ESCAPE_RE.sub(lambda m: DATA_ESCAPE_MAP[m.group(0)], s) return DATA_ESCAPE_RE.sub(lambda m: DATA_ESCAPE_MAP[m.group(0)], s)
class baseproxyobserver(object): class baseproxyobserver(object):
def _writedata(self, data): def _writedata(self, data):
if not self.logdata: if not self.logdata:
if self.logdataapis:
self.fh.write('\n') self.fh.write('\n')
self.fh.flush() self.fh.flush()
return return
# Simple case writes all data on a single line. # Simple case writes all data on a single line.
if b'\n' not in data: if b'\n' not in data:
if self.logdataapis:
self.fh.write(': %s\n' % escapedata(data)) self.fh.write(': %s\n' % escapedata(data))
else:
self.fh.write('%s> %s\n' % (self.name, escapedata(data)))
self.fh.flush() self.fh.flush()
return return
# Data with newlines is written to multiple lines. # Data with newlines is written to multiple lines.
if self.logdataapis:
self.fh.write(':\n') self.fh.write(':\n')
lines = data.splitlines(True) lines = data.splitlines(True)
for line in lines: for line in lines:
self.fh.write('%s> %s\n' % (self.name, escapedata(line))) self.fh.write('%s> %s\n' % (self.name, escapedata(line)))
self.fh.flush() self.fh.flush()
class fileobjectobserver(baseproxyobserver): class fileobjectobserver(baseproxyobserver):
"""Logs file object activity.""" """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.fh = fh
self.name = name self.name = name
self.logdata = logdata self.logdata = logdata
self.logdataapis = logdataapis
self.reads = reads self.reads = reads
self.writes = writes self.writes = writes
def read(self, res, size=-1): def read(self, res, size=-1):
if not self.reads: if not self.reads:
return return
# Python 3 can return None from reads at EOF instead of empty strings. # Python 3 can return None from reads at EOF instead of empty strings.
if res is None: if res is None:
res = '' res = ''
if self.logdataapis:
self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res))) self.fh.write('%s> read(%d) -> %d' % (self.name, size, len(res)))
self._writedata(res) self._writedata(res)
def readline(self, res, limit=-1): def readline(self, res, limit=-1):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> readline() -> %d' % (self.name, len(res))) self.fh.write('%s> readline() -> %d' % (self.name, len(res)))
self._writedata(res) self._writedata(res)
def readinto(self, res, dest): def readinto(self, res, dest):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest), self.fh.write('%s> readinto(%d) -> %r' % (self.name, len(dest),
res)) res))
data = dest[0:res] if res is not None else b'' data = dest[0:res] if res is not None else b''
self._writedata(data) self._writedata(data)
def write(self, res, data): def write(self, res, data):
if not self.writes: if not self.writes:
return return
# Python 2 returns None from some write() calls. Python 3 (reasonably) # Python 2 returns None from some write() calls. Python 3 (reasonably)
# returns the integer bytes written. # returns the integer bytes written.
if res is None and data: if res is None and data:
res = len(data) res = len(data)
if self.logdataapis:
self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res)) self.fh.write('%s> write(%d) -> %r' % (self.name, len(data), res))
self._writedata(data) self._writedata(data)
def flush(self, res): def flush(self, res):
if not self.writes: if not self.writes:
return return
self.fh.write('%s> flush() -> %r\n' % (self.name, res)) self.fh.write('%s> flush() -> %r\n' % (self.name, res))
# For observedbufferedinputpipe. # For observedbufferedinputpipe.
def bufferedread(self, res, size): def bufferedread(self, res, size):
if not self.reads:
return
if self.logdataapis:
self.fh.write('%s> bufferedread(%d) -> %d' % ( self.fh.write('%s> bufferedread(%d) -> %d' % (
self.name, size, len(res))) self.name, size, len(res)))
self._writedata(res) self._writedata(res)
def bufferedreadline(self, 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) self._writedata(res)
def makeloggingfileobject(logh, fh, name, reads=True, writes=True, def makeloggingfileobject(logh, fh, name, reads=True, writes=True,
logdata=False): logdata=False, logdataapis=True):
"""Turn a file object into a logging file object.""" """Turn a file object into a logging file object."""
observer = fileobjectobserver(logh, name, reads=reads, writes=writes, observer = fileobjectobserver(logh, name, reads=reads, writes=writes,
logdata=logdata) logdata=logdata, logdataapis=logdataapis)
return fileobjectproxy(fh, observer) return fileobjectproxy(fh, observer)
class socketobserver(baseproxyobserver): class socketobserver(baseproxyobserver):
"""Logs socket activity.""" """Logs socket activity."""
def __init__(self, fh, name, reads=True, writes=True, states=True, def __init__(self, fh, name, reads=True, writes=True, states=True,
logdata=False): logdata=False, logdataapis=True):
self.fh = fh self.fh = fh
self.name = name self.name = name
self.reads = reads self.reads = reads
self.writes = writes self.writes = writes
self.states = states self.states = states
self.logdata = logdata self.logdata = logdata
self.logdataapis = logdataapis
def makefile(self, res, mode=None, bufsize=None): def makefile(self, res, mode=None, bufsize=None):
if not self.states: if not self.states:
return return
self.fh.write('%s> makefile(%r, %r)\n' % ( self.fh.write('%s> makefile(%r, %r)\n' % (
self.name, mode, bufsize)) self.name, mode, bufsize))
def recv(self, res, size, flags=0): def recv(self, res, size, flags=0):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> recv(%d, %d) -> %d' % ( self.fh.write('%s> recv(%d, %d) -> %d' % (
self.name, size, flags, len(res))) self.name, size, flags, len(res)))
self._writedata(res) self._writedata(res)
def recvfrom(self, res, size, flags=0): def recvfrom(self, res, size, flags=0):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> recvfrom(%d, %d) -> %d' % ( self.fh.write('%s> recvfrom(%d, %d) -> %d' % (
self.name, size, flags, len(res[0]))) self.name, size, flags, len(res[0])))
self._writedata(res[0]) self._writedata(res[0])
def recvfrom_into(self, res, buf, size, flags=0): def recvfrom_into(self, res, buf, size, flags=0):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % ( self.fh.write('%s> recvfrom_into(%d, %d) -> %d' % (
self.name, size, flags, res[0])) self.name, size, flags, res[0]))
self._writedata(buf[0:res[0]]) self._writedata(buf[0:res[0]])
def recv_into(self, res, buf, size=0, flags=0): def recv_into(self, res, buf, size=0, flags=0):
if not self.reads: if not self.reads:
return return
if self.logdataapis:
self.fh.write('%s> recv_into(%d, %d) -> %d' % ( self.fh.write('%s> recv_into(%d, %d) -> %d' % (
self.name, size, flags, res)) self.name, size, flags, res))
self._writedata(buf[0:res]) self._writedata(buf[0:res])
def send(self, res, data, flags=0): def send(self, res, data, flags=0):
if not self.writes: if not self.writes:
return return
self.fh.write('%s> send(%d, %d) -> %d' % ( self.fh.write('%s> send(%d, %d) -> %d' % (
self.name, len(data), flags, len(res))) self.name, len(data), flags, len(res)))
self._writedata(data) self._writedata(data)
def sendall(self, res, data, flags=0): def sendall(self, res, data, flags=0):
if not self.writes: if not self.writes:
return return
if self.logdataapis:
# Returns None on success. So don't bother reporting return value. # Returns None on success. So don't bother reporting return value.
self.fh.write('%s> sendall(%d, %d)' % ( self.fh.write('%s> sendall(%d, %d)' % (
self.name, len(data), flags)) self.name, len(data), flags))
self._writedata(data) self._writedata(data)
def sendto(self, res, data, flagsoraddress, address=None): def sendto(self, res, data, flagsoraddress, address=None):
if not self.writes: if not self.writes:
return return
if address: if address:
flags = flagsoraddress flags = flagsoraddress
else: else:
flags = 0 flags = 0
if self.logdataapis:
self.fh.write('%s> sendto(%d, %d, %r) -> %d' % ( self.fh.write('%s> sendto(%d, %d, %r) -> %d' % (
self.name, len(data), flags, address, res)) self.name, len(data), flags, address, res))
self._writedata(data) self._writedata(data)
def setblocking(self, res, flag): def setblocking(self, res, flag):
if not self.states: if not self.states:
return return
self.fh.write('%s> setblocking(%r)\n' % (self.name, flag)) self.fh.write('%s> setblocking(%r)\n' % (self.name, flag))
def setsockopt(self, level, optname, value): def setsockopt(self, level, optname, value):
if not self.states: if not self.states:
return return
self.fh.write('%s> setsockopt(%r, %r, %r) -> %r\n' % ( self.fh.write('%s> setsockopt(%r, %r, %r) -> %r\n' % (
self.name, level, optname, value)) self.name, level, optname, value))
def makeloggingsocket(logh, fh, name, reads=True, writes=True, states=True, def makeloggingsocket(logh, fh, name, reads=True, writes=True, states=True,
logdata=False): logdata=False, logdataapis=True):
"""Turn a socket into a logging socket.""" """Turn a socket into a logging socket."""
observer = socketobserver(logh, name, reads=reads, writes=writes, observer = socketobserver(logh, name, reads=reads, writes=writes,
states=states, logdata=logdata) states=states, logdata=logdata,
logdataapis=logdataapis)
return socketproxy(fh, observer) return socketproxy(fh, observer)
def version(): def version():
"""Return version information if available.""" """Return version information if available."""
try: try:
from . import __version__ from . import __version__
return __version__.version return __version__.version
except ImportError: except ImportError:

tests/test-http-protocol.t

$ hg init empty $ hg init empty
$ hg -R empty serve -p $HGPORT -d --pid-file hg.pid $ hg -R empty serve -p $HGPORT -d --pid-file hg.pid
$ cat hg.pid > $DAEMON_PIDS $ cat hg.pid > $DAEMON_PIDS
$ hg --verbose debugwireproto http://$LOCALIP:$HGPORT << EOF $ hg --verbose debugwireproto http://$LOCALIP:$HGPORT << EOF
> command listkeys > command listkeys
> namespace namespaces > namespace namespaces
> EOF > EOF
s> sendall(*, 0): (glob)
s> GET /?cmd=capabilities HTTP/1.1\r\n s> GET /?cmd=capabilities HTTP/1.1\r\n
s> Accept-Encoding: identity\r\n s> Accept-Encoding: identity\r\n
s> accept: application/mercurial-0.1\r\n s> accept: application/mercurial-0.1\r\n
s> host: $LOCALIP:$HGPORT\r\n (glob) s> host: $LOCALIP:$HGPORT\r\n (glob)
s> user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob) s> user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob)
s> \r\n s> \r\n
s> makefile('rb', None) s> makefile('rb', None)
s> readline() -> 36:
s> HTTP/1.1 200 Script output follows\r\n s> HTTP/1.1 200 Script output follows\r\n
s> readline() -> 28:
s> Server: testing stub value\r\n s> Server: testing stub value\r\n
s> readline() -> *: (glob)
s> Date: $HTTP_DATE$\r\n s> Date: $HTTP_DATE$\r\n
s> readline() -> 41:
s> Content-Type: application/mercurial-0.1\r\n s> Content-Type: application/mercurial-0.1\r\n
s> readline() -> 21:
s> Content-Length: *\r\n (glob) s> Content-Length: *\r\n (glob)
s> readline() -> 2:
s> \r\n 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 sending listkeys command
s> sendall(*, 0): (glob)
s> GET /?cmd=listkeys HTTP/1.1\r\n s> GET /?cmd=listkeys HTTP/1.1\r\n
s> Accept-Encoding: identity\r\n s> Accept-Encoding: identity\r\n
s> vary: X-HgArg-1,X-HgProto-1\r\n s> vary: X-HgArg-1,X-HgProto-1\r\n
s> x-hgarg-1: namespace=namespaces\r\n s> x-hgarg-1: namespace=namespaces\r\n
s> x-hgproto-1: 0.1 0.2 comp=$USUAL_COMPRESSIONS$\r\n s> x-hgproto-1: 0.1 0.2 comp=$USUAL_COMPRESSIONS$\r\n
s> accept: application/mercurial-0.1\r\n s> accept: application/mercurial-0.1\r\n
s> host: $LOCALIP:$HGPORT\r\n (glob) s> host: $LOCALIP:$HGPORT\r\n (glob)
s> user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob) s> user-agent: mercurial/proto-1.0 (Mercurial *)\r\n (glob)
s> \r\n s> \r\n
s> makefile('rb', None) s> makefile('rb', None)
s> readline() -> 36:
s> HTTP/1.1 200 Script output follows\r\n s> HTTP/1.1 200 Script output follows\r\n
s> readline() -> 28:
s> Server: testing stub value\r\n s> Server: testing stub value\r\n
s> readline() -> *: (glob)
s> Date: $HTTP_DATE$\r\n s> Date: $HTTP_DATE$\r\n
s> readline() -> 41:
s> Content-Type: application/mercurial-0.1\r\n s> Content-Type: application/mercurial-0.1\r\n
s> readline() -> 20:
s> Content-Length: 30\r\n s> Content-Length: 30\r\n
s> readline() -> 2:
s> \r\n s> \r\n
s> read(30) -> 30:
s> bookmarks \n s> bookmarks \n
s> namespaces \n s> namespaces \n
s> phases s> phases
response: bookmarks \nnamespaces \nphases response: bookmarks \nnamespaces \nphases
Same thing, but with "httprequest" command Same thing, but with "httprequest" command
$ hg --verbose debugwireproto --peer raw http://$LOCALIP:$HGPORT << EOF $ hg --verbose debugwireproto --peer raw http://$LOCALIP:$HGPORT << EOF
> httprequest GET ?cmd=listkeys > httprequest GET ?cmd=listkeys
> accept: application/mercurial-0.1 > accept: application/mercurial-0.1
> user-agent: mercurial/proto-1.0 (Mercurial 42) > user-agent: mercurial/proto-1.0 (Mercurial 42)
> x-hgarg-1: namespace=namespaces > x-hgarg-1: namespace=namespaces
> EOF > EOF
using raw connection to peer using raw connection to peer
s> sendall(*, 0): (glob)
s> GET /?cmd=listkeys HTTP/1.1\r\n s> GET /?cmd=listkeys HTTP/1.1\r\n
s> Accept-Encoding: identity\r\n s> Accept-Encoding: identity\r\n
s> accept: application/mercurial-0.1\r\n s> accept: application/mercurial-0.1\r\n
s> user-agent: mercurial/proto-1.0 (Mercurial 42)\r\n s> user-agent: mercurial/proto-1.0 (Mercurial 42)\r\n
s> x-hgarg-1: namespace=namespaces\r\n s> x-hgarg-1: namespace=namespaces\r\n
s> host: $LOCALIP:$HGPORT\r\n (glob) s> host: $LOCALIP:$HGPORT\r\n (glob)
s> \r\n s> \r\n
s> makefile('rb', None) s> makefile('rb', None)
s> readline() -> 36:
s> HTTP/1.1 200 Script output follows\r\n s> HTTP/1.1 200 Script output follows\r\n
s> readline() -> 28:
s> Server: testing stub value\r\n s> Server: testing stub value\r\n
s> readline() -> *: (glob)
s> Date: $HTTP_DATE$\r\n s> Date: $HTTP_DATE$\r\n
s> readline() -> 41:
s> Content-Type: application/mercurial-0.1\r\n s> Content-Type: application/mercurial-0.1\r\n
s> readline() -> 20:
s> Content-Length: 30\r\n s> Content-Length: 30\r\n
s> readline() -> 2:
s> \r\n s> \r\n
s> read(30) -> 30:
s> bookmarks \n s> bookmarks \n
s> namespaces \n s> namespaces \n
s> phases s> phases
$ killdaemons.py $ killdaemons.py