add support for log levels

This commit is contained in:
Maximilian Hils 2014-03-13 01:04:45 +01:00
parent 7e86744226
commit 4d9799f103
10 changed files with 65 additions and 60 deletions

View File

@ -437,20 +437,20 @@ class ConsoleMaster(flow.FlowMaster):
status, val = s.run(method, f) status, val = s.run(method, f)
if val: if val:
if status: if status:
self.add_event("Method %s return: %s"%(method, val)) self.add_event("Method %s return: %s"%(method, val), "debug")
else: else:
self.add_event("Method %s error: %s"%(method, val[1])) self.add_event("Method %s error: %s"%(method, val[1]), "error")
def run_script_once(self, command, f): def run_script_once(self, command, f):
if not command: if not command:
return return
self.add_event("Running script on flow: %s"%command) self.add_event("Running script on flow: %s"%command, "debug")
try: try:
s = script.Script(command, self) s = script.Script(command, self)
except script.ScriptError, v: except script.ScriptError, v:
self.statusbar.message("Error loading script.") self.statusbar.message("Error loading script.")
self.add_event("Error loading script:\n%s"%v.args[0]) self.add_event("Error loading script:\n%s"%v.args[0], "error")
return return
if f.request: if f.request:
@ -582,7 +582,7 @@ class ConsoleMaster(flow.FlowMaster):
if self.options.rfile: if self.options.rfile:
ret = self.load_flows(self.options.rfile) ret = self.load_flows(self.options.rfile)
if ret and self.state.flow_count(): if ret and self.state.flow_count():
self.add_event("File truncated or corrupted. Loaded as many flows as possible.") self.add_event("File truncated or corrupted. Loaded as many flows as possible.","error")
elif not self.state.flow_count(): elif not self.state.flow_count():
self.shutdown() self.shutdown()
print >> sys.stderr, "Could not load file:", ret print >> sys.stderr, "Could not load file:", ret
@ -1001,20 +1001,20 @@ class ConsoleMaster(flow.FlowMaster):
self.eventlist[:] = [] self.eventlist[:] = []
def add_event(self, e, level="info"): def add_event(self, e, level="info"):
if level == "info": needed = dict(error=1, info=1, debug=2).get(level, 1)
e = urwid.Text(str(e)) if self.o.verbosity < needed:
elif level == "error": return
if level == "error":
e = urwid.Text(("error", str(e))) e = urwid.Text(("error", str(e)))
else:
e = urwid.Text(str(e))
self.eventlist.append(e) self.eventlist.append(e)
if len(self.eventlist) > EVENTLOG_SIZE: if len(self.eventlist) > EVENTLOG_SIZE:
self.eventlist.pop(0) self.eventlist.pop(0)
self.eventlist.set_focus(len(self.eventlist)-1) self.eventlist.set_focus(len(self.eventlist)-1)
# Handlers # Handlers
def handle_log(self, l):
self.add_event(l.msg)
l.reply()
def handle_error(self, r): def handle_error(self, r):
f = flow.FlowMaster.handle_error(self, r) f = flow.FlowMaster.handle_error(self, r)
if f: if f:

View File

@ -490,7 +490,7 @@ def get_content_view(viewmode, hdrItems, content, limit, logfunc):
except Exception: except Exception:
s = traceback.format_exc() s = traceback.format_exc()
s = "Content viewer failed: \n" + s s = "Content viewer failed: \n" + s
logfunc(s) logfunc(s, "error")
ret = None ret = None
if not ret: if not ret:
ret = get("Raw")(hdrs, content, limit) ret = get("Raw")(hdrs, content, limit)

View File

@ -140,8 +140,8 @@ class DumpMaster(flow.FlowMaster):
raise DumpError(v.strerror) raise DumpError(v.strerror)
return flows return flows
def add_event(self, e, level="error"): def add_event(self, e, level="info"):
needed = dict(error=1, info=2, debug=3)[level] needed = dict(error=1, info=1, debug=2).get(level, 1)
if self.o.verbosity >= needed: if self.o.verbosity >= needed:
print >> self.outfile, e print >> self.outfile, e
self.outfile.flush() self.outfile.flush()
@ -196,10 +196,6 @@ class DumpMaster(flow.FlowMaster):
if self.o.flow_detail: if self.o.flow_detail:
self.outfile.flush() self.outfile.flush()
def handle_log(self, l):
self.add_event(l.msg)
l.reply()
def handle_request(self, r): def handle_request(self, r):
f = flow.FlowMaster.handle_request(self, r) f = flow.FlowMaster.handle_request(self, r)
if f: if f:

