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.
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!
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.
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?
I'm closing as "NOT_OUR_BUG", please re-open if you think I'm wrong. ;)