Beef up logging substantially.

5 files changed, 61 insertions, 30 deletions

diff --git a/libmproxy/console/__init__.py b/libmproxy/console/__init__.py
index 2e28b6cf..8686c974 100644
--- a/libmproxy/console/__init__.py
+++ b/libmproxy/console/__init__.py
@@ -948,6 +948,10 @@ class ConsoleMaster(flow.FlowMaster):
         self.eventlist.set_focus(len(self.eventlist))
 
     # Handlers
+    def handle_log(self, l):
+        self.add_event(l.msg)
+        l._ack()
+
     def handle_error(self, r):
         f = flow.FlowMaster.handle_error(self, r)
         if f:
diff --git a/libmproxy/dump.py b/libmproxy/dump.py
index 36f54608..ea4ac0b3 100644
--- a/libmproxy/dump.py
+++ b/libmproxy/dump.py
@@ -144,6 +144,10 @@ class DumpMaster(flow.FlowMaster):
         if self.eventlog:
             print >> self.outfile, e
 
+    def handle_log(self, l):
+        self.add_event(l.msg)
+        l._ack()
+
     def handle_request(self, r):
         f = flow.FlowMaster.handle_request(self, r)
         if f:
diff --git a/libmproxy/flow.py b/libmproxy/flow.py
index 4de8bc96..a93f8e24 100644
--- a/libmproxy/flow.py
+++ b/libmproxy/flow.py
@@ -637,7 +637,7 @@ class ClientConnect(controller.Msg):
             address: (address, port) tuple, or None if the connection is replayed.
             requestcount: Number of requests created by this client connection.
             close: Is the client connection closed?
-            connection_error: Error string or None.
+            error: Error string or None.
     """
     def __init__(self, address):
         """
@@ -647,7 +647,7 @@ class ClientConnect(controller.Msg):
         self.address = address
         self.close = False
         self.requestcount = 0
-        self.connection_error = None
+        self.error = None
         controller.Msg.__init__(self)
 
     def __eq__(self, other):
@@ -1388,20 +1388,10 @@ class FlowMaster(controller.Master):
 
     def handle_clientconnect(self, cc):
         self.run_script_hook("clientconnect", cc)
-        self.add_event("Connect from: %s:%s"%cc.address)
         cc._ack()
 
     def handle_clientdisconnect(self, r):
         self.run_script_hook("clientdisconnect", r)
-        s = "Disconnect from: %s:%s"%r.client_conn.address
-        self.add_event(s)
-        if r.client_conn.requestcount:
-            s = "    -> handled %s requests"%r.client_conn.requestcount
-            self.add_event(s)
-        if r.client_conn.connection_error:
-            self.add_event(
-                "   -> error: %s"%r.client_conn.connection_error, "error"
-            )
         r._ack()
 
     def handle_error(self, r):
diff --git a/libmproxy/proxy.py b/libmproxy/proxy.py
index 3ec22fb4..6ab1d489 100644
--- a/libmproxy/proxy.py
+++ b/libmproxy/proxy.py
@@ -16,8 +16,8 @@ import sys, os, string, socket, time
 import shutil, tempfile, threading
 import optparse, SocketServer
 from OpenSSL import SSL
-from netlib import odict, tcp, http, wsgi, certutils
-import utils, flow, version, platform
+from netlib import odict, tcp, http, wsgi, certutils, http_status
+import utils, flow, version, platform, controller
 
 
 class ProxyError(Exception):
@@ -28,6 +28,13 @@ class ProxyError(Exception):
         return "ProxyError(%s, %s)"%(self.code, self.msg)
 
 
+class Log(controller.Msg):
+    def __init__(self, msg):
+        controller.Msg.__init__(self)
+        self.msg = msg
+
+
+
 class ProxyConfig:
     def __init__(self, certfile = None, cacert = None, clientcerts = None, cert_wait_time=0, upstream_cert=False, body_size_limit = None, reverse_proxy=None, transparent_proxy=None):
         assert not (reverse_proxy and transparent_proxy)
@@ -114,11 +121,18 @@ class ProxyHandler(tcp.BaseHandler):
 
     def handle(self):
         cc = flow.ClientConnect(self.client_address)
+        self.log(cc, "connect")
         cc._send(self.mqueue)
         while self.handle_request(cc) and not cc.close:
             pass
         cc.close = True
         cd = flow.ClientDisconnect(cc)
+
+        self.log(
+            cc, "disconnect",
+            [
+                "handled %s requests"%cc.requestcount]
+        )
         cd._send(self.mqueue)
 
     def server_connect(self, scheme, host, port):
@@ -182,17 +196,37 @@ class ProxyHandler(tcp.BaseHandler):
                 # disconnect.
                 if http.response_connection_close(response.httpversion, response.headers):
                     return
