view tools/modtrace.lua @ 13652:a08065207ef0

net.server_epoll: Call :shutdown() on TLS sockets when supported Comment from Matthew: This fixes a potential issue where the Prosody process gets blocked on sockets waiting for them to close. Unlike non-TLS sockets, closing a TLS socket sends layer 7 data, and this can cause problems for sockets which are in the process of being cleaned up. This depends on LuaSec changes which are not yet upstream. From Martijn's original email: So first my analysis of luasec. in ssl.c the socket is put into blocking mode right before calling SSL_shutdown() inside meth_destroy(). My best guess to why this is is because meth_destroy is linked to the __close and __gc methods, which can't exactly be called multiple times and luasec does want to make sure that a tls session is shutdown as clean as possible. I can't say I disagree with this reasoning and don't want to change this behaviour. My solution to this without changing the current behaviour is to introduce a shutdown() method. I am aware that this overlaps in a conflicting way with tcp's shutdown method, but it stays close to the OpenSSL name. This method calls SSL_shutdown() in the current (non)blocking mode of the underlying socket and returns a boolean whether or not the shutdown is completed (matching SSL_shutdown()'s 0 or 1 return values), and returns the familiar ssl_ioerror() strings on error with a false for completion. This error can then be used to determine if we have wantread/wantwrite to finalize things. Once meth_shutdown() has been called once a shutdown flag will be set, which indicates to meth_destroy() that the SSL_shutdown() has been handled by the application and it shouldn't be needed to set the socket to blocking mode. I've left the SSL_shutdown() call in the LSEC_STATE_CONNECTED to prevent TOCTOU if the application reaches a timeout for the shutdown code, which might allow SSL_shutdown() to clean up anyway at the last possible moment. Another thing I've changed to luasec is the call to socket_setblocking() right before calling close(2) in socket_destroy() in usocket.c. According to the latest POSIX[0]: Note that the requirement for close() on a socket to block for up to the current linger interval is not conditional on the O_NONBLOCK setting. Which I read to mean that removing O_NONBLOCK on the socket before close doesn't impact the behaviour and only causes noise in system call tracers. I didn't touch the windows bits of this, since I don't do windows. For the prosody side of things I've made the TLS shutdown bits resemble interface:onwritable(), and put it under a combined guard of self._tls and self.conn.shutdown. The self._tls bit is there to prevent getting stuck on this condition, and self.conn.shutdown is there to prevent the code being called by instances where the patched luasec isn't deployed. The destroy() method can be called from various places and is read by me as the "we give up" error path. To accommodate for these unexpected entrypoints I've added a single call to self.conn:shutdown() to prevent the socket being put into blocking mode. I have no expectations that there is any other use here. Same as previous, the self.conn.shutdown check is there to make sure it's not called on unpatched luasec deployments and self._tls is there to make sure we don't call shutdown() on tcp sockets. I wouldn't recommend logging of the conn:shutdown() error inside close(), since a lot of clients simply close the connection before SSL_shutdown() is done.
author Martijn van Duren <martijn@openbsd.org>
date Thu, 06 Feb 2025 15:04:38 +0000
parents 5eaf77114fdb
children
line wrap: on
line source

-- Trace module calls and method calls on created objects
--
-- Very rough and for debugging purposes only. It makes many
-- assumptions and there are many ways it could fail.
--
-- Example use:
--
--   local dbuffer = require "tools.modtrace".trace("util.dbuffer");
--

local t_pack = table.pack;
local serialize = require "util.serialization".serialize;
local unpack = table.unpack;
local set = require "util.set";

local serialize_cfg = {
	preset = "oneline";
	freeze = true;
	fatal = false;
	fallback = function (v) return "<"..tostring(v)..">" end;
};

local function stringify_value(v)
	if type(v) == "string" and #v > 20 then
		return ("<string(%d)>"):format(#v);
	elseif type(v) == "function" then
		return tostring(v);
	end
	return serialize(v, serialize_cfg);
end

local function stringify_params(...)
	local n = select("#", ...);
	local r = {};
	for i = 1, n do
		table.insert(r, stringify_value((select(i, ...))));
	end
	return table.concat(r, ", ");
end

local function stringify_result(ret)
	local r = {};
	for i = 1, ret.n do
		table.insert(r, stringify_value(ret[i]));
	end
	return table.concat(r, ", ");
end

local function stringify_call(method_name, ...)
	return ("%s(%s)"):format(method_name, stringify_params(...));
end

local function wrap_method(original_obj, original_method, method_name)
	method_name = ("<%s>:%s"):format(getmetatable(original_obj).__name or "object", method_name);
	return function (new_obj_self, ...)
		local opts = new_obj_self._modtrace_opts;
		local f = opts.output or io.stderr;
		f:write(stringify_call(method_name, ...));
		local ret = t_pack(original_method(original_obj, ...));
		if ret.n > 0 then
			f:write(" = ", stringify_result(ret), "\n");
		else
			f:write("\n");
		end
		return unpack(ret, 1, ret.n);
	end;
end

local function wrap_function(original_function, function_name, opts)
	local f = opts.output or io.stderr;
	return function (...)
		f:write(stringify_call(function_name, ...));
		local ret = t_pack(original_function(...));
		if ret.n > 0 then
			f:write(" = ", stringify_result(ret), "\n");
		else
			f:write("\n");
		end
		return unpack(ret, 1, ret.n);
	end;
end

local function wrap_metamethod(name, method)
	if name == "__index" then
		return function (new_obj, k)
			local original_method;
			if type(method) == "table" then
				original_method = new_obj._modtrace_original_obj[k];
			else
				original_method = method(new_obj._modtrace_original_obj, k);
			end
			if original_method == nil then
				return nil;
			end
			return wrap_method(new_obj._modtrace_original_obj, original_method, k);
		end;
	end
	return function (new_obj, ...)
		return method(new_obj._modtrace_original_obj, ...);
	end;
end

local function wrap_mt(original_mt)
	local new_mt = {};
	for k, v in pairs(original_mt) do
		new_mt[k] = wrap_metamethod(k, v);
	end
	return new_mt;
end

local function wrap_obj(original_obj, opts)
	local new_mt = wrap_mt(getmetatable(original_obj));
	return setmetatable({_modtrace_original_obj = original_obj, _modtrace_opts = opts}, new_mt);
end

local function wrap_new(original_new, function_name, opts)
	local f = opts.output or io.stderr;
	return function (...)
		f:write(stringify_call(function_name, ...));
		local ret = t_pack(original_new(...));
		local obj = ret[1];

		if ret.n == 1 and type(ret[1]) == "table" then
			f:write(" = <", getmetatable(ret[1]).__name or "object", ">", "\n");
		elseif ret.n > 0 then
			f:write(" = ", stringify_result(ret), "\n");
		else
			f:write("\n");
		end

		if obj then
			ret[1] = wrap_obj(obj, opts);
		end
		return unpack(ret, 1, ret.n);
	end;
end

local function trace(module, opts)
	if type(module) == "string" then
		module = require(module);
	end
	opts = opts or {};
	local new_methods = set.new(opts.new_methods or {"new"});
	local fake_module = setmetatable({}, {
		__index = function (_, k)
			if new_methods:contains(k) then
				return wrap_new(module[k], k, opts);
			else
				return wrap_function(module[k], k, opts);
			end
		end;
	});
	return fake_module;
end

return {
	wrap = trace;
	trace = trace;
}