View File

@ -478,7 +478,7 @@ class FlowMaster(controller.Master):
"host": host, "host": host,
"port": port}).start() "port": port}).start()
def add_event(self, e, level="error"): def add_event(self, e, level="info"):
""" """
level: debug, info, error level: debug, info, error
""" """
@ -659,6 +659,10 @@ class FlowMaster(controller.Master):
if block: if block:
rt.join() rt.join()
def handle_log(self, l):
self.add_event(l.msg, l.level)
l.reply()
def handle_clientconnect(self, cc): def handle_clientconnect(self, cc):
self.run_script_hook("clientconnect", cc) self.run_script_hook("clientconnect", cc)
cc.reply() cc.reply()

View File

@ -861,7 +861,7 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
return HTTPResponse.from_stream(self.c.server_conn.rfile, request.method, return HTTPResponse.from_stream(self.c.server_conn.rfile, request.method,
body_size_limit=self.c.config.body_size_limit) body_size_limit=self.c.config.body_size_limit)
except (tcp.NetLibDisconnect, http.HttpErrorConnClosed), v: except (tcp.NetLibDisconnect, http.HttpErrorConnClosed), v:
self.c.log("error in server communication: %s" % str(v)) self.c.log("error in server communication: %s" % str(v), level="debug")
if i < 1: if i < 1:
# In any case, we try to reconnect at least once. # In any case, we try to reconnect at least once.
# This is necessary because it might be possible that we already initiated an upstream connection # This is necessary because it might be possible that we already initiated an upstream connection
@ -881,7 +881,7 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
try: try:
req = HTTPRequest.from_stream(self.c.client_conn.rfile, req = HTTPRequest.from_stream(self.c.client_conn.rfile,
body_size_limit=self.c.config.body_size_limit) body_size_limit=self.c.config.body_size_limit)
self.c.log("request", [req._assemble_first_line(req.form_in)]) self.c.log("request", "debug", [req._assemble_first_line(req.form_in)])
send_upstream = self.process_request(flow, req) send_upstream = self.process_request(flow, req)
if not send_upstream: if not send_upstream:
return True return True
@ -906,7 +906,7 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
flow.server_conn = self.c.server_conn # no further manipulation of self.c.server_conn beyond this point flow.server_conn = self.c.server_conn # no further manipulation of self.c.server_conn beyond this point
# we can safely set it as the final attribute value here. # we can safely set it as the final attribute value here.
self.c.log("response", [flow.response._assemble_first_line()]) self.c.log("response", "debug", [flow.response._assemble_first_line()])
response_reply = self.c.channel.ask("response", flow.response) response_reply = self.c.channel.ask("response", flow.response)
if response_reply is None or response_reply == KILL: if response_reply is None or response_reply == KILL:
return False return False
@ -946,7 +946,7 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
else: else:
err = error.__class__ err = error.__class__
self.c.log("error: %s" % err) self.c.log("error: %s" % err, level="info")
if flow: if flow:
flow.error = Error(err) flow.error = Error(err)
@ -985,21 +985,23 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
Hooking code isn't particulary beautiful, but it isolates this edge-case from Hooking code isn't particulary beautiful, but it isolates this edge-case from
the protocol-agnostic ConnectionHandler the protocol-agnostic ConnectionHandler
""" """
self.c.log("Hook reconnect function") self.c.log("Hook reconnect function", level="debug")
original_reconnect_func = self.c.server_reconnect original_reconnect_func = self.c.server_reconnect
def reconnect_http_proxy(): def reconnect_http_proxy():
self.c.log("Hooked reconnect function") self.c.log("Hooked reconnect function", "debug")
self.c.log("Hook: Run original reconnect") self.c.log("Hook: Run original reconnect", "debug")
original_reconnect_func(no_ssl=True) original_reconnect_func(no_ssl=True)
self.c.log("Hook: Write CONNECT request to upstream proxy", [upstream_request._assemble_first_line()]) self.c.log("Hook: Write CONNECT request to upstream proxy", "debug",
[upstream_request._assemble_first_line()])
self.c.server_conn.send(upstream_request._assemble()) self.c.server_conn.send(upstream_request._assemble())
self.c.log("Hook: Read answer to CONNECT request from proxy") self.c.log("Hook: Read answer to CONNECT request from proxy", "debug")
resp = HTTPResponse.from_stream(self.c.server_conn.rfile, upstream_request.method) resp = HTTPResponse.from_stream(self.c.server_conn.rfile, upstream_request.method)
if resp.code != 200: if resp.code != 200:
raise proxy.ProxyError(resp.code, raise proxy.ProxyError(resp.code,
"Cannot reestablish SSL connection with upstream proxy: \r\n" + str(resp.headers)) "Cannot reestablish SSL "
self.c.log("Hook: Establish SSL with upstream proxy") "connection with upstream proxy: \r\n" + str(resp.headers))
self.c.log("Hook: Establish SSL with upstream proxy", "debug")
self.c.establish_ssl(server=True) self.c.establish_ssl(server=True)
self.c.server_reconnect = reconnect_http_proxy self.c.server_reconnect = reconnect_http_proxy
@ -1008,11 +1010,11 @@ class HTTPHandler(ProtocolHandler, TemporaryServerChangeMixin):
""" """
Upgrade the connection to SSL after an authority (CONNECT) request has been made. Upgrade the connection to SSL after an authority (CONNECT) request has been made.
""" """
self.c.log("Received CONNECT request. Upgrading to SSL...") self.c.log("Received CONNECT request. Upgrading to SSL...", "debug")
self.expected_form_in = "relative" self.expected_form_in = "relative"
self.expected_form_out = "relative" self.expected_form_out = "relative"
self.c.establish_ssl(server=True, client=True) self.c.establish_ssl(server=True, client=True)
self.c.log("Upgrade to SSL completed.") self.c.log("Upgrade to SSL completed.", "debug")
def process_request(self, flow, request): def process_request(self, flow, request):