-        except IOError, v:
-            cc.connection_error = v
-        except (ProxyError, http.HttpError), e:
-            cc.connection_error = "%s: %s"%(e.code, e.msg)
+        except (IOError, ProxyError, http.HttpError), e:
+            if isinstance(e, IOError):
+                cc.error = str(e)
+            else:
+                cc.error = "%s: %s"%(e.code, e.msg)
+
             if request:
-                err = flow.Error(request, e.msg)
+                err = flow.Error(request, cc.error)
                 err._send(self.mqueue)
-            self.send_error(e.code, e.msg)
+                self.log(
+                    cc, cc.error,
+                    ["url: %s"%request.get_url()]
+                )
+            else:
+                self.log(cc, cc.error)
+
+            if isinstance(e, ProxyError):
+                self.send_error(e.code, e.msg)
         else:
             return True
 
+    def log(self, cc, msg, subs=()):
+        msg = [
+            "%s:%s: "%cc.address + msg
+        ]
+        for i in subs:
+            msg.append("  -> "+i)
+        msg = "\n".join(msg)
+        l = Log(msg)
+        l._send(self.mqueue)
+
     def find_cert(self, host, port, sni):
         if self.config.certfile:
             return self.config.certfile
@@ -235,7 +269,7 @@ class ProxyHandler(tcp.BaseHandler):
                 return None
             r = http.parse_init_http(line)
             if not r:
-                raise ProxyError(400, "Bad HTTP request line: %s"%line)
+                raise ProxyError(400, "Bad HTTP request line: %s"%repr(line))
             method, path, httpversion = r
             headers = http.read_headers(self.rfile)
             content = http.read_http_body_request(
@@ -249,7 +283,7 @@ class ProxyHandler(tcp.BaseHandler):
             scheme, host, port = self.config.reverse_proxy
             r = http.parse_init_http(line)
             if not r:
-                raise ProxyError(400, "Bad HTTP request line: %s"%line)
+                raise ProxyError(400, "Bad HTTP request line: %s"%repr(line))
             method, path, httpversion = r
             headers = http.read_headers(self.rfile)
             content = http.read_http_body_request(
@@ -263,7 +297,7 @@ class ProxyHandler(tcp.BaseHandler):
             if line.startswith("CONNECT"):
                 r = http.parse_init_connect(line)
                 if not r:
-                    raise ProxyError(400, "Bad HTTP request line: %s"%line)
+                    raise ProxyError(400, "Bad HTTP request line: %s"%repr(line))
                 host, port, httpversion = r
                 # FIXME: Discard additional headers sent to the proxy. Should I expose
                 # these to users?
@@ -285,7 +319,7 @@ class ProxyHandler(tcp.BaseHandler):
                 host, port, httpversion = self.proxy_connect_state
                 r = http.parse_init_http(line)
                 if not r:
-                    raise ProxyError(400, "Bad HTTP request line: %s"%line)
+                    raise ProxyError(400, "Bad HTTP request line: %s"%repr(line))
                 method, path, httpversion = r
                 headers = http.read_headers(self.rfile)
                 content = http.read_http_body_request(
@@ -295,7 +329,7 @@ class ProxyHandler(tcp.BaseHandler):
             else:
                 r = http.parse_init_proxy(line)
                 if not r:
-                    raise ProxyError(400, "Bad HTTP request line: %s"%line)
+                    raise ProxyError(400, "Bad HTTP request line: %s"%repr(line))
                 method, scheme, host, port, path, httpversion = http.parse_init_proxy(line)
                 headers = http.read_headers(self.rfile)
                 content = http.read_http_body_request(
@@ -312,8 +346,7 @@ class ProxyHandler(tcp.BaseHandler):
 
     def send_error(self, code, body):
         try:
-            import BaseHTTPServer
-            response = BaseHTTPServer.BaseHTTPRequestHandler.responses[code][0]
+            response = http_status.RESPONSES.get(code, "Unknown")
             self.wfile.write("HTTP/1.1 %s %s\r\n" % (code, response))
             self.wfile.write("Server: %s\r\n"%version.NAMEVERSION)
             self.wfile.write("Connection: close\r\n")
diff --git a/test/test_server.py b/test/test_server.py
index e4a62fa5..1f83c496 100644
--- a/test/test_server.py
+++ b/test/test_server.py
@@ -55,6 +55,6 @@ class TestProxy(tutils.HTTPProxTest):
         assert f.status_code == 304
 
         l = self.log()
-        assert l[0].address
-        assert "host" in l[1].headers
-        assert l[2].code == 304
+        assert l[1].address
+        assert "host" in l[2].headers
+        assert l[3].code == 304