I got the following backtrace in prosody trunk: Mar 25 02:12:26 c2s555587e9cda0 error Traceback[c2s]: /usr/lib/prosody/modules/mod_saslauth.lua:52: attempt to index field 'sasl_handler' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_saslauth.lua:52: in function 'handle_status' /usr/lib/prosody/modules/mod_saslauth.lua:78: in function </usr/lib/prosody/modules/mod_saslauth.lua:67> (tail call): ? /usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75> (tail call): ? /usr/lib/prosody/core/stanza_router.lua:143: in function 'core_process_stanza' /usr/lib/prosody/modules/mod_c2s.lua:283: in function 'func' /usr/lib/prosody/util/async.lua:127: in function </usr/lib/prosody/util/async.lua:125> Mar 25 02:12:26 http error Traceback[http]: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_c2s.lua:238: in function 'handler' /usr/lib/prosody/util/async.lua:211: in function </usr/lib/prosody/util/async.lua:149> (tail call): ? /usr/lib/prosody/util/async.lua:79: in function 'done' ...usr/local/lib/prosody-modules.local/mod_auth_kwo.lua:103: in function <...usr/local/lib/prosody-modules.local/mod_auth_kwo.lua:101> [C]: in function 'xpcall' /usr/lib/prosody/net/http.lua:104: in function 'callback' /usr/lib/prosody/net/http.lua:76: in function 'success_cb' /usr/lib/prosody/net/http/parser.lua:171: in function 'feed' /usr/lib/prosody/net/http.lua:86: in function 'reader' /usr/lib/prosody/net/http.lua:158: in function 'onincoming' /usr/lib/prosody/net/server_event.lua:641: in function </usr/lib/prosody/net/server_event.lua:590> [C]: in function 'loop' /usr/lib/prosody/net/server_event.lua:796: in function </usr/lib/prosody/net/server_event.lua:795> [C]: in function 'xpcall' /usr/bin/prosody:76: in function 'loop' /usr/bin/prosody:86: in main chunk [C]: ? Mar 25 02:12:26 http error Request '<nil>': error in callback: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value) Mar 25 02:12:26 general error Top-level error, please report: /usr/lib/prosody/net/http.lua:45: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value) stack traceback: [C]: in function 'error' /usr/lib/prosody/net/http.lua:45: in function </usr/lib/prosody/net/http.lua:41> (tail call): ? /usr/lib/prosody/net/http.lua:76: in function 'success_cb' /usr/lib/prosody/net/http/parser.lua:171: in function 'feed' /usr/lib/prosody/net/http.lua:86: in function 'reader' /usr/lib/prosody/net/http.lua:158: in function 'onincoming' /usr/lib/prosody/net/server_event.lua:641: in function </usr/lib/prosody/net/server_event.lua:590> [C]: in function 'loop' /usr/lib/prosody/net/server_event.lua:796: in function </usr/lib/prosody/net/server_event.lua:795> [C]: in function 'xpcall' /usr/bin/prosody:76: in function 'loop' /usr/bin/prosody:86: in main chunk [C]: ? Mar 25 02:12:26 general error stack traceback: [C]: in function 'loop' /usr/lib/prosody/net/server_event.lua:796: in function </usr/lib/prosody/net/server_event.lua:795> [C]: in function 'xpcall' /usr/bin/prosody:76: in function 'loop' /usr/bin/prosody:86: in main chunk [C]: ?

Looks like either a dupe of #1507 or problems caused by it. Other than that this is lacking in context and details, and it involves a non-public module.

• tags Status-NeedInfo

the non public module (mod_auth_kwo) only does an util.http call and calls async.done() in the http.request() callback, nothing special here. The http request is made in plain_test_password() which is registered here: function provider.get_sasl_handler(session) return new_sasl(host, { plain_test = function(sasl, username, password, realm) return plain_test_password(session, username, password), true; end, }); end But yes, this could be a duplicate.

Okay, after looking at the other backtrace I don't think this is a duplicate. Both traces show a timing issue because util.hhtp is used in combination with util.async to stop the current code flow and resume it later on at which stage it could be that underlying data has changed (the connection got closed etc.).

