Mercurial > prosody-modules

comparison mod_smacks/mod_smacks.lua @ 3478:f6319346e2a3

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
mod_smacks: improved debug logging
author Georg Lukas <georg@op-co.de>
date Wed, 06 Mar 2019 21:44:07 +0100
parents 1f2381492c9f
children 9ef309fb501d
comparison
equal deleted inserted replaced
3477:1f2381492c9f 3478:f6319346e2a3
150 event.features:tag("sm", sm2_attr):tag("optional"):up():up(); 150 event.features:tag("sm", sm2_attr):tag("optional"):up():up();
151 event.features:tag("sm", sm3_attr):tag("optional"):up():up(); 151 event.features:tag("sm", sm3_attr):tag("optional"):up():up();
152 end 152 end
153 end); 153 end);
154 154
155 local function request_ack_if_needed(session, force) 155 local function request_ack_if_needed(session, force, reason)
156 local queue = session.outgoing_stanza_queue; 156 local queue = session.outgoing_stanza_queue;
157 if session.awaiting_ack == nil and not session.hibernating then 157 if session.awaiting_ack == nil and not session.hibernating then
158 if (#queue > max_unacked_stanzas and session.last_queue_count ~= #queue) or force then 158 if (#queue > max_unacked_stanzas and session.last_queue_count ~= #queue) or force then
159 session.log("debug", "Queuing <r> (in a moment)"); 159 session.log("debug", "Queuing <r> (in a moment) from %s - #queue=%d", reason, #queue);
160 session.awaiting_ack = false; 160 session.awaiting_ack = false;
161 session.awaiting_ack_timer = stoppable_timer(1e-06, function () 161 session.awaiting_ack_timer = stoppable_timer(1e-06, function ()
162 if not session.awaiting_ack and not session.hibernating then 162 if not session.awaiting_ack and not session.hibernating then
163 session.log("debug", "Sending <r> (inside timer, before send)"); 163 session.log("debug", "Sending <r> (inside timer, before send)");
164 (session.sends2s or session.send)(st.stanza("r", { xmlns = session.smacks })) 164 (session.sends2s or session.send)(st.stanza("r", { xmlns = session.smacks }))
200 stamp = datetime.datetime() 200 stamp = datetime.datetime()
201 }); 201 });
202 end 202 end
203 203
204 queue[#queue+1] = cached_stanza; 204 queue[#queue+1] = cached_stanza;
205 session.log("debug", "#queue = %d", #queue);
206 if session.hibernating then 205 if session.hibernating then
207 session.log("debug", "hibernating, stanza queued"); 206 session.log("debug", "hibernating, stanza queued");
208 return nil; 207 return nil;
209 end 208 end
210 request_ack_if_needed(session, false); 209 request_ack_if_needed(session, false, "outgoing_stanza_filter");
211 end 210 end
212 return stanza; 211 return stanza;
213 end 212 end
214 213
215 local function count_incoming_stanzas(stanza, session) 214 local function count_incoming_stanzas(stanza, session)
362 module:fire_event("delivery/success", { session = origin, stanza = handled_stanza }); 361 module:fire_event("delivery/success", { session = origin, stanza = handled_stanza });
363 end 362 end
364 363
365 origin.log("debug", "#queue = %d", #queue); 364 origin.log("debug", "#queue = %d", #queue);
366 origin.last_acknowledged_stanza = origin.last_acknowledged_stanza + handled_stanza_count; 365 origin.last_acknowledged_stanza = origin.last_acknowledged_stanza + handled_stanza_count;
367 request_ack_if_needed(origin, false) 366 request_ack_if_needed(origin, false, "handle_a")
368 return true; 367 return true;
369 end 368 end
370 module:hook_stanza(xmlns_sm2, "a", handle_a); 369 module:hook_stanza(xmlns_sm2, "a", handle_a);
371 module:hook_stanza(xmlns_sm3, "a", handle_a); 370 module:hook_stanza(xmlns_sm3, "a", handle_a);
372 371
503 ); 502 );
504 end; 503 end;
505 elseif session.username == original_session.username 504 elseif session.username == original_session.username
506 and session.host == original_session.host then 505 and session.host == original_session.host then
507 session.log("debug", "mod_smacks resuming existing session %s...", get_session_id(original_session)); 506 session.log("debug", "mod_smacks resuming existing session %s...", get_session_id(original_session));
507 original_session.log("debug", "mod_smacks session resumed from %s...", get_session_id(session));
508 -- TODO: All this should move to sessionmanager (e.g. session:replace(new_session)) 508 -- TODO: All this should move to sessionmanager (e.g. session:replace(new_session))
509 if original_session.conn then 509 if original_session.conn then
510 original_session.log("debug", "mod_smacks closing an old connection for this session"); 510 original_session.log("debug", "mod_smacks closing an old connection for this session");
511 local conn = original_session.conn; 511 local conn = original_session.conn;
512 c2s_sessions[conn] = nil; 512 c2s_sessions[conn] = nil;
546 function session.send(stanza) 546 function session.send(stanza)
547 session.log("warn", "Tried to send stanza on old session migrated by smacks resume (maybe there is a bug?): %s", tostring(stanza)); 547 session.log("warn", "Tried to send stanza on old session migrated by smacks resume (maybe there is a bug?): %s", tostring(stanza));
548 return false; 548 return false;
549 end 549 end
550 module:fire_event("smacks-hibernation-end", {origin = session, resumed = original_session, queue = queue}); 550 module:fire_event("smacks-hibernation-end", {origin = session, resumed = original_session, queue = queue});
551 request_ack_if_needed(original_session, true); 551 request_ack_if_needed(original_session, true, "handle_resume");
552 else 552 else
553 module:log("warn", "Client %s@%s[%s] tried to resume stream for %s@%s[%s]", 553 module:log("warn", "Client %s@%s[%s] tried to resume stream for %s@%s[%s]",
554 session.username or "?", session.host or "?", session.type, 554 session.username or "?", session.host or "?", session.type,
555 original_session.username or "?", original_session.host or "?", original_session.type); 555 original_session.username or "?", original_session.host or "?", original_session.type);
556 session.send(st.stanza("failed", { xmlns = xmlns_sm }) 556 session.send(st.stanza("failed", { xmlns = xmlns_sm })