Merge branch 'diagnosis'

11 files changed, 289 insertions, 39 deletions

diff --git a/Makefile b/Makefile
index 2228776..639aaae 100644
--- a/Makefile
+++ b/Makefile
@@ -1,7 +1,7 @@
 all: test
 
 LMODULES := supple supple.request supple.objects supple.sandbox \
-	    supple.host supple.comms
+	    supple.host supple.comms supple.track
 CMODULES := supple.capi
 MODULES := $(LMODULES) $(CMODULES)
 LUA_VER := 5.1
diff --git a/example/simple-example.lua b/example/simple-example.lua
index 1d82944..6f35400 100644
--- a/example/simple-example.lua
+++ b/example/simple-example.lua
@@ -41,39 +41,55 @@ local mt = {
 
 setmetatable(tab, mt)
 
-local function lprint(...)
+local tests, passed = 0, 0
+
+local function lprint(expect, result, ...)
+   tests = tests + 1
+   luxio.write(1, ("[%d]\r"):format(tests))
    local foo = {n=select("#",...),...}
-   if foo[1] then
-      print "Function ran OK:"
-   else
-      print "Error encountered:"
+   if expect and not result then
+      print "Want OK, got FAIL"
+   elseif (not expect) and result then
+      print "Want FAIL, got OK"
    end
-   for i = 2, foo.n do
-      if type(foo[i]) == "table" then
-	 print("{")
-	 for k, v in pairs(foo[i]) do
-	    print("",k,v)
+   if expect ~= result then
+      for i = 1, foo.n do
+	 if type(foo[i]) == "table" then
+	    print("{")
+	    for k, v in pairs(foo[i]) do
+	       print("",k,v)
+	    end
+	    print("}")
+	 else
+	    print(foo[i])
 	 end
-	 print("}")
-      else
-	 print(foo[i])
       end
+      print()
+   else
+      passed = passed + 1
    end
-   print()
+end
+
+local function lprint_ok(...)
+   return lprint(true, ...)
+end
+
+local function lprint_fail(...)
+   return lprint(false, ...)
 end
 
 -- Finally, run the subcode
-lprint(supple.host.run(subcode, "@test-code", tab))
+lprint_ok(supple.host.run(subcode, "@test-code", tab))
 assert(tab.tot == 24)
 
 -- Now run a supple command which we expect to error out.
-lprint(supple.host.run("unknown()", "@test-code"))
+lprint_fail(supple.host.run("unknown()", "@test-code"))
 
 -- And now, one where we pass an error from host to sandbox and back
-lprint(supple.host.run("local f = ... f()", "@test-code", function() unknown() end))
+lprint_fail(supple.host.run("local f = ... f()", "@test-code", function() unknown() end))
 
 -- And now, one where we pass an error from sandbox to host to sandbox and back
-lprint(supple.host.run("local f = ... f(function() unknown() end)", "@test-code", function(ff) ff() end))
+lprint_fail(supple.host.run("local f = ... f(function() unknown() end)", "@test-code", function(ff) ff() end))
 
 -- Next , a reasonable traceback via named functions on each end...
 
@@ -99,7 +115,7 @@ function loopback(f)
    f(loopback)
 end
 
-lprint(supple.host.run(errsrc, "@error-code", loopback))
+lprint_fail(supple.host.run(errsrc, "@error-code", loopback))
 
 -- Now we try the sandboxing limits
 
@@ -112,9 +128,9 @@ local long_run = [[
 ]]
 
 supple.host.set_limits { count = 100 }
-lprint(supple.host.run(long_run, "@long-code"))
+lprint_fail(supple.host.run(long_run, "@long-code"))
 supple.host.set_limits { memory = 1000 }
-lprint(supple.host.run(long_run, "@big-code"))
+lprint_fail(supple.host.run(long_run, "@big-code"))
 
 
 -- next we demonstrate that ipairs works on proxied tables
@@ -128,7 +144,7 @@ local summing = [[
       return tot
 ]]
 
-lprint(supple.host.run(summing, "@summing", { 10, 14, 3 }))
+lprint_ok(supple.host.run(summing, "@summing", { 10, 14, 3 }))
 
 -- next we demonstrate that next works on proxied tables
 
@@ -137,8 +153,8 @@ local isempty = [[
       return next(t) == nil
 ]]
 
-lprint(supple.host.run(isempty, "@isempty", {}))
-lprint(supple.host.run(isempty, "@isempty", {"bar"}))
+lprint_ok(supple.host.run(isempty, "@isempty", {}))
+lprint_ok(supple.host.run(isempty, "@isempty", {"bar"}))
 
 -- And now that pairs works on proxied tables
 
@@ -152,7 +168,7 @@ local keys = [[
       return ret
 ]]
 
-lprint(supple.host.run(keys, "@keys", { foo="bar", baz="meta" }))
+lprint_ok(supple.host.run(keys, "@keys", { foo="bar", baz="meta" }))
 
 -- Next demonstrate that using supple.host.loadstring works to allow
 -- globals set in the parent to be seen/changed
@@ -168,4 +184,38 @@ local getname = [[
 ]]
 
 -- Expect to see 'PRINT'
-lprint(supple.host.run(getname, "@getname", loader))
+lprint_ok(supple.host.run(getname, "@getname", loader))
+
+-- Attempt to do a test which shows the same issue as seen with gitano-web
+
+local updates = {
+   ["refs/heads/master"] = {
+      oldsha = "0123456789abcdef0123456789abcdef01234567",
+      newsha = "76543210fedcba9876543210fedcba9876543210",
+   }
+}
+
+local update_code = [[
+      local repo, updates = ...
+      local hadmaster = false
+      local foundrefs = {}
+      if updates["refs/heads/master"] then
+	 hadmaster = true
+      end
+      for ref, data in pairs(updates) do
+	 foundrefs[ref] = { data.oldsha, data.newsha }
+      end
+      return hadmaster, foundrefs
+]]
+
+for i = 1, 1000 do
+   lprint_ok(supple.host.run(update_code, "@update-hook", "REPO", updates))
+   if passed ~= tests then
+      os.exit(1)
+   end
+end
+
+print(("[%d/%d OK]"):format(passed, tests))
+
+-- Dump the final trace, just for edification
+--print(supple.track.stop())
diff --git a/lib/supple.lua b/lib/supple.lua
index 9cb2d8a..513d3ac 100644
--- a/lib/supple.lua
+++ b/lib/supple.lua
@@ -13,6 +13,7 @@ local objects = require 'supple.objects'
 local comms = require 'supple.comms'
 local sandbox = require 'supple.sandbox'
 local host = require 'supple.host'
+local track = require 'supple.track'
 
 local _VERSION = 1
 local _ABI = 1
@@ -26,6 +27,7 @@ return {
    comms = comms,
    sandbox = sandbox,
    host = host,
+   track = track,
    _VERSION = _VERSION,
    VERSION = VERSION,
    _ABI = _ABI,
diff --git a/lib/supple/capi.c b/lib/supple/capi.c
index 38c4f27..34e6169 100644
--- a/lib/supple/capi.c
+++ b/lib/supple/capi.c
@@ -181,7 +181,7 @@ supple_capi_lockdown(lua_State *L)
 	char *tempdir;
 	struct rlimit lim;
 	lua_settop(L, 0); /* Discard any arguments */
-	
+
 	/* Prepare a copy of the tempdir template ready */
 	tempdir = lua_newuserdata(L, strlen(TEMPDIR_NAME));
 	strcpy(tempdir, TEMPDIR_NAME);
diff --git a/lib/supple/comms.lua b/lib/supple/comms.lua
index e72f8f1..ae2779c 100644
--- a/lib/supple/comms.lua
+++ b/lib/supple/comms.lua
@@ -14,6 +14,7 @@ local luxio = require "luxio"
 local capi = require "supple.capi"
 local request = require "supple.request"
 local objects = require "supple.objects"
+local track = require "supple.track"
 
 local unpack = unpack
 local tonumber = tonumber
@@ -34,6 +35,7 @@ local function send_msg(msg)
       error("Message too long")
    end
    local msglen = ("%05d"):format(#msg)
+   track.record("XMIT", msg)
    luxio.write(fd, msglen .. msg)
 end
 
@@ -53,6 +55,7 @@ local function recv_msg()
    if type(str) ~= "string" or #str ~= len then
       error("Unable to read " .. tostring(len) .. " bytes of msg")
    end
+   track.record("RECV", str)
    return str
 end
 
@@ -64,7 +67,8 @@ local function captcha(msg)
       return info.short_src:match("/supple/[^%.]+%.lua$")
    end
    while info and info.func ~= xpcall do
-      if info.currentline > 0 and not in_supple() then
+--      if info.currentline > 0 and not in_supple() then
+      if true then
 	 local ttype, tag = objects.find_tag(info.func)
 	 if ttype then
 	    info.name = tag
@@ -78,7 +82,7 @@ local function captcha(msg)
       level = level + 1
       info = getinfo(level, "Snlf")
    end
-   return {msg, concat(traceback, "\n") or ""}
+   return {msg, (concat(traceback, "\n") or "") .. "\nComms track:\n" .. track.stop()}
 end
 
 local limits = {}
@@ -111,7 +115,23 @@ end
 
 local function wait_for_response()
    repeat
+      -- We *MUST* disable GC for the duration of receiving and parsing the
+      -- message, lest we send a __gc transaction between the first and second
+      -- read operations.  Or indeed if we GC and object between receiving the
+      -- message and deserialising and thus anchoring the object. If we error
+      -- out here, we don't really care about restarting gc since we won't
+      -- survive long anyhow.
+      gc "stop"
+      -- Also anchor all the objects just in case
+      local anchor = objects.get_object_anchor()
+      -- Now receive and deserialise (thus anchoring relevant objects)
       local back = request.deserialise(recv_msg())
+      -- Now that the request is anchored, release the extra anchor and
+      -- re-allow GC
+      anchor = nil
+      gc "restart"
+      -- And get on with parsing the message we received..
+
       -- back could be three things
       -- an error (raise it)
       if back.error then
@@ -182,9 +202,12 @@ local function wait_for_response()
 end
 
 local function make_call(object, method, ...)
+   track.enter("make_call", object, method)
    local req = request.request(object, method, ...)
    send_msg(req)
-   return wait_for_response()
+   local ret = {wait_for_response()}
+   track.leave("make_call", object, method)
+   return unpack(ret)
 end
 
 local function set_limits(newlimits)
diff --git a/lib/supple/host.lua b/lib/supple/host.lua
index 617b365..596fba1 100644
--- a/lib/supple/host.lua
+++ b/lib/supple/host.lua
@@ -15,6 +15,7 @@ local subprocess = require 'luxio.subprocess'
 local comms = require 'supple.comms'
 local objects = require 'supple.objects'
 local capi = require 'supple.capi'
+local track = require 'supple.track'
 
 local hostname = "host"
 local counter = 0
@@ -80,6 +81,8 @@ local function run_sandbox(codestr, codename, ...)
    objects.set_name(("host[%d,%%d]"):format(counter))
    comms._set_fd(commsfd)
    objects.set_proc_call(comms.call)
+
+   track.start()
    
    local func, env = comms.call("supple:loadstring", "__call", codestr, codename)
    if not func then
@@ -120,12 +123,12 @@ local function run_sandbox(codestr, codename, ...)
    objects.clean_down(true)
 
    comms._set_fd(-1)
-   luxio.kill(child.pid, luxio.SIGKILL)
+   luxio.close(commsfd)
    child:wait()
    if ok then
       return ok, unpack(ret)
    else
-      return ok, err
+      return ok, err .. "\n\nHost comms track:\n" .. track.stop()
    end
 end
 
diff --git a/lib/supple/objects.lua b/lib/supple/objects.lua
index 5a5dfca..2f5da79 100644
--- a/lib/supple/objects.lua
+++ b/lib/supple/objects.lua
@@ -12,18 +12,22 @@
 local gc = collectgarbage
 
 local capi = require 'supple.capi'
+local track = require 'supple.track'
 
 local my_objects_by_obj = {}
 local my_objects_by_tag = {}
+local my_objects_expn_by_tag = {}
 local my_name = "UNSET"
 local my_counter = 0
 local their_objects_by_tag = setmetatable({}, { __mode="v" })
 local their_objects_by_obj = setmetatable({}, { __mode="k" })
+local their_objects_refcnt = {}
 local proc_call = nil
 
 local type = capi.rawtype
 
 local function clean_down(call_other_end)
+   track.enter("clean_down")
    -- And force a full GC
    gc "collect"
    gc "collect"
@@ -35,6 +39,8 @@ local function clean_down(call_other_end)
    -- And forget all our local objects
    my_objects_by_obj = {}
    my_objects_by_tag = {}
+   my_objects_expn_by_tag = {}
+   track.leave("clean_down")
 end
 
 local function set_name(newname)
@@ -76,21 +82,26 @@ local function give(obj, special_tag)
    end
    -- If the passed object is one of their objects then "unwrap" it by
    -- returning their tag.
+   track.enter("give", tostring(obj), tostring(special_tag))
    local tag = their_objects_by_obj[obj];
    if tag then
+      track.leave("give", "theirs", tag)
       return { tag = tag }
    end
    -- If it's one of our objects which has already been wrapped, return our
    -- tag
    local tag = my_objects_by_obj[obj]
    if tag then
-      return { tag = tag }
+      track.leave("give", "ours", tag)
+      return my_objects_expn_by_tag[tag]
    end
    -- otherwise wrap it freshly for us and return that.
    local tag = new_tag(special_tag)
    local expn = capi.explain(obj, tag)
    my_objects_by_obj[obj] = tag
    my_objects_by_tag[tag] = obj
+   my_objects_expn_by_tag[tag] = expn
+   track.leave("give", "ours, new", tag)
    return expn
 end
 
@@ -103,25 +114,28 @@ local function receive(obj)
    assert(type(obj) == "table")
    assert(type(obj.tag) == "string")
    local tag = obj.tag
+   track.enter("receive", tag)
    -- First up, is it one of our objects?
    local ret = my_objects_by_tag[tag]
    if ret then
+      track.leave("receive", "ours", tostring(ret))
       return ret
    end
    -- Now is it a known one of their objects?
    ret = their_objects_by_tag[tag]
    if ret then
+      track.leave("receive", "theirs", tostring(ret))
       return ret
    end
    -- Okay, prepare a proxy?
-   assert(type(obj.type) == "string")
+   assert(type(obj.type) == "string", "Type string expected, got " .. type(obj.type) .. " preparing proxy for " .. obj.tag)
    local proxy, mt = capi.new_proxy(obj.type)
    assert(capi.type(proxy) == obj.type)
    their_objects_by_tag[tag] = proxy
    their_objects_by_obj[proxy] = tag
+   their_objects_refcnt[tag] = (their_objects_refcnt[tag] or 0) + 1
    -- Fill out the metatable
    obj.methods = obj.methods or {}
-   obj.methods[#obj.methods+1] = "__gc"
    if obj.type == "function" then
       obj.methods[#obj.methods+1] = "__call"
    end
@@ -133,18 +147,33 @@ local function receive(obj)
    end
    for _, name in ipairs(obj.methods or {}) do
       local function meta_func(mobj, ...)
-	 return proc_call(tag, name, ...)
+	 track.enter("meta_func", tostring(mobj), tag, name)
+	 local ret = {proc_call(tag, name, ...)}
+	 track.leave("meta_func", tostring(mobj), tag, name)
+	 return unpack(ret)
       end
       mt[name] = meta_func
    end
+   function mt:__gc()
+      their_objects_refcnt[tag] = their_objects_refcnt[tag] - 1
+      if their_objects_refcnt[tag] == 0 then
+	 their_objects_refcnt[tag] = nil
+	 proc_call(tag, "__gc")
+      end
+   end
    -- And return the proxy object
+   track.leave("receive", "theirs, new", tostring(proxy))
    return proxy
 end
 
 local function forget_mine(tag)
+   track.enter("forget_mine", tag)
    local obj = my_objects_by_tag[tag]
+   assert(obj, "Trying to forget nil object: " .. tag)
    my_objects_by_tag[tag] = nil
    my_objects_by_obj[obj] = nil
+   my_objects_expn_by_tag[tag] = nil
+   track.leave("forget_mine", tag)
 end
 
 local function find_tag(obj)
@@ -156,6 +185,17 @@ local function find_tag(obj)
    end
 end
 
+local function get_object_anchor()
+   local ret = {}
+   for obj in pairs(their_objects_by_obj) do
+      ret[obj] = true
+   end
+   for obj in pairs(my_objects_by_obj) do
+      ret[obj] = true
+   end
+   return ret
+end
+
 return {
    set_name = set_name,
    get_name = get_name,
@@ -165,4 +205,5 @@ return {
    clean_down = clean_down,
    forget_mine = forget_mine,
    find_tag = find_tag,
+   get_object_anchor = get_object_anchor,
 }
diff --git a/lib/supple/sandbox.lua b/lib/supple/sandbox.lua
index cc1bc6c..f4025bc 100644
--- a/lib/supple/sandbox.lua
+++ b/lib/supple/sandbox.lua
@@ -24,12 +24,15 @@ local objects = require 'supple.objects'
 local comms = require 'supple.comms'
 local luxio = require 'luxio'
 local sio = require 'luxio.simple'
+local track = require 'supple.track'
 
 local loadstring = loadstring
 local load = load
 local setfenv = setfenv
 local gc = collectgarbage
 local unpack = unpack
+local xpcall = xpcall
+local traceback = debug.traceback
 
 local function set_limits(ltab)
    local count = ltab.count
@@ -152,6 +155,7 @@ local function run()
 
    -- Pretend we've "given" the host an object called 'supple:loadstring'
    -- which is the loadstring/load function
+   track.start()
    objects.give(set_limits, "supple:set_limits")
    objects.give(wrappered_load, "supple:loadstring")
    objects.give(objects.clean_down, "supple:clean_down")
@@ -160,6 +164,14 @@ local function run()
    return fn(comms._wait)
 end
 
+local function wrapper_run()
+   local ok, retcode = xpcall(run, traceback)
+   if not ok then
+      error(retcode)
+   end
+   return retcode
+end
+
 return {
-   run = run,
+   run = wrapper_run,
 }
diff --git a/lib/supple/track.lua b/lib/supple/track.lua
new file mode 100644
index 0000000..b22156f
--- /dev/null
+++ b/lib/supple/track.lua
@@ -0,0 +1,62 @@
+-- lib/supple/track.lua
+--
+-- Sandbox (for) Untrusted Procedure Partitioning (in) Lua Engine
+--
+-- Tracking and logging for debug porpoises.
+--
+-- Copyright 2012 Daniel Silverstone <dsilvers@digital-scurf.org>
+--
+-- For licence terms, see COPYING
+--
+
+local depth
+local track
+
+local function record(...)
+   if depth then
+      track[#track+1] = { depth, ... }
+   end
+end
+
+local function enter(...)
+   if depth then
+      record(">>>", ...)
+      depth = depth + 1
+   end
+end
+
+local function leave(...)
+   if depth then
+      if depth > 0 then
+	 depth = depth - 1
+      end
+      record("<<<", ...)
+   end
+end
+
+local function start_tracking()
+   depth, track = 0, {}
+end
+
+local function stop_tracking()
+   if track == nil then
+      return "***NO TRACKING DATA***"
+   end
+   local ret = {}
+   for i = 1, #track do
+      local ent = track[i]
+      local pfx = ("  "):rep(ent[1])
+      table.remove(ent, 1)
+      ret[#ret+1] = pfx .. table.concat(ent, " ")
+   end
+   depth, track = nil, {}
+   return table.concat(ret, "\n")
+end
+
+return {
+   start = start_tracking,
+   stop = stop_tracking,
+   enter = enter,
+   leave = leave,
+   record = record,
+}
\ No newline at end of file
diff --git a/src/wrapper.c b/src/wrapper.c
index 7cb52e3..d4f1412 100644
--- a/src/wrapper.c
+++ b/src/wrapper.c
@@ -68,7 +68,13 @@ main(int argc, char **argv)
 	parg.retcode = 0;
 	
 	success = lua_cpcall(L, &protected_main, &parg);
-	
+
+        if (success != 0) {
+		size_t l;
+		const char *s = lua_tolstring(L, 1, &l);
+		write(2, s, l);
+        }
+
 	lua_close(L);
 	
 	return ((success == 0) && (parg.retcode == 0)) ? EXIT_SUCCESS :
diff --git a/test/test-supple.track.lua b/test/test-supple.track.lua
new file mode 100644
index 0000000..d71e7a3
--- /dev/null
+++ b/test/test-supple.track.lua
@@ -0,0 +1,51 @@
+-- test/test-supple.track.lua
+--
+-- Supple - Tests for the track module
+--
+-- Copyright 2012 Daniel Silverstone <dsilvers@digital-scurf.org>
+--
+-- For Licence terms, see COPYING
+--
+
+-- Step one, start coverage
+
+local luacov = require 'luacov'
+
+local track = require 'supple.track'
+
+local testnames = {}
+
+local real_assert = assert
+local total_asserts = 0
+local function assert(...)
+   local retval = real_assert(...)
+   total_asserts = total_asserts + 1
+   return retval
+end
+
+local function add_test(suite, name, value)
+   rawset(suite, name, value)
+   testnames[#testnames+1] = name
+end
+
+local suite = setmetatable({}, {__newindex = add_test})
+
+function suite:starts()
+   track.start()
+end
+
+local count_ok = 0
+for _, testname in ipairs(testnames) do
+--   print("Run: " .. testname)
+   local ok, err = xpcall(suite[testname], debug.traceback)
+   if not ok then
+      print(err)
+      print()
+   else
+      count_ok = count_ok + 1
+   end
+end
+
+print(tostring(count_ok) .. "/" .. tostring(#testnames) .. " [" .. tostring(total_asserts) .. "] OK")
+
+os.exit(count_ok == #testnames and 0 or 1)