Revamp pathoc log output with a context handler

This does two things - it gives us a central place to put log utilities,
and it lets us group together related log lines.
This commit is contained in:
Aldo Cortesi 2015-04-30 13:59:10 +12:00
parent f927701e74
commit fea3d8e421
3 changed files with 146 additions and 114 deletions

View File

@ -16,6 +16,43 @@ import language
import utils import utils
class Log:
def __init__(self, fp):
self.lines = []
self.fp = fp
self.suppressed = False
def __enter__(self):
return self
def __exit__(self, exc_type, exc_value, traceback):
if self.suppressed or not self.fp:
return
if exc_type == tcp.NetLibTimeout:
self("Timeout")
elif exc_type == tcp.NetLibDisconnect:
self("Disconnect")
elif exc_type == http.HttpError:
self("HTTP Error: %s"%exc_value.message)
self.fp.write("\n".join(self.lines))
self.fp.write("\n")
self.fp.flush()
def __call__(self, line):
self.lines.append(line)
def suppress(self):
self.suppressed = True
def dump(self, data, hexdump):
if hexdump:
for line in netlib.utils.hexdump(data):
self("\t%s %s %s"%line)
else:
for i in netlib.utils.cleanBin(data).split("\n"):
self("\t%s"%i)
class PathocError(Exception): class PathocError(Exception):
pass pass
@ -79,9 +116,10 @@ class Response:
class WebsocketFrameReader(threading.Thread): class WebsocketFrameReader(threading.Thread):
def __init__(self, rfile, callback, ws_read_limit): def __init__(self, rfile, showresp, callback, ws_read_limit):
threading.Thread.__init__(self) threading.Thread.__init__(self)
self.ws_read_limit = ws_read_limit self.ws_read_limit = ws_read_limit
self.showresp = showresp
self.rfile, self.callback = rfile, callback self.rfile, self.callback = rfile, callback
self.terminate = Queue.Queue() self.terminate = Queue.Queue()
self.is_done = Queue.Queue() self.is_done = Queue.Queue()
@ -97,7 +135,12 @@ class WebsocketFrameReader(threading.Thread):
except Queue.Empty: except Queue.Empty:
pass pass
for rfile in r: for rfile in r:
print websockets.Frame.from_file(self.rfile).human_readable() if self.showresp:
rfile.start_log()
self.callback(
websockets.Frame.from_file(self.rfile),
rfile.get_log()
)
if self.ws_read_limit is not None: if self.ws_read_limit is not None:
self.ws_read_limit -= 1 self.ws_read_limit -= 1
self.is_done.put(None) self.is_done.put(None)
@ -126,7 +169,7 @@ class Pathoc(tcp.TCPClient):
ignorecodes = (), ignorecodes = (),
ignoretimeout = False, ignoretimeout = False,
showsummary = False, showsummary = False,
fp = sys.stderr fp = sys.stdout
): ):
""" """
spec: A request specification spec: A request specification
@ -163,6 +206,9 @@ class Pathoc(tcp.TCPClient):
self.ws_framereader = None self.ws_framereader = None
def log(self):
return Log(self.fp)
def http_connect(self, connect_to): def http_connect(self, connect_to):
self.wfile.write( self.wfile.write(
'CONNECT %s:%s HTTP/1.1\r\n'%tuple(connect_to) + 'CONNECT %s:%s HTTP/1.1\r\n'%tuple(connect_to) +
@ -205,20 +251,11 @@ class Pathoc(tcp.TCPClient):
if showssl: if showssl:
print >> fp, str(self.sslinfo) print >> fp, str(self.sslinfo)
def _show_summary(self, fp, resp): def _resp_summary(self, resp):
print >> fp, "<< %s %s: %s bytes"%( return "<< %s %s: %s bytes"%(
resp.status_code, utils.xrepr(resp.msg), len(resp.content) resp.status_code, utils.xrepr(resp.msg), len(resp.content)
) )
def _show(self, fp, header, data, hexdump):
if hexdump:
print >> fp, "%s (hex dump):"%header
for line in netlib.utils.hexdump(data):
print >> fp, "\t%s %s %s"%line
else:
print >> fp, "%s (unprintables escaped):"%header
print >> fp, netlib.utils.cleanBin(data)
def stop(self): def stop(self):
self.ws_framereader.terminate.put(None) self.ws_framereader.terminate.put(None)
@ -232,19 +269,28 @@ class Pathoc(tcp.TCPClient):
except Queue.Empty: except Queue.Empty:
pass pass
def websocket_get_frame(self, frame): def websocket_get_frame(self, frame, wirelog):
""" """
Called when a frame is received from the server. Called when a frame is received from the server.
""" """
pass with self.log() as log:
log("<< %s"%frame.header.human_readable())
if self.showresp:
log.dump(
wirelog,
self.hexdump
)
def websocket_send_frame(self, r): def websocket_send_frame(self, r):
""" """
Sends a single websocket frame. Sends a single websocket frame.
""" """
with self.log() as log:
req = None req = None
if isinstance(r, basestring): if isinstance(r, basestring):
r = language.parse_requests(r)[0] r = language.parse_requests(r)[0]
log(">> %s"%r)
if self.showreq: if self.showreq:
self.wfile.start_log() self.wfile.start_log()
try: try:
@ -252,21 +298,13 @@ class Pathoc(tcp.TCPClient):
self.wfile.flush() self.wfile.flush()
except tcp.NetLibTimeout: except tcp.NetLibTimeout:
if self.ignoretimeout: if self.ignoretimeout:
self.log("Timeout (ignored)")
return None return None
if self.showsummary:
print >> self.fp, "<<", "Timeout"
raise
except tcp.NetLibDisconnect: # pragma: nocover
if self.showsummary:
print >> self.fp, "<<", "Disconnect"
raise raise
finally: finally:
if req: if req:
if self.explain:
print >> self.fp, ">> Spec:", r.spec()
if self.showreq: if self.showreq:
self._show( log.dump(
self.fp, ">> Websocket Frame",
self.wfile.get_log(), self.wfile.get_log(),
self.hexdump self.hexdump
) )
@ -280,13 +318,14 @@ class Pathoc(tcp.TCPClient):
server frame. server frame.
limit: Disconnect after receiving N server frames. limit: Disconnect after receiving N server frames.
""" """
with self.log() as log:
resp = self.http(r) resp = self.http(r)
if resp.status_code == 101: if resp.status_code == 101:
if self.showsummary: log("starting websocket connection...")
print >> self.fp, "<< websocket connection established..."
self.ws_framereader = WebsocketFrameReader( self.ws_framereader = WebsocketFrameReader(
self.rfile, self.rfile,
self.websocket_get_frame, self.showresp,
callback,
self.ws_read_limit self.ws_read_limit
) )
self.ws_framereader.start() self.ws_framereader.start()
@ -302,8 +341,10 @@ class Pathoc(tcp.TCPClient):
May raise http.HTTPError, tcp.NetLibError May raise http.HTTPError, tcp.NetLibError
""" """
with self.log() as log:
if isinstance(r, basestring): if isinstance(r, basestring):
r = language.parse_requests(r)[0] r = language.parse_requests(r)[0]
log(">> %s"%r)
resp, req = None, None resp, req = None, None
if self.showreq: if self.showreq:
self.wfile.start_log() self.wfile.start_log()
@ -321,41 +362,24 @@ class Pathoc(tcp.TCPClient):
) )
resp.append(self.sslinfo) resp.append(self.sslinfo)
resp = Response(*resp) resp = Response(*resp)
except http.HttpError, v:
if self.showsummary:
print >> self.fp, "<< HTTP Error:", v.message
raise
except tcp.NetLibTimeout: except tcp.NetLibTimeout:
if self.ignoretimeout: if self.ignoretimeout:
log("Timeout (ignored)")
return None return None
if self.showsummary:
print >> self.fp, "<<", "Timeout"
raise
except tcp.NetLibDisconnect: # pragma: nocover
if self.showsummary:
print >> self.fp, "<<", "Disconnect"
raise raise
finally: finally:
if req: if req:
if resp and resp.status_code in self.ignorecodes:
resp = None
else:
if self.explain:
print >> self.fp, ">> Spec:", r.spec()
if self.showreq: if self.showreq:
self._show( log.dump(
self.fp, ">> Request",
self.wfile.get_log(), self.wfile.get_log(),
self.hexdump self.hexdump
) )
if resp:
if self.showsummary and resp: log(self._resp_summary(resp))
self._show_summary(self.fp, resp) if resp.status_code in self.ignorecodes:
log.suppress()
if self.showresp: if self.showresp:
self._show( log.dump(
self.fp,
"<< Response",
self.rfile.get_log(), self.rfile.get_log(),
self.hexdump self.hexdump
) )

