#1875 If an account will be deleting, then prosody server freezes and every user will be disconnected
Reporter
Huxx
Owner
Nobody
Created
Updated
Stars
★ (1)
Tags
Priority-Medium
Status-NeedInfo
Type-Defect
Huxx
on
Hello,
if a user tries to delete an account, the whole prosody server is locked. Every connected client will be disconnected, when an account will be deleted.Also the whole deleting process tooks mostly 3 minutes.
After the account were deleted connection will be again accepted and users can connect again. Prosody version 0.12.4 stable is running on Debian 12.6.
default_storage = "internal"
storage = {
archive = "xmlarchive";
offline = "xmlarchive";
pep = "internal";
pep_data = "internal";
muc_log = "xmlarchive";
accounts = "internal";
account_details = "internal";
archive2_prefs = "internal";
archive_cleanup = "internal";
archive_prefs = "internal";
cloud_notify = "internal";
lastlog = "internal";
lastlog2 = "internal";
motd_sequential_seen = "internal";
roster = "internal";
private = "internal";
vcard = "internal";
blocklist = "internal";
pupsub_nodes = "internal";
}
I can reproduce this problem. Created an account testdelete@*** and then start deleting it at 14:09 with conversations client. At 14:12 the deleting process finished. In the debug log there are no more log entries between 14:09 and 14:12.
Debug Log
cat debug.log | grep testdelete
Aug 18 14:05:03 c2s5605e67f92f0 debug Received[c2s_unauthed]: <iq from='testdelete@***' type='set' id='RiMzgZoyzly1' xml:lang='en'>
Aug 18 14:05:03 ***:auth_internal_hashed debug account not found for username 'testdelete'
Aug 18 14:05:03 c2s5605e67f92f0 debug Sending[c2s_unauthed]: <iq type='result' to='testdelete@***' id='RiMzgZoyzly1'>
Aug 18 14:05:03 c2s5605e67f92f0 info User account created: testdelete@***
Aug 18 14:05:04 c2s5605dd58c860 info Authenticated as testdelete@***
Aug 18 14:05:04 rostermanager debug load_roster: asked for: testdelete@***
Aug 18 14:05:04 rostermanager debug load_roster: loading for new user: testdelete@***
Aug 18 14:05:04 mod_firewall::user/bodycheck info spam: bodylines: <message to='testdelete@***' from='***'><body>*** INFO
Aug 18 14:05:04 stanzarouter debug Discarding unhandled error message (cancel, not-allowed) from local: <message from='testdelete@***' type='error' to='***'>
Aug 18 14:05:04 ***:motd_sequential debug MOTD send to user testdelete@***
Aug 18 14:05:04 ***:pep debug Creating pubsub service for user "testdelete"
Aug 18 14:05:04 ***:bookmarks debug No existing legacy bookmarks for testdelete@***, migration already done: (nil)
Aug 18 14:05:04 ***:bookmarks debug Additionally, no bookmarks 2 were existing for testdelete@***, assuming empty.
Aug 18 14:05:04 c2s5605dd58c860 debug Resource bound: testdelete@***/Conversations.USVY
Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='th799pa9wosv' to='***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='result' to='testdelete@***/Conversations.USVY' id='th799pa9wosv'>
Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='vY_PNACTsaIJ' xml:lang='en'>
Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='vY_PNACTsaIJ'>
Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='KFDJNw-AR09x' to='testdelete@***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq from='testdelete@***' type='result' to='testdelete@***/Conversations.USVY' id='KFDJNw-AR09x'>
Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='8xPbzECq2f2Y' to='conference.***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='conference.***' type='result' to='testdelete@***/Conversations.USVY' id='8xPbzECq2f2Y'>
Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='855YX9KH_kzL' to='uploads.***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='uploads.***' type='result' to='testdelete@***/Conversations.USVY' id='855YX9KH_kzL'>
Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='yualL_6vu-KV' to='pubsub.***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='pubsub.***' type='result' to='testdelete@***/Conversations.USVY' id='yualL_6vu-KV'>
Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='MkaQ5XfQyrWP' xml:lang='en'>
Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='MkaQ5XfQyrWP'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='JYUmQNNlhWU-' to='testdelete@***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='JYUmQNNlhWU-'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='nm1a_CDoUeE0' xml:lang='en'>
Aug 18 14:05:10 ***:carbons debug testdelete@***/Conversations.USVY enabled carbons
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='nm1a_CDoUeE0'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='ZddrrHNd0BPC' to='***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='result' to='testdelete@***/Conversations.USVY' id='ZddrrHNd0BPC'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='JTuIEOsjowFW' xml:lang='en'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='JTuIEOsjowFW'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='cL3sjhkg2CB6' xml:lang='en'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='cL3sjhkg2CB6'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='1dai1OU-i8pJ' xml:lang='en'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='1dai1OU-i8pJ'>
Aug 18 14:05:10 c2s5605dd58c860 debug Presence from testdelete@***/Conversations.USVY with SHA-1 caps http://conversations.im#hV6yIEFlLgDca/x5w67HqrRECe8=, querying disco#info
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <presence xml:lang='en' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:10 ***:storage_xmlarchive debug Loading root index for testdelete
Aug 18 14:05:10 ***:storage_xmlarchive debug Loading root index for testdelete
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='PskysOmB6qRk' xml:lang='en'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='PskysOmB6qRk'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='19kTpzSGvwhi' xml:lang='en'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='19kTpzSGvwhi'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='get' to='testdelete@***/Conversations.USVY' id='ebc27627-0576-4317-90ab-796341ad16ab'>
Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='set' xml:lang='en' id='M2TspPFQYeVH' to='p2.siacs.eu' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:10 s2sout5605d96f5940 debug Sending[s2sout]: <iq type='set' from='testdelete@***/Conversations.USVY' id='M2TspPFQYeVH' to='p2.siacs.eu' xml:lang='en'>
Aug 18 14:05:10 s2sin5605d97fb500 debug Received[s2sin]: <iq type='result' xml:lang='en' id='M2TspPFQYeVH' to='testdelete@***/Conversations.USVY' from='p2.siacs.eu'>
Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' xml:lang='en' id='M2TspPFQYeVH' to='testdelete@***/Conversations.USVY' from='p2.siacs.eu'>
Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='dBjjGyFLUwq-' xml:lang='en'>
Aug 18 14:05:11 ***:pep debug Creating new persistent item store for user testdelete, node "eu.siacs.conversations.axolotl.bundles:748783226"
Aug 18 14:05:11 ***:storage_internal debug testdelete has 0 items out of 10000 limit in store pep_eu.siacs.conversations.axolotl.bundles:748783226
Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='dBjjGyFLUwq-'>
Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq type='result' xml:lang='en' to='***' id='ebc27627-0576-4317-90ab-796341ad16ab' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='m7dBHrjpOkuZ' xml:lang='en'>
Aug 18 14:05:11 c2s5605dd58c860 info Push notifications enabled for testdelete@***/Conversations.USVY (p2.siacs.eu<C1UIKP2K1A2z)
Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='m7dBHrjpOkuZ'>
Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='qFqXAoukRyj1' to='testdelete@***' from='testdelete@***/Conversations.USVY'>
Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='qFqXAoukRyj1'>
Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='GWAikcgqD5By' xml:lang='en'>
Aug 18 14:05:11 ***:pep debug Creating new persistent item store for user testdelete, node "eu.siacs.conversations.axolotl.devicelist"
Aug 18 14:05:11 ***:storage_internal debug testdelete has 0 items out of 10000 limit in store pep_eu.siacs.conversations.axolotl.devicelist
Aug 18 14:05:11 ***:pep debug Sending notification to testdelete@***/Conversations.USVY from testdelete@*** for node eu.siacs.conversations.axolotl.devicelist
Aug 18 14:05:11 ***:mam debug Not archiving stanza: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'> (headline)
Aug 18 14:05:11 ***:carbons debug Not copying stanza: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'> (default)
Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'>
Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='GWAikcgqD5By'>
Aug 18 14:05:57 ***:throttle_presence debug Suppressing presence updates to testdelete@***/Conversations.USVY
Aug 18 14:07:59 ***:throttle_presence debug Flushing buffer for testdelete@***/Conversations.USVY
Aug 18 14:08:30 ***:throttle_presence debug Suppressing presence updates to testdelete@***/Conversations.USVY
Aug 18 14:09:01 ***:throttle_presence debug Flushing buffer for testdelete@***/Conversations.USVY
Aug 18 14:09:09 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='TJE4_mgKWP44' xml:lang='en'>
Aug 18 14:09:09 datamanager debug Removing empty accounts datastore for user testdelete@***
Aug 18 14:09:09 rostermanager debug load_roster: asked for: testdelete@***
Aug 18 14:09:09 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='TJE4_mgKWP44'>
Aug 18 14:09:09 c2s5605dd58c860 debug c2s stream for testdelete@***/Conversations.USVY closed: Account deleted
Aug 18 14:09:09 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='error' id='TJE4_mgKWP44'>
Aug 18 14:09:09 stanzarouter debug Discarding unhandled error iq (cancel, recipient-unavailable) from c2s: <iq from='testdelete@***/Conversations.USVY' type='error' id='TJE4_mgKWP44'>
Aug 18 14:09:09 c2s5605dd58c860 debug Unbinding resource for testdelete@***/Conversations.USVY (testdelete@***): Account deleted
Aug 18 14:09:09 sessionmanager debug All resources of testdelete are now offline
Aug 18 14:09:09 c2s5605dd58c860 debug Presence from testdelete@***/Conversations.USVY without caps received, skipping
Aug 18 14:09:09 datamanager debug Removing empty pep_eu.siacs.conversations.axolotl.bundles:748783226 datastore for user testdelete@***
Aug 18 14:09:09 datamanager debug Removing empty pep_eu.siacs.conversations.axolotl.devicelist datastore for user testdelete@***
Aug 18 14:09:09 datamanager debug Removing empty pep datastore for user testdelete@***
Aug 18 14:12:14 c2s5605dd58c860 info User removed their account: testdelete@***
MattJ
on
Hi, thanks for the report!
If I remember correctly, I believe we have debugged this with you in the past and the problem was that you are using internal storage with a very large number of users on a public service. The recommendation is to switch to a more efficient storage driver such as SQLite.
If you have evidence that your problem is caused by something else, let us know. But I'm not inclined to spend time debugging the same thing twice :)
Changes
tags Status-NeedInfo
Huxx
on
In past i already migrated to sqlite. The behaviour there still existed. Plus other strange errors. So i migrated back to internal and xmlarchive storage.
Zash
on
Could it be related to the removal of remaining user data at https://hg.prosody.im/0.12/file/0.12.4/core/usermanager.lua#l132 ? Since it happens after the event where mod_pep deletes its data, it seems plausible. It would be iterating over all existing stores. A larger servers likely has a *lot* of PEP node stores since OMEMO would create up to 2 147 483 647 stores.
Huxx
on
So i migrated now the most stores to PostgreSQL. The problem as descripted still exist. Deleted user testpost2 at 21:23:45. Then the prosody server freezes and all users get disconnected. At 21:27 freeze is over and users can connect again.
default_storage = "internal"
storage = {
archive = "xmlarchive";
offline = "xmlarchive";
pep = "sql";
pep_data = "sql";
muc_log = "xmlarchive";
accounts = "sql";
account_details = "sql";
archive2_prefs = "sql";
archive_cleanup = "sql";
archive_prefs = "sql";
cloud_notify = "sql";
lastlog = "sql";
lastlog2 = "sql";
motd_sequential_seen = "sql";
roster = "sql";
private = "sql";
vcard = "sql";
blocklist = "sql";
pupsub_nodes = "sql";
}
Aug 23 21:23:45 rostermanager debug load_roster: asked for: testpost2@***
Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <iq type='result' id='bgwSHZwdz9xC' to='testpost2@***/Conversations.-kmr'>
Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='23'>
Aug 23 21:23:45 c2s56016747b550 debug Disconnecting client, <stream:error> is: <stream:error><not-authorized xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xmlns='urn:ietf:params:xml:ns:xmpp-streams'>Account deleted</text></stream:error>
Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <stream:error>
Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: </stream:stream>
Aug 23 21:23:45 c2s56016747b550 debug c2s stream for testpost2@***/Conversations.-kmr closed: Account deleted
Aug 23 21:23:45 c2s56016747b550 debug Destroying session with 1 unacked stanzas
Aug 23 21:23:45 c2s56016747b550 debug Received[c2s]: <iq type='error' id='bgwSHZwdz9xC' from='testpost2@***/Conversations.-kmr'>
Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 mod_firewall::deliver debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 stanzarouter debug Discarding unhandled error iq (cancel, recipient-unavailable) from c2s: <iq type='error' id='bgwSHZwdz9xC' from='testpost2@***/Conversations.-kmr'>
Aug 23 21:23:45 c2s56016747b550 debug Unbinding resource for testpost2@***/Conversations.-kmr (testpost2@***): Account deleted
Aug 23 21:23:45 sessionmanager debug All resources of testpost2 are now offline
Aug 23 21:23:45 c2s56016747b550 debug Received[c2s]: <presence type='unavailable'>
Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 c2s56016747b550 debug Presence from testpost2@***/Conversations.-kmr without caps received, skipping
Aug 23 21:23:45 mod_firewall::deliver debug Chain "user/pass_acceptable" accepted stanza (ret false)
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:134>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:134>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 socket debug try to close client connection with id: 5601662870f0
Aug 23 21:23:45 socket debug closing delayed until writebuffer is empty
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:578>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:578>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:578>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:578>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()]
Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:685>()]
Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:685>()]
Aug 23 21:27:31 ........
Huxx
on
With telnet i dont see and debug_sql, but i cant see more messages.
module:load("debug_sql");
| Loaded for *
| OK: Module loaded onto 1 host
user:delete("testo1234@***");
| OK: User deleted
server freezes when i want to delete the user. after 5 minutes the prosody server is back. when i then delete another user, everything working fine and no server freeze. when i then wait for example one hour and try the test deleting again, then the server freezes again.
Huxx
on
i also checked the prosody files folder. it looks like it still uses pep from filebased, because it was creating files for it today. but in prosody config i changed it to
pep = "sql";
pep_data = "sql";
77333034 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1318259584
63575280 64K drwxr-x--- 2 prosody prosody 60K 4. Sep 01:18 pep_urn%3axmpp%3aavatar%3ametadata
60818420 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1986304471
63592790 136K drwxr-x--- 2 prosody prosody 132K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2edevicelist
63593089 64K drwxr-x--- 2 prosody prosody 60K 4. Sep 01:18 pep_urn%3axmpp%3aavatar%3adata
71566751 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1140639719
57542022 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1048450496
71697477 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:16 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a491423642
Zash
on
mod_debug_sql enables logging of each SQL query to debug logs, please check those.
Also remember to turn it off afterwards because it logs lots of private information that should not be logged.
Huxx
on
Deleted at Sep 04 15:26:25. Then server freezes till Sep 04 15:32:47.
Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:64>()]
Sep 04 15:26:25 sql debug [select] SELECT "key","type","value" FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='accounts';
Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:64>()]
Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:134>()]
Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='accounts'
Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:134>()]
Sep 04 15:26:25 rostermanager debug load_roster: asked for: testsql@***
Sep 04 15:26:25 rostermanager debug load_roster: loading for offline user: testsql@***
Sep 04 15:26:25 rostermanager debug load_roster: cache miss, loading from storage
Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:64>()]
Sep 04 15:26:25 sql debug [select] SELECT "key","type","value" FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='roster';
Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:64>()]
Sep 04 15:26:25 rostermanager debug load_roster: caching loaded roster
Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:685>()]
Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosody" WHERE "host"='***' AND "user"='testsql'
Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosodyarchive" WHERE "host"='***' AND "user"='testsql'
Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:685>()]
Sep 04 15:32:47 c2s558fce46fe50 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3' xml:lang='en'>
Sep 04 15:32:47 ***:smacks debug Received ack request, acking for 103
Sep 04 15:32:47 c2s558fce46fe50 debug Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='103'>
Sep 04 15:32:47 c2s558fce46fe50 debug Queuing <r> (in a moment) from piggybacked by handle_r - #queue=7
Sep 04 15:32:47 c2s558fce46fe50 debug Handled 104 incoming stanzas
Zash
on
Could you try this in the shell check how long it takes: `>require"core.storagemanager".olddm.purge("test-username", "example.com")`
The the username should either be a sacrificial test account or not exist. Change the domain name to yours as well.
Huxx
on
I took 4 - 5 minutes. Client connections were cutted for that time.
Hello, if a user tries to delete an account, the whole prosody server is locked. Every connected client will be disconnected, when an account will be deleted.Also the whole deleting process tooks mostly 3 minutes. After the account were deleted connection will be again accepted and users can connect again. Prosody version 0.12.4 stable is running on Debian 12.6. default_storage = "internal" storage = { archive = "xmlarchive"; offline = "xmlarchive"; pep = "internal"; pep_data = "internal"; muc_log = "xmlarchive"; accounts = "internal"; account_details = "internal"; archive2_prefs = "internal"; archive_cleanup = "internal"; archive_prefs = "internal"; cloud_notify = "internal"; lastlog = "internal"; lastlog2 = "internal"; motd_sequential_seen = "internal"; roster = "internal"; private = "internal"; vcard = "internal"; blocklist = "internal"; pupsub_nodes = "internal"; } I can reproduce this problem. Created an account testdelete@*** and then start deleting it at 14:09 with conversations client. At 14:12 the deleting process finished. In the debug log there are no more log entries between 14:09 and 14:12. Debug Log cat debug.log | grep testdelete Aug 18 14:05:03 c2s5605e67f92f0 debug Received[c2s_unauthed]: <iq from='testdelete@***' type='set' id='RiMzgZoyzly1' xml:lang='en'> Aug 18 14:05:03 ***:auth_internal_hashed debug account not found for username 'testdelete' Aug 18 14:05:03 c2s5605e67f92f0 debug Sending[c2s_unauthed]: <iq type='result' to='testdelete@***' id='RiMzgZoyzly1'> Aug 18 14:05:03 c2s5605e67f92f0 info User account created: testdelete@*** Aug 18 14:05:04 c2s5605dd58c860 info Authenticated as testdelete@*** Aug 18 14:05:04 rostermanager debug load_roster: asked for: testdelete@*** Aug 18 14:05:04 rostermanager debug load_roster: loading for new user: testdelete@*** Aug 18 14:05:04 mod_firewall::user/bodycheck info spam: bodylines: <message to='testdelete@***' from='***'><body>*** INFO Aug 18 14:05:04 stanzarouter debug Discarding unhandled error message (cancel, not-allowed) from local: <message from='testdelete@***' type='error' to='***'> Aug 18 14:05:04 ***:motd_sequential debug MOTD send to user testdelete@*** Aug 18 14:05:04 ***:pep debug Creating pubsub service for user "testdelete" Aug 18 14:05:04 ***:bookmarks debug No existing legacy bookmarks for testdelete@***, migration already done: (nil) Aug 18 14:05:04 ***:bookmarks debug Additionally, no bookmarks 2 were existing for testdelete@***, assuming empty. Aug 18 14:05:04 c2s5605dd58c860 debug Resource bound: testdelete@***/Conversations.USVY Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='th799pa9wosv' to='***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='result' to='testdelete@***/Conversations.USVY' id='th799pa9wosv'> Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='vY_PNACTsaIJ' xml:lang='en'> Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='vY_PNACTsaIJ'> Aug 18 14:05:04 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='KFDJNw-AR09x' to='testdelete@***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:04 c2s5605dd58c860 debug Sending[c2s]: <iq from='testdelete@***' type='result' to='testdelete@***/Conversations.USVY' id='KFDJNw-AR09x'> Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='8xPbzECq2f2Y' to='conference.***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='conference.***' type='result' to='testdelete@***/Conversations.USVY' id='8xPbzECq2f2Y'> Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='855YX9KH_kzL' to='uploads.***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='uploads.***' type='result' to='testdelete@***/Conversations.USVY' id='855YX9KH_kzL'> Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='yualL_6vu-KV' to='pubsub.***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq from='pubsub.***' type='result' to='testdelete@***/Conversations.USVY' id='yualL_6vu-KV'> Aug 18 14:05:05 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='MkaQ5XfQyrWP' xml:lang='en'> Aug 18 14:05:05 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='MkaQ5XfQyrWP'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='JYUmQNNlhWU-' to='testdelete@***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='JYUmQNNlhWU-'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='nm1a_CDoUeE0' xml:lang='en'> Aug 18 14:05:10 ***:carbons debug testdelete@***/Conversations.USVY enabled carbons Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='nm1a_CDoUeE0'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='ZddrrHNd0BPC' to='***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='result' to='testdelete@***/Conversations.USVY' id='ZddrrHNd0BPC'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='JTuIEOsjowFW' xml:lang='en'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='JTuIEOsjowFW'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='cL3sjhkg2CB6' xml:lang='en'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='cL3sjhkg2CB6'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='1dai1OU-i8pJ' xml:lang='en'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='1dai1OU-i8pJ'> Aug 18 14:05:10 c2s5605dd58c860 debug Presence from testdelete@***/Conversations.USVY with SHA-1 caps http://conversations.im#hV6yIEFlLgDca/x5w67HqrRECe8=, querying disco#info Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <presence xml:lang='en' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:10 ***:storage_xmlarchive debug Loading root index for testdelete Aug 18 14:05:10 ***:storage_xmlarchive debug Loading root index for testdelete Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='PskysOmB6qRk' xml:lang='en'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='PskysOmB6qRk'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='get' id='19kTpzSGvwhi' xml:lang='en'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='19kTpzSGvwhi'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq from='***' type='get' to='testdelete@***/Conversations.USVY' id='ebc27627-0576-4317-90ab-796341ad16ab'> Aug 18 14:05:10 c2s5605dd58c860 debug Received[c2s]: <iq type='set' xml:lang='en' id='M2TspPFQYeVH' to='p2.siacs.eu' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:10 s2sout5605d96f5940 debug Sending[s2sout]: <iq type='set' from='testdelete@***/Conversations.USVY' id='M2TspPFQYeVH' to='p2.siacs.eu' xml:lang='en'> Aug 18 14:05:10 s2sin5605d97fb500 debug Received[s2sin]: <iq type='result' xml:lang='en' id='M2TspPFQYeVH' to='testdelete@***/Conversations.USVY' from='p2.siacs.eu'> Aug 18 14:05:10 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' xml:lang='en' id='M2TspPFQYeVH' to='testdelete@***/Conversations.USVY' from='p2.siacs.eu'> Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='dBjjGyFLUwq-' xml:lang='en'> Aug 18 14:05:11 ***:pep debug Creating new persistent item store for user testdelete, node "eu.siacs.conversations.axolotl.bundles:748783226" Aug 18 14:05:11 ***:storage_internal debug testdelete has 0 items out of 10000 limit in store pep_eu.siacs.conversations.axolotl.bundles:748783226 Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='dBjjGyFLUwq-'> Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq type='result' xml:lang='en' to='***' id='ebc27627-0576-4317-90ab-796341ad16ab' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='m7dBHrjpOkuZ' xml:lang='en'> Aug 18 14:05:11 c2s5605dd58c860 info Push notifications enabled for testdelete@***/Conversations.USVY (p2.siacs.eu<C1UIKP2K1A2z) Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='m7dBHrjpOkuZ'> Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq type='get' xml:lang='en' id='qFqXAoukRyj1' to='testdelete@***' from='testdelete@***/Conversations.USVY'> Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='error' to='testdelete@***/Conversations.USVY' id='qFqXAoukRyj1'> Aug 18 14:05:11 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='GWAikcgqD5By' xml:lang='en'> Aug 18 14:05:11 ***:pep debug Creating new persistent item store for user testdelete, node "eu.siacs.conversations.axolotl.devicelist" Aug 18 14:05:11 ***:storage_internal debug testdelete has 0 items out of 10000 limit in store pep_eu.siacs.conversations.axolotl.devicelist Aug 18 14:05:11 ***:pep debug Sending notification to testdelete@***/Conversations.USVY from testdelete@*** for node eu.siacs.conversations.axolotl.devicelist Aug 18 14:05:11 ***:mam debug Not archiving stanza: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'> (headline) Aug 18 14:05:11 ***:carbons debug Not copying stanza: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'> (default) Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <message from='testdelete@***' type='headline' id='LNLwWDczt2s8Yhrcmb3x1Apb' to='testdelete@***/Conversations.USVY'> Aug 18 14:05:11 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='GWAikcgqD5By'> Aug 18 14:05:57 ***:throttle_presence debug Suppressing presence updates to testdelete@***/Conversations.USVY Aug 18 14:07:59 ***:throttle_presence debug Flushing buffer for testdelete@***/Conversations.USVY Aug 18 14:08:30 ***:throttle_presence debug Suppressing presence updates to testdelete@***/Conversations.USVY Aug 18 14:09:01 ***:throttle_presence debug Flushing buffer for testdelete@***/Conversations.USVY Aug 18 14:09:09 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='set' id='TJE4_mgKWP44' xml:lang='en'> Aug 18 14:09:09 datamanager debug Removing empty accounts datastore for user testdelete@*** Aug 18 14:09:09 rostermanager debug load_roster: asked for: testdelete@*** Aug 18 14:09:09 c2s5605dd58c860 debug Sending[c2s]: <iq type='result' to='testdelete@***/Conversations.USVY' id='TJE4_mgKWP44'> Aug 18 14:09:09 c2s5605dd58c860 debug c2s stream for testdelete@***/Conversations.USVY closed: Account deleted Aug 18 14:09:09 c2s5605dd58c860 debug Received[c2s]: <iq from='testdelete@***/Conversations.USVY' type='error' id='TJE4_mgKWP44'> Aug 18 14:09:09 stanzarouter debug Discarding unhandled error iq (cancel, recipient-unavailable) from c2s: <iq from='testdelete@***/Conversations.USVY' type='error' id='TJE4_mgKWP44'> Aug 18 14:09:09 c2s5605dd58c860 debug Unbinding resource for testdelete@***/Conversations.USVY (testdelete@***): Account deleted Aug 18 14:09:09 sessionmanager debug All resources of testdelete are now offline Aug 18 14:09:09 c2s5605dd58c860 debug Presence from testdelete@***/Conversations.USVY without caps received, skipping Aug 18 14:09:09 datamanager debug Removing empty pep_eu.siacs.conversations.axolotl.bundles:748783226 datastore for user testdelete@*** Aug 18 14:09:09 datamanager debug Removing empty pep_eu.siacs.conversations.axolotl.devicelist datastore for user testdelete@*** Aug 18 14:09:09 datamanager debug Removing empty pep datastore for user testdelete@*** Aug 18 14:12:14 c2s5605dd58c860 info User removed their account: testdelete@***
Hi, thanks for the report! If I remember correctly, I believe we have debugged this with you in the past and the problem was that you are using internal storage with a very large number of users on a public service. The recommendation is to switch to a more efficient storage driver such as SQLite. If you have evidence that your problem is caused by something else, let us know. But I'm not inclined to spend time debugging the same thing twice :)
ChangesIn past i already migrated to sqlite. The behaviour there still existed. Plus other strange errors. So i migrated back to internal and xmlarchive storage.
Could it be related to the removal of remaining user data at https://hg.prosody.im/0.12/file/0.12.4/core/usermanager.lua#l132 ? Since it happens after the event where mod_pep deletes its data, it seems plausible. It would be iterating over all existing stores. A larger servers likely has a *lot* of PEP node stores since OMEMO would create up to 2 147 483 647 stores.
So i migrated now the most stores to PostgreSQL. The problem as descripted still exist. Deleted user testpost2 at 21:23:45. Then the prosody server freezes and all users get disconnected. At 21:27 freeze is over and users can connect again. default_storage = "internal" storage = { archive = "xmlarchive"; offline = "xmlarchive"; pep = "sql"; pep_data = "sql"; muc_log = "xmlarchive"; accounts = "sql"; account_details = "sql"; archive2_prefs = "sql"; archive_cleanup = "sql"; archive_prefs = "sql"; cloud_notify = "sql"; lastlog = "sql"; lastlog2 = "sql"; motd_sequential_seen = "sql"; roster = "sql"; private = "sql"; vcard = "sql"; blocklist = "sql"; pupsub_nodes = "sql"; } Aug 23 21:23:45 rostermanager debug load_roster: asked for: testpost2@*** Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <iq type='result' id='bgwSHZwdz9xC' to='testpost2@***/Conversations.-kmr'> Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='23'> Aug 23 21:23:45 c2s56016747b550 debug Disconnecting client, <stream:error> is: <stream:error><not-authorized xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xmlns='urn:ietf:params:xml:ns:xmpp-streams'>Account deleted</text></stream:error> Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: <stream:error> Aug 23 21:23:45 c2s56016747b550 debug Sending[c2s]: </stream:stream> Aug 23 21:23:45 c2s56016747b550 debug c2s stream for testpost2@***/Conversations.-kmr closed: Account deleted Aug 23 21:23:45 c2s56016747b550 debug Destroying session with 1 unacked stanzas Aug 23 21:23:45 c2s56016747b550 debug Received[c2s]: <iq type='error' id='bgwSHZwdz9xC' from='testpost2@***/Conversations.-kmr'> Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 mod_firewall::deliver debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 stanzarouter debug Discarding unhandled error iq (cancel, recipient-unavailable) from c2s: <iq type='error' id='bgwSHZwdz9xC' from='testpost2@***/Conversations.-kmr'> Aug 23 21:23:45 c2s56016747b550 debug Unbinding resource for testpost2@***/Conversations.-kmr (testpost2@***): Account deleted Aug 23 21:23:45 sessionmanager debug All resources of testpost2 are now offline Aug 23 21:23:45 c2s56016747b550 debug Received[c2s]: <presence type='unavailable'> Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 mod_firewall::preroute debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 c2s56016747b550 debug Presence from testpost2@***/Conversations.-kmr without caps received, skipping Aug 23 21:23:45 mod_firewall::deliver debug Chain "user/pass_acceptable" accepted stanza (ret false) Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:134>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:134>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 socket debug try to close client connection with id: 5601662870f0 Aug 23 21:23:45 socket debug closing delayed until writebuffer is empty Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:578>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:578>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:578>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:578>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:194>()] Aug 23 21:23:45 sql debug SQL transaction begin [function<mod_storage_sql.lua:685>()] Aug 23 21:23:45 sql debug SQL transaction success [function<mod_storage_sql.lua:685>()] Aug 23 21:27:31 ........
With telnet i dont see and debug_sql, but i cant see more messages. module:load("debug_sql"); | Loaded for * | OK: Module loaded onto 1 host user:delete("testo1234@***"); | OK: User deleted server freezes when i want to delete the user. after 5 minutes the prosody server is back. when i then delete another user, everything working fine and no server freeze. when i then wait for example one hour and try the test deleting again, then the server freezes again.
i also checked the prosody files folder. it looks like it still uses pep from filebased, because it was creating files for it today. but in prosody config i changed it to pep = "sql"; pep_data = "sql"; 77333034 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1318259584 63575280 64K drwxr-x--- 2 prosody prosody 60K 4. Sep 01:18 pep_urn%3axmpp%3aavatar%3ametadata 60818420 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1986304471 63592790 136K drwxr-x--- 2 prosody prosody 132K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2edevicelist 63593089 64K drwxr-x--- 2 prosody prosody 60K 4. Sep 01:18 pep_urn%3axmpp%3aavatar%3adata 71566751 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1140639719 57542022 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:18 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a1048450496 71697477 4,0K drwxr-x--- 2 prosody prosody 4,0K 4. Sep 01:16 pep_eu%2esiacs%2econversations%2eaxolotl%2ebundles%3a491423642
mod_debug_sql enables logging of each SQL query to debug logs, please check those. Also remember to turn it off afterwards because it logs lots of private information that should not be logged.
Deleted at Sep 04 15:26:25. Then server freezes till Sep 04 15:32:47. Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:64>()] Sep 04 15:26:25 sql debug [select] SELECT "key","type","value" FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='accounts'; Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:64>()] Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:134>()] Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='accounts' Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:134>()] Sep 04 15:26:25 rostermanager debug load_roster: asked for: testsql@*** Sep 04 15:26:25 rostermanager debug load_roster: loading for offline user: testsql@*** Sep 04 15:26:25 rostermanager debug load_roster: cache miss, loading from storage Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:64>()] Sep 04 15:26:25 sql debug [select] SELECT "key","type","value" FROM "prosody" WHERE "host"='***' AND "user"='testsql' AND "store"='roster'; Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:64>()] Sep 04 15:26:25 rostermanager debug load_roster: caching loaded roster Sep 04 15:26:25 sql debug SQL transaction begin [function<mod_storage_sql.lua:685>()] Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosody" WHERE "host"='***' AND "user"='testsql' Sep 04 15:26:25 sql debug [delete] DELETE FROM "prosodyarchive" WHERE "host"='***' AND "user"='testsql' Sep 04 15:26:25 sql debug SQL transaction success [function<mod_storage_sql.lua:685>()] Sep 04 15:32:47 c2s558fce46fe50 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3' xml:lang='en'> Sep 04 15:32:47 ***:smacks debug Received ack request, acking for 103 Sep 04 15:32:47 c2s558fce46fe50 debug Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='103'> Sep 04 15:32:47 c2s558fce46fe50 debug Queuing <r> (in a moment) from piggybacked by handle_r - #queue=7 Sep 04 15:32:47 c2s558fce46fe50 debug Handled 104 incoming stanzas
Could you try this in the shell check how long it takes: `>require"core.storagemanager".olddm.purge("test-username", "example.com")` The the username should either be a sacrificial test account or not exist. Change the domain name to yours as well.
I took 4 - 5 minutes. Client connections were cutted for that time.