Mercurial > prosody-modules

annotate mod_log_slow_events/mod_log_slow_events.lua @ 5787:e79f9dec35c0

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
mod_c2s_conn_throttle: Reduce log level from error->info Our general policy is that "error" should never be triggerable by remote entities, and that it is always about something that requires admin intervention. This satisfies neither condition. The "warn" level can be used for unexpected events/behaviour triggered by remote entities, and this could qualify. However I don't think failed auth attempts are unexpected enough. I selected "info" because it is what is also used for other notable session lifecycle events.
author Matthew Wild <mwild1@gmail.com>
date Thu, 07 Dec 2023 15:46:50 +0000
parents 3ba8fd1a297e
children
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
rev   line source
2849
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2296
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: 2296
diff changeset
2
1680
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;
1696
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
4 local base64_decode = require "util.encodings".base64.decode;
1680
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
2296
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1696
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: 1696
diff changeset
9
1696
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
10 function event_wrapper(handlers, event_name, event_data)
1680
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));
1696
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
35 else
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
36 local request = event_data.request;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
37 if request then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
38 log_data("http_method", request.method);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
39 log_data("http_path", request.path);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
40 local auth = request.headers.authorization;
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
41 if auth then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
42 local creds = auth:match("^Basic +(.+)$");
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
43 if creds then
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
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: 1695
diff changeset
45 log_data("http_user", user);
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
46 end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
47 end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
48 end
1680
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
2296
8c0bf3151e37 mod_log_slow_events: Add metric to monitor number of slow events
Matthew Wild <mwild1@gmail.com>
parents: 1696
diff changeset
51 measure_slow_event();
1695
78b3b3add19c mod_log_slow_events: Minor improvement to log message
Matthew Wild <mwild1@gmail.com>
parents: 1680
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");
1680
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;
1696
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
55 end
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
diff changeset
56
efc1d674eac0 mod_log_slow_events: Log slow HTTP requests
Matthew Wild <mwild1@gmail.com>
parents: 1695
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: 1695
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: 1695
diff changeset
59
2850
3ba8fd1a297e mod_log_slow_events: Also catch global events
Kim Alvefur <zash@zash.se>
parents: 2849
diff changeset
60 module:wrap_event(false, event_wrapper);
2849
5e74028557dc mod_log_slow_events: Turn into a shared module (fixes http events being logged multiple times)
Kim Alvefur <zash@zash.se>
parents: 2296
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: 2296
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: 2296
diff changeset
63 end