Improve websocket logging

5 files changed, 40 insertions, 32 deletions

diff --git a/libpathod/language/__init__.py b/libpathod/language/__init__.py
index 52ccf61c..48466fa6 100644
--- a/libpathod/language/__init__.py
+++ b/libpathod/language/__init__.py
@@ -2,7 +2,7 @@ import time
 
 import pyparsing as pp
 
-from . import base, http, websockets, writer, exceptions
+from . import http, websockets, writer, exceptions
 
 from exceptions import *
 from base import Settings
diff --git a/libpathod/language/websockets.py b/libpathod/language/websockets.py
index 96dbce53..a42dfc2f 100644
--- a/libpathod/language/websockets.py
+++ b/libpathod/language/websockets.py
@@ -93,6 +93,7 @@ COMPONENTS = (
 class WebsocketFrame(message.Message):
     components = COMPONENTS
     logattrs = ["body"]
+    # Used for nested frames
     unique_name = "body"
 
     @property
diff --git a/libpathod/pathoc.py b/libpathod/pathoc.py
index f7268193..cb954e15 100644
--- a/libpathod/pathoc.py
+++ b/libpathod/pathoc.py
@@ -347,8 +347,8 @@ class Pathoc(tcp.TCPClient):
         """
             Performs a single request.
 
-            r: A language.http.Request object, or a string representing one
-            request.
+            r: A language.message.Messsage object, or a string representing
+            one.
 
             Returns Response if we have a non-ignored response.
 
diff --git a/libpathod/pathod.py b/libpathod/pathod.py
index abce15fe..3cd63162 100644
--- a/libpathod/pathod.py
+++ b/libpathod/pathod.py
@@ -5,6 +5,7 @@ import sys
 import threading
 import urllib
 import re
+import time
 
 from netlib import tcp, http, wsgi, certutils, websockets
 
@@ -106,42 +107,52 @@ class PathodHandler(tcp.BaseHandler):
         lw = self.wfile if self.server.logresp else None
         while True:
             with log.Log(self.logfp, self.server.hexdump, lr, lw) as lg:
+                started = time.time()
                 try:
                     frm = websockets.Frame.from_file(self.rfile)
                 except tcp.NetLibIncomplete, e:
                     lg("Error reading websocket frame: %s"%e)
                     break
+                ended = time.time()
                 lg(frm.human_readable())
-                retlog = dict(
-                    type="wsframe",
-                    frame=dict(
-                    ),
-                    cipher=None,
-                )
-                ld = language.websockets.NESTED_LEADER
-                if frm.payload.startswith(ld):
-                    nest = frm.payload[len(ld):]
-                    try:
-                        wf = language.parse_websocket_frame(nest)
-                    except language.exceptions.ParseException, v:
-                        lg(
-                            "Parse error in reflected frame specifcation:"
-                            " %s" % v.msg
-                        )
-                        break
+            retlog = dict(
+                type = "inbound",
+                protocol = "websockets",
+                started = started,
+                duration = ended - started,
+                frame = dict(
+                ),
+                cipher=None,
+            )
+            if self.ssl_established:
+                retlog["cipher"] = self.get_current_cipher()
+            self.addlog(retlog)
+            ld = language.websockets.NESTED_LEADER
+            if frm.payload.startswith(ld):
+                nest = frm.payload[len(ld):]
+                try:
+                    wf = language.parse_websocket_frame(nest)
+                except language.exceptions.ParseException, v:
+                    lg(
+                        "Parse error in reflected frame specifcation:"
+                        " %s" % v.msg
+                    )
+                    break
+                with log.Log(self.logfp, self.server.hexdump, lr, lw) as lg:
                     frame_log = language.serve(
                         wf,
                         self.wfile,
                         self.settings
                     )
-                self.addlog(retlog)
+                    lg("crafting websocket spec: %s" % frame_log["spec"])
+                    self.addlog(frame_log)
         return self.handle_websocket, None
 
     def handle_http_connect(self, connect, lg):
         """
             Handle a CONNECT request.
         """
-        headers = http.read_headers(self.rfile)
+        http.read_headers(self.rfile)
         self.wfile.write(
             'HTTP/1.1 200 Connection established\r\n' +
             ('Proxy-agent: %s\r\n' % version.NAMEVERSION) +
@@ -237,6 +248,7 @@ class PathodHandler(tcp.BaseHandler):
 
             retlog = dict(
                 type="crafted",
+                protocol="http",
                 request=dict(
                     path=path,
                     method=method,
diff --git a/test/test_pathod.py b/test/test_pathod.py
index c7ea47e3..d3013692 100644
--- a/test/test_pathod.py
+++ b/test/test_pathod.py
@@ -1,8 +1,7 @@
 import cStringIO
 from libpathod import pathod, version
 from netlib import tcp, http
-import time
-import sys
+import pprint
 
 import tutils
 
@@ -211,14 +210,10 @@ class CommonTests(tutils.DaemonTests):
         assert r.status_code == 101
 
     def test_websocket_frame(self):
-        r = self.pathoc(["ws:/p/", "wf:b@10"], ws_read_limit=0)
-        print >> sys.stderr, r
-        print >> sys.stderr, self.d.log()
-        assert self.d.last_log()["type"] == "wsframe"
-
-    def test_websocket_reflected_frame(self):
-        r = self.pathoc(["ws:/p/", "wf:f'wf'"], ws_read_limit=0)
-        assert r
+        r = self.pathoc(["ws:/p/", "wf:f'wf'"], ws_read_limit=1)
+        #print r
+        #pprint.pprint(r)
+        #pprint.pprint(self.d.log())
 
 
 class TestDaemon(CommonTests):