fix: logging

Dockerfile

@@ -16,6 +16,7 @@ RUN cd prosody-0.11.6/ && ./configure --sysconfdir="/etc/prosody" --no-example-c
 
 RUN mkdir /vnc
 RUN mkdir -p /var/run/prosody/
+RUN mkdir -p /var/log/prosody/
 
 RUN addgroup prosody
 RUN adduser -D -S -h /var/lib/prosody -H -G prosody prosody

config/prosody.cfg.lua.template

@@ -77,6 +77,8 @@ modules_enabled = {
    "vnc_receipts";
    "vnc_remotemucstore";
 
+   -- debug
+   "log_slow_events";
 }
 
 modules_disabled = {
@@ -93,7 +95,9 @@ modules_disabled = {
 
 -- The supported levels are: "debug", "info", "warn", "error".
 log = {
-  levels = { "info", "warn", "error" }, to = "console" ;
+--  levels = { "info", "warn", "error" }, to = "console" ;
+  info = "/var/log/prosody.log";
+  error = "/var/log/prosody.err";
 }
 
 --------------------------------------------------------------------------------
@@ -191,6 +195,8 @@ smacks_max_hibernated_sessions = 10;
 smacks_max_old = 10;
 --------------------------------------------------------------------------------
 
+log_slow_events_threshold = 1.5
+
 --------------------------------------------------------------------------------
 ---- MOTD config
 --------------------------------------------------------------------------------

config/startup.sh

@@ -33,4 +33,7 @@ cat /etc/prosody/prosody.cfg.lua
 # su prosody -c /usr/local/bin/prosody -F
 env
 
+touch /var/log/prosody.log
+tail -f /var/log/prosody.log &
+
 /usr/local/bin/prosody -F

vnctalk/mod_log_slow_events.lua

@@ -0,0 +1,63 @@
+module:set_global();
+
+local time = require "socket".gettime;
+local base64_decode = require "util.encodings".base64.decode;
+
+local max_seconds = module:get_option_number("log_slow_events_threshold", 0.5);
+
+local measure_slow_event = module:measure("slow_events", "rate");
+
+function event_wrapper(handlers, event_name, event_data)
+	local start = time();
+	local ret = handlers(event_name, event_data);
+	local duration = time()-start;
+	if duration > max_seconds then
+		local data = {};
+		if event_data then
+			local function log_data(name, value)
+				if value then
+					table.insert(data, ("%s=%q"):format(name, value));
+					return true;
+				end
+			end
+			local sess = event_data.origin or event_data.session;
+			if sess then
+				log_data("ip", sess.ip);
+				if not log_data("full_jid", sess.full_jid) then
+					log_data("username", sess.username);
+				end
+				log_data("type", sess.type);
+				log_data("host", sess.host);
+			end
+			local stanza = event_data.stanza;
+			if stanza then
+				log_data("stanza", tostring(stanza));
+			else
+				local request = event_data.request;
+				if request then
+					log_data("http_method", request.method);
+					log_data("http_path", request.path);
+					local auth = request.headers.authorization;
+					if auth then
+						local creds = auth:match("^Basic +(.+)$");
+						if creds then
+							local user = string.match(base64_decode(creds) or "", "^([^:]+):");
+							log_data("http_user", user);
+						end
+					end
+				end
+			end
+		end
+		measure_slow_event();
+		module:log("warn", "Slow event '%s' took %0.2fs: %s", event_name, duration, next(data) and table.concat(data, ", ") or "no recognised data");
+	end
+	return ret;
+end
+
+local http_events = require "net.http.server"._events;
+module:wrap_object_event(http_events, false, event_wrapper);
+
+module:wrap_event(false, event_wrapper);
+function module.add_host(module)
+	module:wrap_event(false, event_wrapper);
+end