View File

@ -172,7 +172,7 @@ class TemporaryServerChangeMixin(object):
self.c.server_conn.address.port, self.c.server_conn.address.port,
address.host, address.host,
address.port address.port
)) ), "debug")
if not hasattr(self, "_backup_server_conn"): if not hasattr(self, "_backup_server_conn"):
self._backup_server_conn = self.c.server_conn self._backup_server_conn = self.c.server_conn
@ -193,7 +193,7 @@ class TemporaryServerChangeMixin(object):
self.c.server_conn.address.port, self.c.server_conn.address.port,
self._backup_server_conn.address.host, self._backup_server_conn.address.host,
self._backup_server_conn.address.port self._backup_server_conn.address.port
)) ), "debug")
self.c.del_server_connection() self.c.del_server_connection()
self.c.server_conn = self._backup_server_conn self.c.server_conn = self._backup_server_conn

View File

@ -45,7 +45,7 @@ class TCPHandler(ProtocolHandler):
data = data.getvalue() data = data.getvalue()
if data == "": # no data received, rfile is closed if data == "": # no data received, rfile is closed
self.c.log("Close writing connection to %s" % dst_str) self.c.log("Close writing connection to %s" % dst_str, "debug")
conns.remove(rfile) conns.remove(rfile)
if dst.ssl_established: if dst.ssl_established:
dst.connection.shutdown() dst.connection.shutdown()
@ -55,6 +55,6 @@ class TCPHandler(ProtocolHandler):
self.c.close = True self.c.close = True
break break
self.c.log("%s %s\r\n%s" % (direction, dst_str,data)) self.c.log("%s %s\r\n%s" % (direction, dst_str, data), "debug")
dst.wfile.write(data) dst.wfile.write(data)
dst.wfile.flush() dst.wfile.flush()