I coded a simple test module that can be used as auth handler for prosody trunk: https://dyn.eightysoft.de/mod_auth_test.lua This produces the following log and backtrace when connecting with gajim (the empty lines are there to mark timestamp changes) which shows exactly the same problem as in my backtraces I posted earlier: Apr 29 01:25:46 c2s55a896a40880 debug RECV(88): <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">AGR1bW15AHh4eA==</auth> Apr 29 01:25:46 c2s55a896a40880 debug Received[c2s_unauthed]: <auth xml:lang='de' mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Apr 29 01:25:46 localhost:auth_test debug Testing password for user dummy (sleeping for 10 seconds) Apr 29 01:25:46 runnerksUDgxPK debug changed state from ready to waiting Apr 29 01:25:48 c2s55a896a40880 debug Disconnecting client, <stream:error> is: <stream:error><connection-timeout xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error> Apr 29 01:25:48 c2s55a896a40880 debug Sending[c2s_unauthed]: <stream:error> Apr 29 01:25:48 c2s55a896a40880 debug SEND(94): <stream:error><connection-timeout xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error> Apr 29 01:25:48 c2s55a896a40880 debug Sending[c2s_unauthed]: </stream:stream> Apr 29 01:25:48 c2s55a896a40880 debug SEND(16): </stream:stream> Apr 29 01:25:48 c2s55a896a40880 debug c2s stream for ::1 closed: connection-timeout Apr 29 01:25:48 c2s55a896a40880 debug Destroying session for (unknown) ((unknown)@localhost): connection-timeout Apr 29 01:25:48 socket debug try to close client connection with id: 55a896a3f090 Apr 29 01:25:48 socket debug closing delayed until writebuffer is empty Apr 29 01:25:48 socket debug closing client after writing Apr 29 01:25:48 socket debug closing client with id: 55a896a3f090 client to close Apr 29 01:25:48 c2s55a896a40880 info Client disconnected: connection closed Apr 29 01:25:48 c2s55a896a40880 debug Destroying session for (unknown) ((unknown)@(unknown)) Apr 29 01:25:56 localhost:auth_test debug Auth provider confirmed valid password Apr 29 01:25:56 runnerksUDgxPK debug Calling 'error' watcher Apr 29 01:25:56 c2s55a896a40880 error Traceback[c2s]: /usr/lib/prosody/modules/mod_saslauth.lua:52: attempt to index field 'sasl_handler' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_saslauth.lua:52: in function 'handle_status' /usr/lib/prosody/modules/mod_saslauth.lua:78: in function </usr/lib/prosody/modules/mod_saslauth.lua:67> (...tail calls...) /usr/share/lua/5.2/prosody/util/events.lua:79: in function </usr/share/lua/5.2/prosody/util/events.lua:75> (...tail calls...) /usr/share/lua/5.2/prosody/core/stanza_router.lua:143: in function 'core_process_stanza' /usr/lib/prosody/modules/mod_c2s.lua:283: in function 'func' /usr/share/lua/5.2/prosody/util/async.lua:127: in function </usr/share/lua/5.2/prosody/util/async.lua:125> Apr 29 01:25:56 runnerksUDgxPK debug creating new coroutine Apr 29 01:25:56 runnerksUDgxPK debug changed state from waiting to ready Apr 29 01:25:56 timer error Traceback[timer]: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_c2s.lua:238: in function 'handler' /usr/share/lua/5.2/prosody/util/async.lua:211: in function </usr/share/lua/5.2/prosody/util/async.lua:149> (...tail calls...) /usr/share/lua/5.2/prosody/util/async.lua:79: in function 'done' /usr/lib/prosody/modules/mod_auth_test.lua:36: in function </usr/lib/prosody/modules/mod_auth_test.lua:35> (...tail calls...) [C]: in function 'xpcall' /usr/share/lua/5.2/prosody/util/timer.lua:39: in function 'callback' /usr/share/lua/5.2/prosody/net/server_event.lua:864: in function </usr/share/lua/5.2/prosody/net/server_event.lua:863> [C]: in function 'loop' /usr/share/lua/5.2/prosody/net/server_event.lua:796: in function </usr/share/lua/5.2/prosody/net/server_event.lua:795> [C]: in function 'xpcall' /usr/bin/prosody:62: in function 'loop' /usr/bin/prosody:72: in main chunk [C]: in ?

I propose this fix: https://dyn.eightysoft.de/prosody.patch

Can reproduce using the test auth module, thanks for that. The patch doesn't seem to follow our code and commit style guidelines and I'm not sure if it's the right approach, will have to look further into the issue.

• tags Patch Status-Accepted

What guidelines does it not follow? Well it is okay for me if you solve this problem going another route. But currently it is spamming my logfiles really bad :(

https://hg.prosody.im/0.11/rev/f1abc34414bc Thanks

• tags Milestone-0.11 Status-Fixed
• owner Zash