changeset 6538:de1f17ed4dac

mod_firewall: Add support for tracing rule evaluation in real-time
author Matthew Wild <mwild1@gmail.com>
date Mon, 11 May 2026 13:37:19 +0100
parents 9bc83fba89ac
children 4d7e2d0db2ab
files mod_firewall/README.md mod_firewall/actions.lib.lua mod_firewall/mod_firewall.lua mod_firewall/trace.lib.lua
diffstat 4 files changed, 187 insertions(+), 2 deletions(-) [+]
line wrap: on
line diff
--- a/mod_firewall/README.md	Mon May 11 13:18:45 2026 +0100
+++ b/mod_firewall/README.md	Mon May 11 13:37:19 2026 +0100
@@ -842,3 +842,73 @@
 Example to limit stanzas per session type:
 
     LIMIT: normal on $(session.type)
+
+### Tracing
+
+mod_firewall has tracing functionality, to help with debugging scripts and
+rules.
+
+To enable tracing for a script, add at the top:
+
+```
+@@ trace = on
+```
+
+All chains defined in the script will then have tracing activated. Note that
+this has a small performance impact (in processing and in memory allocations),
+even when the tracing functionality is not actively being used.
+
+You need to reload mod_firewall after enabling tracing in a script, so it will
+pick up the change and recompile the rules.
+
+When tracing is enabled, you can trace all evaluations by running:
+
+```
+prosodyctl shell firewall trace HOST
+```
+
+Replace HOST with the name of the host/component you want to trace (obviously
+mod_firewall must be loaded on that host).
+
+What is a trace? When tracing is enabled, a trace is generated each time a
+chain runs an evaluation of a stanza. The trace records the script name, chain
+name, the stanza that was being evaluated, and which rules/conditions matched.
+This information is then sent to any active 'trace' commands. If no commands
+are active, traces are discarded.
+
+Note that traces are per-chain and only printed when they are complete. This
+can result in unintuitive ordering of the output when multiple chains are
+invoked during processing of a stanza. Results of traces from "inner" chains
+will be displayed before traces from an "outer" chain.
+
+#### Tagging traces
+
+Sometimes you only need to trace a subset of evaluations. To do this, you can
+use the `TAG TRACE` action. This will apply a tag to the trace of the current
+evaluation.
+
+For example, if you only want to trace stanzas sent to a specific JID:
+
+```
+TO: user@example.com
+TAG TRACE=interesting
+```
+
+Then you can filter for this tag when you watch traces:
+
+```
+prosodyctl shell firewall trace --tag=interesting HOST
+```
+
+You can filter by the special tag name `untagged` to only show traces which
+have not been tagged.
+
+Notes on trace tagging:
+
+- Traces are per chain, however tags will propagate through to future chains
+  which execute on the same event. This allows easily tracing a stanza through
+  multiple chains, for example.
+- A trace may only have one tag. If `TAG TRACE` is used multiple times, it
+  will overwrite the tag for the current trace and any future chains which run
+  on this event/stanza. Chains (other than the current one) which already
+  began evaluation won't use the new tag.
--- a/mod_firewall/actions.lib.lua	Mon May 11 13:18:45 2026 +0100
+++ b/mod_firewall/actions.lib.lua	Mon May 11 13:37:19 2026 +0100
@@ -277,4 +277,8 @@
 	return code:format(where, reason, text), { "core_post_stanza", "current_host", "st", "new_short_id" };
 end
 
+function action_handlers.TAG_TRACE(tag_name)
+	return ("if trace_record then trace_record.tag, event.firewall_trace_tag = %q, %q end"):format(tag_name, tag_name), { "trace" };
+end
+
 return action_handlers;
--- a/mod_firewall/mod_firewall.lua	Mon May 11 13:18:45 2026 +0100
+++ b/mod_firewall/mod_firewall.lua	Mon May 11 13:37:19 2026 +0100
@@ -328,7 +328,7 @@
 	};
 
 	trace = {
-		global_code = [[local trace_init = module:require("trace").init;]];
+		global_code = [[local trace_init = module.environment.trace.init;]];
 	};
 };
 
@@ -382,6 +382,15 @@
 local condition_handlers = module:require("conditions");
 local action_handlers = module:require("actions");
 
+module.environment.trace = module:require("trace");
+
+local metadata_field_handlers = {
+	trace = function (v)
+		v = v:lower();
+		return v == "on" or v == "true";
+	end;
+};
+
 if module:get_option_boolean("firewall_experimental_user_marks", true) then
 	module:require"marks";
 end
