mod_log_slow_events/mod_log_slow_events.lua
author Kim Alvefur <zash@zash.se>
Sun, 03 Mar 2024 11:23:40 +0100
changeset 5857 97c9b76867ca
parent 2854 3ba8fd1a297e
permissions -rw-r--r--
mod_log_ringbuffer: Detach event handlers on logging reload (thanks Menel) Otherwise the global event handlers accumulate, one added each time logging is reoladed, and each invocation of the signal or event triggers one dump of each created ringbuffer.
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
2853
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2300
diff changeset
     1
module:set_global();
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2300
diff changeset
     2
1684
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
     3
local time = require "socket".gettime;
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
     4
local base64_decode = require "util.encodings".base64.decode;
1684
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
     5
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
     6
local max_seconds = module:get_option_number("log_slow_events_threshold", 0.5);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
     7
2300
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1700
diff changeset
     8
local measure_slow_event = module:measure("slow_events", "rate");
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1700
diff changeset
     9
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    10
function event_wrapper(handlers, event_name, event_data)
1684
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    11
	local start = time();
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    12
	local ret = handlers(event_name, event_data);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    13
	local duration = time()-start;
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    14
	if duration > max_seconds then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    15
		local data = {};
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    16
		if event_data then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    17
			local function log_data(name, value)
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    18
				if value then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    19
					table.insert(data, ("%s=%q"):format(name, value));
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    20
					return true;
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    21
				end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    22
			end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    23
			local sess = event_data.origin or event_data.session;
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    24
			if sess then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    25
				log_data("ip", sess.ip);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    26
				if not log_data("full_jid", sess.full_jid) then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    27
					log_data("username", sess.username);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    28
				end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    29
				log_data("type", sess.type);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    30
				log_data("host", sess.host);
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    31
			end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    32
			local stanza = event_data.stanza;
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    33
			if stanza then
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    34
				log_data("stanza", tostring(stanza));
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    35
			else
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    36
				local request = event_data.request;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    37
				if request then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    38
					log_data("http_method", request.method);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    39
					log_data("http_path", request.path);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    40
					local auth = request.headers.authorization;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    41
					if auth then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    42
						local creds = auth:match("^Basic +(.+)$");
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    43
						if creds then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    44
							local user = string.match(base64_decode(creds) or "", "^([^:]+):");
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    45
							log_data("http_user", user);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    46
						end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    47
					end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    48
				end
1684
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    49
			end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    50
		end
2300
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1700
diff changeset
    51
		measure_slow_event();
1699
78b3b3add19c mod_log_slow_events: Minor improvement to log message
Matthew Wild <mwild1@gmail.com>
parents: 1684
diff changeset
    52
		module:log("warn", "Slow event '%s' took %0.2fs: %s", event_name, duration, next(data) and table.concat(data, ", ") or "no recognised data");
1684
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    53
	end
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
    54
	return ret;
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    55
end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    56
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    57
local http_events = require "net.http.server"._events;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    58
module:wrap_object_event(http_events, false, event_wrapper);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    59
2854
3ba8fd1a297e mod_log_slow_events: Also catch global events
Kim Alvefur <zash@zash.se>
parents: 2853
diff changeset
    60
module:wrap_event(false, event_wrapper);
2853
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2300
diff changeset
    61
function module.add_host(module)
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2300
diff changeset
    62
	module:wrap_event(false, event_wrapper);
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2300
diff changeset
    63
end