View File

@ -67,5 +67,6 @@ class AddressPriority(object):
class Log: class Log:
def __init__(self, msg): def __init__(self, msg, level):
self.msg = msg self.msg = msg
self.level = level

View File

@ -66,7 +66,7 @@ class ConnectionHandler:
self.sni = None self.sni = None
def handle(self): def handle(self):
self.log("clientconnect") self.log("clientconnect", "info")
self.channel.ask("clientconnect", self) self.channel.ask("clientconnect", self)
self.determine_conntype() self.determine_conntype()
@ -86,7 +86,7 @@ class ConnectionHandler:
try: try:
handle_messages(self.conntype, self) handle_messages(self.conntype, self)
except ConnectionTypeChange: except ConnectionTypeChange:
self.log("Connection Type Changed: %s" % self.conntype) self.log("Connection Type Changed: %s" % self.conntype, "info")
continue continue
# FIXME: Do we want to persist errors? # FIXME: Do we want to persist errors?
@ -94,14 +94,14 @@ class ConnectionHandler:
handle_error(self.conntype, self, e) handle_error(self.conntype, self, e)
except Exception, e: except Exception, e:
import traceback, sys import traceback, sys
self.log(traceback.format_exc()) self.log(traceback.format_exc(), "error")
print >> sys.stderr, traceback.format_exc() print >> sys.stderr, traceback.format_exc()
print >> sys.stderr, "mitmproxy has crashed!" print >> sys.stderr, "mitmproxy has crashed!"
print >> sys.stderr, "Please lodge a bug report at: https://github.com/mitmproxy/mitmproxy" print >> sys.stderr, "Please lodge a bug report at: https://github.com/mitmproxy/mitmproxy"
raise e raise e
self.del_server_connection() self.del_server_connection()
self.log("clientdisconnect") self.log("clientdisconnect", "info")
self.channel.tell("clientdisconnect", self) self.channel.tell("clientdisconnect", self)
def del_server_connection(self): def del_server_connection(self):
@ -110,7 +110,8 @@ class ConnectionHandler:
""" """
if self.server_conn and self.server_conn.connection: if self.server_conn and self.server_conn.connection:
self.server_conn.finish() self.server_conn.finish()
self.log("serverdisconnect", ["%s:%s" % (self.server_conn.address.host, self.server_conn.address.port)]) self.log("serverdisconnect", "debug", ["%s:%s" % (self.server_conn.address.host,
self.server_conn.address.port)])
self.channel.tell("serverdisconnect", self) self.channel.tell("serverdisconnect", self)
self.server_conn = None self.server_conn = None
self.sni = None self.sni = None
@ -129,7 +130,7 @@ class ConnectionHandler:
if self.server_conn: if self.server_conn:
if self.server_conn.priority > priority: if self.server_conn.priority > priority:
self.log("Attempt to change server address, " self.log("Attempt to change server address, "
"but priority is too low (is: %s, got: %s)" % (self.server_conn.priority, priority)) "but priority is too low (is: %s, got: %s)" % (self.server_conn.priority, priority), "info")
return return
if self.server_conn.address == address: if self.server_conn.address == address:
self.server_conn.priority = priority # Possibly increase priority self.server_conn.priority = priority # Possibly increase priority
@ -137,7 +138,7 @@ class ConnectionHandler:
self.del_server_connection() self.del_server_connection()
self.log("Set new server address: %s:%s" % (address.host, address.port)) self.log("Set new server address: %s:%s" % (address.host, address.port), "debug")
self.server_conn = ServerConnection(address, priority) self.server_conn = ServerConnection(address, priority)
def establish_server_connection(self): def establish_server_connection(self):
@ -147,7 +148,7 @@ class ConnectionHandler:
""" """
if self.server_conn.connection: if self.server_conn.connection:
return return
self.log("serverconnect", ["%s:%s" % self.server_conn.address()[:2]]) self.log("serverconnect", "debug", ["%s:%s" % self.server_conn.address()[:2]])
self.channel.tell("serverconnect", self) self.channel.tell("serverconnect", self)
try: try:
self.server_conn.connect() self.server_conn.connect()
@ -176,7 +177,7 @@ class ConnectionHandler:
subs.append("with client") subs.append("with client")
if server: if server:
subs.append("with server (sni: %s)" % self.sni) subs.append("with server (sni: %s)" % self.sni)
self.log("Establish SSL", subs) self.log("Establish SSL", "debug", subs)
if server: if server:
if self.server_conn.ssl_established: if self.server_conn.ssl_established:
@ -199,7 +200,7 @@ class ConnectionHandler:
had_ssl = self.server_conn.ssl_established had_ssl = self.server_conn.ssl_established
priority = self.server_conn.priority priority = self.server_conn.priority
sni = self.sni sni = self.sni
self.log("(server reconnect follows)") self.log("(server reconnect follows)", "debug")
self.del_server_connection() self.del_server_connection()
self.set_server_address(address, priority) self.set_server_address(address, priority)
self.establish_server_connection() self.establish_server_connection()
@ -210,14 +211,14 @@ class ConnectionHandler:
def finish(self): def finish(self):
self.client_conn.finish() self.client_conn.finish()
def log(self, msg, subs=()): def log(self, msg, level, subs=()):
msg = [ msg = [
"%s:%s: %s" % (self.client_conn.address.host, self.client_conn.address.port, msg) "%s:%s: %s" % (self.client_conn.address.host, self.client_conn.address.port, msg)
] ]
for i in subs: for i in subs:
msg.append(" -> " + i) msg.append(" -> " + i)
msg = "\n".join(msg) msg = "\n".join(msg)
self.channel.tell("log", Log(msg)) self.channel.tell("log", Log(msg, level))
def find_cert(self): def find_cert(self):
if self.config.certforward and self.server_conn.ssl_established: if self.config.certforward and self.server_conn.ssl_established:
@ -246,15 +247,17 @@ class ConnectionHandler:
sn = connection.get_servername() sn = connection.get_servername()
if sn and sn != self.sni: if sn and sn != self.sni:
self.sni = sn.decode("utf8").encode("idna") self.sni = sn.decode("utf8").encode("idna")
self.log("SNI received: %s" % self.sni) self.log("SNI received: %s" % self.sni, "debug")
self.server_reconnect() # reconnect to upstream server with SNI self.server_reconnect() # reconnect to upstream server with SNI
# Now, change client context to reflect changed certificate: # Now, change client context to reflect changed certificate:
new_context = SSL.Context(SSL.TLSv1_METHOD) new_context = SSL.Context(SSL.TLSv1_METHOD)
cert, key = self.find_cert() cert, key = self.find_cert()
new_context.use_privatekey_file(key) new_context.use_privatekey(key)
new_context.use_certificate(cert.X509) new_context.use_certificate(cert.x509)
connection.set_context(new_context) connection.set_context(new_context)
# An unhandled exception in this method will core dump PyOpenSSL, so # An unhandled exception in this method will core dump PyOpenSSL, so
# make dang sure it doesn't happen. # make dang sure it doesn't happen.
except Exception, e: # pragma: no cover except Exception, e: # pragma: no cover
import traceback
self.log("Error in handle_sni:\r\n" + traceback.format_exc(), "error")
pass pass

View File

@ -10,16 +10,15 @@ class ScriptContext:
def __init__(self, master): def __init__(self, master):
self._master = master self._master = master
def log(self, *args, **kwargs): def log(self, message, level="info"):
""" """
Logs an event. Logs an event.
How this is handled depends on the front-end. mitmdump will display By default, only events with level "error" get displayed. This can be controlled with the "-v" switch.
events if the v flag ("-e") was passed. mitmproxy sends How log messages are handled depends on the front-end. mitmdump will print them to stdout,
output to the eventlog for display ("e" keyboard shortcut). mitmproxy sends output to the eventlog for display ("e" keyboard shortcut).
""" """
#FIXME refactor_loglevel self._master.add_event(message, level)
self._master.add_event(*args, **kwargs)
def duplicate_flow(self, f): def duplicate_flow(self, f):
""" """