@@ -450,6 +459,10 @@
 			if not k then
 				return nil, errmsg("Unable to parse metadata assignment (expected '@@ key = value')");
 			end
+			local handler = metadata_field_handlers[k];
+			if handler then
+				v = handler(v);
+			end
 			metadata[k] = v;
 		elseif not(state) and line:sub(1,1) == "%" then -- Definition (zone, limit, etc.)
 			local what, name = line:match("^%%%s*([%w_]+) +([^ :]+)");
@@ -566,7 +579,7 @@
 
 		if metadata.trace then
 			include_dep("trace", code);
-			table.insert(code, ("local trace = trace_init(%q, %q);"):format(metadata.filename, chain_name))
+			table.insert(code, ("local trace_record <close>, trace = trace_init(%q, %q, stanza, event.firewall_trace_tag, source_rules);"):format(metadata.filename, chain_name))
 		end
 
 		local condition_cache, n_conditions = {}, 0;
@@ -611,6 +624,9 @@
 					..table.concat(rule.actions, "\n\t\t\t")
 					.."\n\t\tend\n";
 			else
+				if metadata.trace then
+					table.insert(rule.actions, 2, ("trace(%d, nil, true)"):format(rule_n));
+				end
 				rule_code = table.concat(rule.actions, "\n\t\t");
 			end
 			table.insert(code, rule_code);
@@ -676,6 +692,8 @@
 
 function load_script(script)
 	script = resolve_script_path(script);
+	local base_name = script:match("[^/]+$");
+
 	local last_modified = (lfs.attributes(script) or {}).modification or os.time();
 	if loaded_scripts[script] then
 		if loaded_scripts[script].last_modified == last_modified then
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/mod_firewall/trace.lib.lua	Mon May 11 13:37:19 2026 +0100
@@ -0,0 +1,93 @@
+local async = require "prosody.util.async";
+
+local tracers = {};
+
+local trace_mt = {
+	__close = function (t)
+		for session, options in pairs(tracers) do
+			if not options.tag or options.tag == (t.tag or "untagged") then
+				session.print(("\n## Evaluating [%s::%s] (%s)"):format(t.filename, t.chain, t.tag or "untagged"));
+				local stanza_log = options.stanzas;
+				if stanza_log == "full" then
+					session.print(t.stanza);
+				elseif not stanza_log or stanza_log == "header" then
+					session.print(t.stanza:top_tag());
+				end
+
+				for rule_n, rule_trace in ipairs(t.rules) do
+					local source = t.source[rule_n].source;
+					for cond_n, matched in ipairs(rule_trace) do
+						session.print(
+							("%s %s"):format(
+								matched and "✔" or "✖",
+								source.conditions[cond_n] or ("Rule %d condition %d"):format(rule_n, cond_n)
+							)
+						);
+					end
+					if rule_trace.matched then
+						for _, action in ipairs(source.actions) do
+							session.print("➜ "..action);
+						end
+					end
+				end
+			end
+		end
+	end;
+};
+
+local function init(filename, chain_name, stanza, tag, source_rules)
+	local rule_trace = {};
+	local trace = setmetatable({
+		filename = filename;
+		chain = chain_name;
+		rules = rule_trace;
+		stanza = stanza;
+		tag = tag;
+		source = source_rules;
+	}, trace_mt);
+	return trace, function (rule_n, cond_n, result)
+		local rule = rule_trace[rule_n];
+		if not rule then
+			rule = {};
+			rule_trace[rule_n] = rule;
+		end
+
+		if cond_n then
+			rule[cond_n] = result;
+			return result;
+		else
+			-- Rule finished
+			rule.matched = result;
+		end
+	end;
+end
+
+
+module:add_item("shell-command", {
+	section = "firewall";
+	section_desc = "mod_firewall commands";
+	name = "trace";
+	desc = "Trace executions";
+	args = {
+		{ name = "host", type = "string" };
+	};
+	host_selector = "host";
+	flags = {
+		short_params = { t = "tag" };
+		value_params = { tag = true, stanzas = true };
+	};
+	handler = function(self, host, opts) --luacheck: ignore 212/self 212/host
+		self.session.print("# Tracing mod_firewall on "..host);
+		tracers[self.session] = opts or {};
+
+		while self.session.is_connected() do
+			async.sleep(3);
+		end
+
+		tracers[self.session] = nil;
+		return true;
+	end;
+});
+
+
+return { init = init };