~nicoco/slidgnal#5: 
privileged_iq crash

I noticed Slidgnal was restarting every three minutes; it's making my contacts shimmer as their icons refresh in Dino, and I can see this in my logs:

root@org:~# journalctl  -f -u prosody.service 
-- Journal begins at Fri 2023-06-09 07:55:19 EDT. --
-- Boot c3ec93f3cf234226aabf7952062e516f --
Sep 27 08:11:57 xmpp.example.org systemd[1]: Started Prosody XMPP Server.
Sep 27 08:12:14 xmpp.example.org prosody[855]: mod_component: Traceback[component]: ...ocal/lib/prosody/modules/mod_privilege/mod_privilege.lua:662: attempt to call method 'send_iq' (a nil value)
                                             stack traceback:
                                                     ...ocal/lib/prosody/modules/mod_privilege/mod_privilege.lua:662: in function '?'
                                                     /usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
                                                     (...tail calls...)
                                                     /usr/lib/prosody/modules/mod_iq.lua:38: in function '?'
                                                     /usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
                                                     (...tail calls...)
                                                     /usr/lib/prosody/core/stanza_router.lua:180: in function 'core_post_stanza'
                                                     /usr/lib/prosody/core/stanza_router.lua:127: in function </usr/lib/prosody/core/stanza_router.lua:53>
                                                     [C]: in function 'xpcall'
                                                     /usr/lib/prosody/modules/mod_component.lua:243: in function 'cb_handlestanza'
                                                     /usr/lib/prosody/util/xmppstream.lua:182: in function </usr/lib/prosody/util/xmppstream.lua:162>
                                                     [C]: in function 'parse'
                                                     /usr/lib/prosody/util/xmppstream.lua:285: in function 'feed'
                                                     /usr/lib/prosody/modules/mod_component.lua:312: in function 'data'
                                                     /usr/lib/prosody/modules/mod_component.lua:324: in function </usr/lib/prosody/modules/mod_component.lua:322>
                                                     (...tail calls...)
                                                     /usr/lib/prosody/net/server_select.lua:924: in function </usr/lib/prosody/net/server_select.lua:908>
                                                     [C]: in function 'xpcall'
                                                     /usr/bin/prosody:76: in function 'loop'
                                                     /usr/bin/prosody:86: in main chunk
                                                     [C]: in ?
[...]
Sep 27 12:04:11 xmpp.example.org prosody[7056]: jcp56437542f290: Incoming Jabber component connection
Sep 27 12:04:11 xmpp.example.org prosody[7056]: signal.example.org:component: External component successfully authenticated
Sep 27 12:06:12 xmpp.example.org prosody[7056]: jcp56437542f290: component disconnected: signal.example.org (false)
Sep 27 12:06:15 xmpp.example.org prosody[7056]: jcp5643752801b0: Incoming Jabber component connection
Sep 27 12:06:15 xmpp.example.org prosody[7056]: signal.example.org:component: External component successfully authenticated

It seems to have something to do with the Privilege module:

