#1473 not archiving stanza infinite loop

Reporter Tim Makarios
Owner Nobody
Created
Updated
Stars ★ (1)
Tags
  • Type-Defect
  • Priority-Medium
  • Status-New
  1. Tim Makarios on

    What steps will reproduce the problem? For me: running Prosody. Restarting it doesn't fix the problem. But it never used to happen, and I don't know what triggered it now. What is the expected output? Prosody working normally, not using excessive memory, or writing similar things over and over again to the log. What do you see instead? The log file has a lot of this (note how rapidly it's written over and over): Dec 07 21:01:28 c2s55ddad44de60 debug Queuing <r> (in a moment) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2225'> Dec 07 21:01:28 c2s55ddad2b0bb0 debug #queue = 1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2e4420 debug Handled 1050 incoming stanzas Dec 07 21:01:28 c2s55ddad2e4420 debug Received[c2s]: <iq id='df9a6ed7-f8fa-429f-8b88-980e725ec566' type='set'> Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:28 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1739 Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 c2s55ddad44de60 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='3298'> Dec 07 21:01:28 c2s55ddad44de60 debug #queue = 1 Dec 07 21:01:28 c2s55ddad44de60 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2226'> Dec 07 21:01:28 c2s55ddad2b0bb0 debug #queue = 1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2f3e20 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2219'> Dec 07 21:01:28 c2s55ddad2f3e20 debug #queue = 0 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad44de60 debug Handled 1103 incoming stanzas Dec 07 21:01:28 c2s55ddad44de60 debug Received[c2s]: <iq id='8TS8P-279053' type='set'> Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:28 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1740 Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:28 c2s55ddad44de60 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='3299'> Dec 07 21:01:28 c2s55ddad44de60 debug #queue = 2 Dec 07 21:01:28 c2s55ddad44de60 debug Queuing <r> (in a moment) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2227'> Dec 07 21:01:28 c2s55ddad2b0bb0 debug #queue = 1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from handle_a - #queue=2 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:28 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2e4420 debug Received[c2s]: <r xmlns='urn:xmpp:sm:2'> Dec 07 21:01:29 freespoken.nz:smacks debug Received ack request, acking for 1050 Dec 07 21:01:29 c2s55ddad44de60 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='3301'> Dec 07 21:01:29 c2s55ddad44de60 debug #queue = 0 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2228'> Dec 07 21:01:29 c2s55ddad2b0bb0 debug #queue = 0 Dec 07 21:01:29 c2s55ddad2e4420 debug Handled 1051 incoming stanzas Dec 07 21:01:29 c2s55ddad2e4420 debug Received[c2s]: <iq id='bee087b4-328a-41b2-998c-f84234ebfd55' type='set'> Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:29 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1741 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad44de60 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2220'> Dec 07 21:01:29 c2s55ddad2f3e20 debug #queue = 1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2e4420 debug Received[c2s]: <r xmlns='urn:xmpp:sm:2'> Dec 07 21:01:29 freespoken.nz:smacks debug Received ack request, acking for 1051 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2221'> Dec 07 21:01:29 c2s55ddad2f3e20 debug #queue = 0 Dec 07 21:01:29 c2s55ddad44de60 debug Handled 1104 incoming stanzas Dec 07 21:01:29 c2s55ddad44de60 debug Received[c2s]: <iq id='8TS8P-279057' type='set'> Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:29 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1742 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2229'> Dec 07 21:01:29 c2s55ddad2b0bb0 debug #queue = 1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad44de60 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='3302'> Dec 07 21:01:29 c2s55ddad44de60 debug #queue = 2 Dec 07 21:01:29 c2s55ddad44de60 debug Queuing <r> (in a moment) from handle_a - #queue=2 Dec 07 21:01:29 c2s55ddad2f3e20 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2222'> Dec 07 21:01:29 c2s55ddad2f3e20 debug #queue = 0 Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from handle_a - #queue=2 Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from handle_a - #queue=2 Dec 07 21:01:29 c2s55ddad2e4420 debug Handled 1052 incoming stanzas Dec 07 21:01:29 c2s55ddad2e4420 debug Received[c2s]: <iq id='82c1386e-1158-4cc9-9907-62d4ce13a33b' type='set'> Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:29 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1743 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2223'> Dec 07 21:01:29 c2s55ddad2f3e20 debug #queue = 0 Dec 07 21:01:29 c2s55ddad44de60 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='3304'> Dec 07 21:01:29 c2s55ddad44de60 debug #queue = 1 Dec 07 21:01:29 c2s55ddad44de60 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2230'> Dec 07 21:01:29 c2s55ddad2b0bb0 debug #queue = 1 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Queuing <r> (in a moment) from handle_a - #queue=1 Dec 07 21:01:29 c2s55ddad44de60 debug Handled 1105 incoming stanzas Dec 07 21:01:29 c2s55ddad44de60 debug Received[c2s]: <iq id='8TS8P-279061' type='set'> Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted2@freespoken.nz/01cb22c4-98a2-4a08-9b8c-b6068dd889f8' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Conversations.OOTo' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad58a2f0 debug Calling delayed_ack_function directly (still waiting for ack) Dec 07 21:01:29 c2s55ddad58a2f0 debug Firing event 'smacks-ack-delayed', queue = 1744 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted1@freespoken.nz/Conversations._p3W' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad2f3e20 debug Queuing <r> (in a moment) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/Gajim' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 freespoken.nz:mam debug Not archiving stanza: <message type='headline' to='redacted3@freespoken.nz/atalk' from='redacted3@freespoken.nz'> (type) Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, before send) from handle_a - #queue=3 Dec 07 21:01:29 c2s55ddad44de60 debug Sending <r> (inside timer, after send) from handle_a - #queue=3 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, before send) from handle_a - #queue=2 Dec 07 21:01:29 c2s55ddad2b0bb0 debug Sending <r> (inside timer, after send) from handle_a - #queue=2 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, before send) from outgoing_stanza_filter - #queue=1 Dec 07 21:01:29 c2s55ddad2f3e20 debug Sending <r> (inside timer, after send) from outgoing_stanza_filter - #queue=1 In addition to seeing that in the logs, top shows lua5.1 (running as the prosody user) using more and more memory (though it doesn't increase linearly with time), until it runs out of memory and crashes. What version of the product are you using? On what operating system? Prosody 0.9.12-2+deb9u2 on Debian Stretch Community modules 3758:900ea02ab00b Gajim 1.1.2-2 on Debian Buster Also another version of Gajim on some version of Windows, and various versions of Conversations on various versions of Android Please provide any additional information below. modules_enabled = { "roster"; -- Allow users to have a roster. Recommended ;) "saslauth"; -- Authentication for clients and servers. Recommended if you want to log in. "tls"; -- Add support for secure TLS on c2s/s2s connections "dialback"; -- s2s dialback support "disco"; -- Service discovery "private"; -- Private XML storage (for room bookmarks, etc.) "vcard"; -- Allow users to set vCards "version"; -- Replies to server version requests "uptime"; -- Report how long server has been running "time"; -- Let others know the time here on this server "ping"; -- Replies to XMPP pings with pongs "pep"; -- Enables users to publish their mood, activity, playing music and more "register"; -- Allow users to register on this server using a client and change passwords "admin_adhoc"; -- Allows administration via an XMPP client that supports ad-hoc commands "posix"; -- POSIX functionality, sends server to background, enables syslog, etc. "blocking"; -- XEP-0191: allow users to block messages from other users "smacks"; -- XEP-0198: Stream Management; prevents loss of messages "carbons"; -- XEP-0280: helps users with more than one device "mam"; -- XEP-0313: Message Archive Management "csi"; -- XEP-0352: Client State Indication; to get less traffic when idle "throttle_presence"; -- such as presence updates, "filter_chatstates"; -- and whether or not someone is typing "cloud_notify"; -- XEP-0357: Push Notifications, for ChatSecure "pinger"; "smacks_offline"; }; If you think it's one of the community modules, I can do a bisect on that folder, to see if it was a recent change, but I haven't noticed the problem before today, and I haven't downloaded any updates to the community modules for at least a week.

New comment

Not published. Used for spam prevention and optional update notifications.