If the event "resource-bind" takes longer (due to modules loaded that may delay the completion of the event) the following sequence can trigger a backtrace:
1. Client connects and sends bind request
2. Same client or other client connects and binds to the same resource
3. The stream of (1) gets closed and the tcp connection dropped due to conflicting resource (default prosody config)
4. The resource-bind event returns and the backtrace occurs
On a mobile device that changes its connectivity (wifi to mobile or vice versa) just after the bind request was send and thus reconnects can trigger this bug.
Backtraces (mod_kwo_roster.lua delays the completion of the event via async wait() and done() while fetching the roster in the background via http, thus the timing):
Mar 14 18:39:28 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 'run'
/usr/lib/prosody/util/async.lua:63: in function 'runner_continue'
/usr/lib/prosody/util/async.lua:79: in function 'done'
...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:256: in function 'cb'
...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:240: in function 'cb'
...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:174: in function <...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:164>
[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 14 18:39:28 http error Request '<nil>': error in callback: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value)
Mar 14 18:39:28 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 14 18:39:28 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]: ?
Zash
on
Thanks for the report.
It would be great if you could reduce your non-public code to something that can be used to reproduce
Changes
tags Status-Accepted
Thilo Molitor
on
This code should be the minimal version of the roster module...but it seems to be a timing issue (like the osser issue I posted) because it only happened once in over 2 weeks.
local http = require "net.http";
local async = require "util.async";
function call_http(cb)
local x = {headers = {}};
local ok, err = http.request(
"https://www.example.org",
x,
function (data, code)
cb(true);
end
);
if not ok then
cb(false);
end
end
module:hook("resource-bind", function(event)
local wait, done = async.waiter();
call_http(function (ok)
done();
end);
module:log("debug", "Halting resource-bind event while waiting for http request");
wait();
module:log("debug", "Restarting resource-bind event");
end);
If the event "resource-bind" takes longer (due to modules loaded that may delay the completion of the event) the following sequence can trigger a backtrace: 1. Client connects and sends bind request 2. Same client or other client connects and binds to the same resource 3. The stream of (1) gets closed and the tcp connection dropped due to conflicting resource (default prosody config) 4. The resource-bind event returns and the backtrace occurs On a mobile device that changes its connectivity (wifi to mobile or vice versa) just after the bind request was send and thus reconnects can trigger this bug. Backtraces (mod_kwo_roster.lua delays the completion of the event via async wait() and done() while fetching the roster in the background via http, thus the timing): Mar 14 18:39:28 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 'run' /usr/lib/prosody/util/async.lua:63: in function 'runner_continue' /usr/lib/prosody/util/async.lua:79: in function 'done' ...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:256: in function 'cb' ...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:240: in function 'cb' ...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:174: in function <...r/local/lib/prosody-modules.local/mod_kwo_roster.lua:164> [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 14 18:39:28 http error Request '<nil>': error in callback: /usr/lib/prosody/modules/mod_c2s.lua:238: attempt to index field 'conn' (a nil value) Mar 14 18:39:28 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 14 18:39:28 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]: ?
Thanks for the report. It would be great if you could reduce your non-public code to something that can be used to reproduce
ChangesThis code should be the minimal version of the roster module...but it seems to be a timing issue (like the osser issue I posted) because it only happened once in over 2 weeks. local http = require "net.http"; local async = require "util.async"; function call_http(cb) local x = {headers = {}}; local ok, err = http.request( "https://www.example.org", x, function (data, code) cb(true); end ); if not ok then cb(false); end end module:hook("resource-bind", function(event) local wait, done = async.waiter(); call_http(function (ok) done(); end); module:log("debug", "Halting resource-bind event while waiting for http request"); wait(); module:log("debug", "Restarting resource-bind event"); end);
I think my patch in https://issues.prosody.im/1515 will solve this, too
https://hg.prosody.im/0.11/rev/133e8ed291fe Thanks
Changes