root@org:~# journalctl  -f -u prosody.service 
[...]
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: DEBUG:slixmpp.xmlstream.xmlstream:Scheduled event: IqTimeout_0942743a-8e7a-486a-a911-42ae2b38c4ec
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: DEBUG:slidge.core.gateway.base:Context in the exception handler: {'message': 'Task exception was never retrieved', 'exception': IqTimeout(<iq id="0942743a-8e7a-486a-a911-42ae2b38c4ec" to="user@example.org" from="signal.example.org" type="get"><privileged_iq xmlns="urn:xmpp:privilege:2"><iq xmlns="jabber:client" type="get" to="user@example.org" from="user@example.org" id="0942743a-8e7a-486a-a911-42ae2b38c4ec"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="urn:xmpp:bookmarks:1"><item id="[redacted_user_1]=@signal.example.org" /></items></pubsub></iq></privileged_iq></iq>), 'future': <Task finished name='Task-21' coro=<BaseGateway.__login_wrap() done, defined at /var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidge/core/gateway/base.py:384> exception=IqTimeout(<iq id="0942743a-8e7a-486a-a911-42ae2b38c4ec" to="user@example.org" from="signal.example.org" type="get"><privileged_iq xmlns="urn:xmpp:privilege:2"><iq xmlns="jabber:client" type="get" to="user@example.org" from="user@example.org" id="0942743a-8e7a-486a-a911-42ae2b38c4ec"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="urn:xmpp:bookmarks:1"><item id="[redacted_user_1]=@signal.example.org" /></items></pubsub></iq></privileged_iq></iq>)>}
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: ERROR:slidge.core.gateway.base:Crash in an asyncio task: {'message': 'Task exception was never retrieved', 'exception': IqTimeout(<iq id="0942743a-8e7a-486a-a911-42ae2b38c4ec" to="user@example.org" from="signal.example.org" type="get"><privileged_iq xmlns="urn:xmpp:privilege:2"><iq xmlns="jabber:client" type="get" to="user@example.org" from="user@example.org" id="0942743a-8e7a-486a-a911-42ae2b38c4ec"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="urn:xmpp:bookmarks:1"><item id="[redacted_user_1]=@signal.example.org" /></items></pubsub></iq></privileged_iq></iq>), 'future': <Task finished name='Task-21' coro=<BaseGateway.__login_wrap() done, defined at /var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidge/core/gateway/base.py:384> exception=IqTimeout(<iq id="0942743a-8e7a-486a-a911-42ae2b38c4ec" to="user@example.org" from="signal.example.org" type="get"><privileged_iq xmlns="urn:xmpp:privilege:2"><iq xmlns="jabber:client" type="get" to="user@example.org" from="user@example.org" id="0942743a-8e7a-486a-a911-42ae2b38c4ec"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="urn:xmpp:bookmarks:1"><item id="[redacted_user_1]=@signal.example.org" /></items></pubsub></iq></privileged_iq></iq>)>}
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: ERROR:slidge.core.gateway.base:Crash in task
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: Traceback (most recent call last):
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:   File "/var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidge/core/gateway/base.py", line 406, in __login_wrap
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:     await session.bookmarks.fill()
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:   File "/var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidgnal/group.py", line 113, in fill
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:     await g.add_to_bookmarks(auto_join=True)
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:   File "/var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidge/group/room.py", line 843, in add_to_bookmarks
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:     ans = await self.xmpp["xep_0356"].send_privileged_iq(iq)
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:   File "/var/lib/slidge/slidge-env/lib/python3.9/site-packages/slidge/slixfix/xep_0356/privilege.py", line 203, in send_privileged_iq
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]:     resp = await iq.send()
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: slixmpp.exceptions.IqTimeout: <iq id="0942743a-8e7a-486a-a911-42ae2b38c4ec" to="user@example.org" from="signal.example.org" type="get"><privileged_iq xmlns="urn:xmpp:privilege:2"><iq xmlns="jabber:client" type="get" to="user@example.org" from="user@example.org" id="0942743a-8e7a-486a-a911-42ae2b38c4ec"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="urn:xmpp:bookmarks:1"><item id="[redacted_user_1]=@signal.example.org" /></items></pubsub></iq></privileged_iq></iq>
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: DEBUG:root:Gateway is connected, cleaning up
Sep 27 11:57:56 xmpp.example.org slidgnal[7710]: DEBUG:slidge.core.gateway.base:Shutting down

Something is weird with the privilege module because both prosody and slidge are complaining about it, though I'm not sure why the errors don't seem 100% correlated.

Status
REPORTED
Submitter
~kousu
Assigned to
No-one
Submitted
9 months ago
Updated
8 months ago
Labels
No labels applied.

~kousu 9 months ago

Oh and whatever is going on, this doesn't seem that harmful, so like https://todo.sr.ht/~nicoco/messlidger/2 it would be nice if this exception didn't cause a crash.

btw I'm not sure if this is a Slidgnal or a Slidge issue. Feel free to move if necessary!

~kousu 9 months ago*

I think I know why the errors aren't correlated: I changed the config.

I currently have

-- /etc/prosody/conf.d/example.org.cfg.lua
VirtualHost "example.org"
  http_host = "example.org"
-- /etc/prosody/conf.d/signal.example.org.cfg.lua 
Component "signal.example.org"
  component_secret = "password"
  modules_enabled = {"privilege"}

local _slidleges = {
    roster = "both";
    message = "outgoing";
    iq = { ["http://jabber.org/protocol/pubsub"] = "both"; };
}

-- can i reopen and just edit a part?
VirtualHost "example.org"
  privileged_entities = {
     ["signal.example.org"] = _slidleges,
  }

I previously had

-- /etc/prosody/conf.d/example.org.cfg.lua
local _slidleges = {
    roster = "both";
    message = "outgoing";
    iq = { ["http://jabber.org/protocol/pubsub"] = "both"; };
}

VirtualHost "example.org"
  http_host = "example.org"
  privileged_entities = {
     ["signal.example.org"] = _slidleges,
  }
-- /etc/prosody/conf.d/signal.example.org.cfg.lua 
Component "signal.example.org"
  component_secret = "password"
  modules_enabled = {"privilege"}

I've set it back to the previous config and I'll report if I receive the same lua errors as before. This is a more minor issue than I thought; if you misconfigure your server intentionally then yeah, Slidge is going to behave weirdly -- though it probably doesn't need to fully restart itself.

~nicoco 8 months ago

Sorry for the delay, I just noticed this one. It looks to me that this might be caused by an outdated mod_privilege in prosody? Sure, I can make this non-fatal in slidge, but I'm not sure we really want that. How did you work around that issue?

Register here or Log in to comment, or comment via email.