mod_log_slow_events/mod_log_slow_events.lua
author Matthew Wild <mwild1@gmail.com>
Wed, 31 Aug 2016 11:29:26 +0100
changeset 2300 8c0bf3151e37
parent 1700 efc1d674eac0
child 2853 5e74028557dc
permissions -rw-r--r--
mod_log_slow_events: Add metric to monitor number of slow events
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
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
     1
local time = require "socket".gettime;
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
     2
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
     3
a9df1f7e273d mod_log_slow_events: Log events that take a long time to process (including stanzas)
Matthew Wild <mwild1@gmail.com>
parents:
diff changeset
     4
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
     5
2300
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1700
diff changeset
     6
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
     7
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
     8
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
     9
	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
    10
	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
    11
	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
    12
	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
    13
		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
    14
		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
    15
			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
    16
				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
    17
					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
    18
					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
    19
				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
    20
			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
    21
			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
    22
			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
    23
				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
    24
				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
    25
					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
    26
				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
    27
				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
    28
				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
    29
			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
    30
			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
    31
			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
    32
				log_data("stanza", tostring(stanza));
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    33
			else
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    34
				local request = event_data.request;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    35
				if request then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    36
					log_data("http_method", request.method);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    37
					log_data("http_path", request.path);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    38
					local auth = request.headers.authorization;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    39
					if auth then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    40
						local creds = auth:match("^Basic +(.+)$");
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    41
						if creds then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    42
							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
    43
							log_data("http_user", user);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    44
						end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    45
					end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    46
				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
    47
			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
    48
		end
2300
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1700
diff changeset
    49
		measure_slow_event();
1699
78b3b3add19c mod_log_slow_events: Minor improvement to log message
Matthew Wild <mwild1@gmail.com>
parents: 1684
diff changeset
    50
		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
    51
	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
    52
	return ret;
1700
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    53
end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    54
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    55
module:wrap_event(false, event_wrapper);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1699
diff changeset
    56
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
    57
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
    58