feat(debug) add a socket debug function (experimental) (#123)

Makefile

@@ -55,7 +55,7 @@ test: certs
 	$(LUA) $(DELIM) $(PKGPATH) tests/removeserver.lua
 	$(LUA) $(DELIM) $(PKGPATH) tests/removethread.lua
 	$(LUA) $(DELIM) $(PKGPATH) tests/request.lua 'http://www.google.com'
-	$(LUA) $(DELIM) $(PKGPATH) tests/request.lua 'https://www.google.nl'
+	$(LUA) $(DELIM) $(PKGPATH) tests/request.lua 'https://www.google.nl' true
 	$(LUA) $(DELIM) $(PKGPATH) tests/semaphore.lua
 	$(LUA) $(DELIM) $(PKGPATH) tests/sleep.lua
 	$(LUA) $(DELIM) $(PKGPATH) tests/tcptimeout.lua

docs/index.html

@@ -123,6 +123,7 @@ <h2><a name="history"></a>History</h2>
                 <code>copas.setthreadname()</code>, <code>copas.getthreadname()</code> added to manage names</li>
                 <li><code>copas.debug.start()</code> and <code>copas.debug.end()</code> to enable debug
                 logging for the scheduler itself.</li>
+                <li><code>copas.debug.socket()</code> to enable debug logging for socket methods (experimental).</li>
             </ul>
         </li>
 	</ul></dd>

docs/reference.html

@@ -704,6 +704,15 @@ <h3>Copas debugging functions</h3>
     <dd>Stops the debug output being generated.
     </dd>
 
+    <dt><strong><code>debug_socket = copas.debug.socket(socket)</code></strong></dt>
+    <dd>This wraps the socket in a debug-wrapper. This will for each method call on the
+    socket object print the method, the parameters and the return values. Check the source
+    code on how to add additional introspection using extra callbacks etc.<br />
+    <p>Extremely noisy and experimental!</p>
+    <p>NOTE 1: for TLS you'll probably need to first do the TLS handshake.</p>
+    <p>NOTE 2: this is separate from the other debugging functions.</p>
+    </dd>
+
 </dl>
 
 

src/copas.lua

@@ -930,7 +930,9 @@ function copas.wrap (skt, sslt)
   if (getmetatable(skt) == _skt_mt_tcp) or (getmetatable(skt) == _skt_mt_udp) then
     return skt -- already wrapped
   end
+
   skt:settimeout(0)
+
   if isTCP(skt) then
     return setmetatable ({socket = skt, ssl_params = normalize_sslt(sslt)}, _skt_mt_tcp)
   else
@@ -1546,6 +1548,7 @@ do
   debug_log = function() end
 
 
+  -- enables debug output for all coroutine operations.
   function copas.debug.start(logger, core)
     log_core = core
     debug_log = logger or print
@@ -1555,13 +1558,156 @@ do
   end
 
 
+  -- disables debug output for coroutine operations.
   function copas.debug.stop()
     debug_log = function() end
     coroutine_yield = coroutine.yield
     coroutine_resume = coroutine.resume
     coroutine_create = coroutine.create
   end
 
+  do
+    local call_id = 0
+
+    -- Description table of socket functions for debug output.
+    -- each socket function name has TWO entries;
+    -- 'name_in' and 'name_out', each being an array of names/descriptions of respectively
+    -- input parameters and return values.
+    -- If either table has a 'callback' key, then that is a function that will be called
+    -- with the parameters/return-values for further inspection.
+    local args = {
+      settimeout_in = {
+        "socket ",
+        "seconds",
+        "mode   ",
+      },
+      settimeout_out = {
+        "success",
+        "error  ",
+      },
+      connect_in = {
+        "socket ",
+        "address",
+        "port   ",
+      },
+      connect_out = {
+        "success",
+        "error  ",
+      },
+      getfd_in = {
+        "socket ",
+        -- callback = function(...)
+        --   print(debug.traceback("called from:", 4))
+        -- end,
+      },
+      getfd_out = {
+        "fd",
+      },
+      send_in = {
+        "socket   ",
+        "data     ",
+        "idx-start",
+        "idx-end  ",
+      },
+      send_out = {
+        "last-idx-send    ",
+        "error            ",
+        "err-last-idx-send",
+      },
+      receive_in = {
+        "socket ",
+        "pattern",
+        "prefix ",
+      },
+      receive_out = {
+        "received    ",
+        "error       ",
+        "partial data",
+      },
+      dirty_in = {
+        "socket",
+        -- callback = function(...)
+        --   print(debug.traceback("called from:", 4))
+        -- end,
+      },
+      dirty_out = {
+        "data in read-buffer",
+      },
+      close_in = {
+        "socket",
+        -- callback = function(...)
+        --   print(debug.traceback("called from:", 4))
+        -- end,
+      },
+      close_out = {
+        "success",
+        "error",
+      },
+    }
+    local function print_call(func, msg, ...)
+      print(msg)
+      local arg = pack(...)
+      local desc = args[func] or {}
+      for i = 1, math.max(arg.n, #desc) do
+        local value = arg[i]
+        if type(value) == "string" then
+          print("\t"..(desc[i] or i)..": '"..tostring(value).."' ("..type(value).." #"..#value..")")
+        else
+          print("\t"..(desc[i] or i)..": '"..tostring(value).."' ("..type(value)..")")
+        end
+      end
+      if desc.callback then
+        desc.callback(...)
+      end
+    end
+
+    local debug_mt = {
+      __index = function(self, key)
+        local value = self.__original_socket[key]
+        if type(value) ~= "function" then
+          return value
+        end
+        return function(self2, ...)
+            local my_id = call_id + 1
+            call_id = my_id
+            local results
+
+            if self2 ~= self then
+              -- there is no self
+              print_call(tostring(key).."_in", my_id .. "-calling '"..tostring(key) .. "' with; ", self, ...)
+              results = pack(value(self, ...))
+            else
+              print_call(tostring(key).."_in", my_id .. "-calling '" .. tostring(key) .. "' with; ", self.__original_socket, ...)
+              results = pack(value(self.__original_socket, ...))
+            end
+            print_call(tostring(key).."_out", my_id .. "-results '"..tostring(key) .. "' returned; ", unpack(results))
+            return unpack(results)
+          end
+      end,
+      __tostring = function(self)
+        return tostring(self.__original_socket)
+      end
+    }
+
+
+    -- wraps a socket (copas or luasocket) in a debug version printing all calls
+    -- and their parameters/return values. Extremely noisy!
+    -- returns the wrapped socket.
+    -- NOTE: only for plain sockets, will not support TLS
+    function copas.debug.socket(original_skt)
+      if (getmetatable(original_skt) == _skt_mt_tcp) or (getmetatable(original_skt) == _skt_mt_udp) then
+        -- already wrapped as Copas socket, so recurse with the original luasocket one
+        original_skt.socket = copas.debug.socket(original_skt.socket)
+        return original_skt
+      end
+
+      local proxy = setmetatable({
+        __original_socket = original_skt
+      }, debug_mt)
+
+      return proxy
+    end
+  end
 end
 
 

tests/request.lua

@@ -2,10 +2,27 @@ local copas = require("copas")
 local http = require("copas.http")
 
 local url = assert(arg[1], "missing url argument")
-print("Testing copas.http.request with url " .. url)
+local debug_mode = not not arg[2]
+
+print("Testing copas.http.request with url " .. url .. (debug_mode and "(in debug mode)" or ""))
 local switches, max_switches = 0, 10000000
 local done = false
 
+
+if debug_mode then
+  copas.debug.start()
+  local socket = require "socket"
+  local old_tcp = socket.tcp
+  socket.tcp = function(...)
+    local sock, err = old_tcp(...)
+    if not sock then
+      return sock, err
+    end
+    return copas.debug.socket(sock)
+  end
+end
+
+
 copas.addthread(function()
   while switches < max_switches do
     copas.sleep(0)