View File

@ -36,7 +36,8 @@ class _TestDaemon:
def test_info(self): def test_info(self):
c = pathoc.Pathoc( c = pathoc.Pathoc(
("127.0.0.1", self.d.port), ("127.0.0.1", self.d.port),
ssl = self.ssl ssl = self.ssl,
fp = None
) )
c.connect() c.connect()
resp = c.request("get:/api/info") resp = c.request("get:/api/info")
@ -77,7 +78,7 @@ class _TestDaemon:
r = r.freeze(language.Settings()) r = r.freeze(language.Settings())
try: try:
c.request(r) c.request(r)
except (http.HttpError, tcp.NetLibError), v: except (http.HttpError, tcp.NetLibError):
pass pass
return s.getvalue() return s.getvalue()
@ -93,7 +94,8 @@ class TestDaemonSSL(_TestDaemon):
c = pathoc.Pathoc( c = pathoc.Pathoc(
("127.0.0.1", self.d.port), ("127.0.0.1", self.d.port),
ssl = True, ssl = True,
sni = "foobar.com" sni = "foobar.com",
fp = None
) )
c.connect() c.connect()
c.request("get:/p/200") c.request("get:/p/200")
@ -108,7 +110,8 @@ class TestDaemonSSL(_TestDaemon):
c = pathoc.Pathoc( c = pathoc.Pathoc(
("127.0.0.1", self.d.port), ("127.0.0.1", self.d.port),
ssl = True, ssl = True,
clientcert = tutils.test_data.path("data/clientcert/client.pem") clientcert = tutils.test_data.path("data/clientcert/client.pem"),
fp = None
) )
c.connect() c.connect()
c.request("get:/p/200") c.request("get:/p/200")
@ -121,7 +124,7 @@ class TestDaemon(_TestDaemon):
ssl = False ssl = False
def test_ssl_error(self): def test_ssl_error(self):
c = pathoc.Pathoc(("127.0.0.1", self.d.port), ssl = True) c = pathoc.Pathoc(("127.0.0.1", self.d.port), ssl = True, fp=None)
tutils.raises("ssl handshake", c.connect) tutils.raises("ssl handshake", c.connect)
def test_showssl(self): def test_showssl(self):
@ -143,8 +146,10 @@ class TestDaemon(_TestDaemon):
def test_showresp(self): def test_showresp(self):
reqs = ["get:/api/info:p0,0", "get:/api/info:p0,0"] reqs = ["get:/api/info:p0,0", "get:/api/info:p0,0"]
assert self.tval(reqs).count("200") == 2 assert self.tval(reqs).count("200") == 2
assert self.tval(reqs, showresp=True).count("unprintables escaped") == 2 assert self.tval(reqs, showresp=True).count("HTTP/1.1 200 OK") == 2
assert self.tval(reqs, showresp=True, hexdump=True).count("hex dump") == 2 assert self.tval(
reqs, showresp=True, hexdump=True
).count("0000000000") == 2
def test_showresp_httperr(self): def test_showresp_httperr(self):
v = self.tval(["get:'/p/200:d20'"], showresp=True, showsummary=True) v = self.tval(["get:'/p/200:d20'"], showresp=True, showsummary=True)
@ -157,15 +162,17 @@ class TestDaemon(_TestDaemon):
def test_showreq(self): def test_showreq(self):
reqs = ["get:/api/info:p0,0", "get:/api/info:p0,0"] reqs = ["get:/api/info:p0,0", "get:/api/info:p0,0"]
assert self.tval(reqs, showreq=True).count("unprintables escaped") == 2 assert self.tval(reqs, showreq=True).count("GET /api") == 2
assert self.tval(reqs, showreq=True, hexdump=True).count("hex dump") == 2 assert self.tval(
reqs, showreq=True, hexdump=True
).count("0000000000") == 2
def test_conn_err(self): def test_conn_err(self):
assert "Invalid server response" in self.tval(["get:'/p/200:d2'"]) assert "Invalid server response" in self.tval(["get:'/p/200:d2'"])
def test_connect_fail(self): def test_connect_fail(self):
to = ("foobar", 80) to = ("foobar", 80)
c = pathoc.Pathoc(("127.0.0.1", self.d.port)) c = pathoc.Pathoc(("127.0.0.1", self.d.port), fp=None)
c.rfile, c.wfile = cStringIO.StringIO(), cStringIO.StringIO() c.rfile, c.wfile = cStringIO.StringIO(), cStringIO.StringIO()
tutils.raises("connect failed", c.http_connect, to) tutils.raises("connect failed", c.http_connect, to)
c.rfile = cStringIO.StringIO( c.rfile = cStringIO.StringIO(

View File

@ -77,7 +77,8 @@ class DaemonTests(object):
c = pathoc.Pathoc( c = pathoc.Pathoc(
("localhost", self.d.port), ("localhost", self.d.port),
ssl=ssl, ssl=ssl,
ws_read_limit=ws_read_limit ws_read_limit=ws_read_limit,
fp = None
) )
c.connect(connect_to) c.connect(connect_to)
if timeout: if timeout: