#1419 net/server_select.lua: attempt to call upvalue 'dispatch' (a nil value)
Reporter
perflyst
Owner
Nobody
Created
Updated
Stars
★★ (2)
Tags
Priority-Medium
Type-Defect
Milestone-0.12
Component-Network
Status-Accepted
perflyst
on
What steps will reproduce the problem?
unknown
What do you see instead?
Sep 02 07:02:12 s2sin56534f572120 warn No certificate provided by pubsub.beta.kontalk.net
Sep 02 07:02:12 mod_s2s warn Forbidding insecure connection to/from pubsub.beta.kontalk.net
Sep 02 07:02:13 general error Top-level error, please report:
/usr/lib/prosody/net/server_select.lua:523: attempt to call upvalue 'dispatch' (a nil value)
Sep 02 07:02:13 general error
stack traceback:
/usr/lib/prosody/net/server_select.lua:523: in function 'readbuffer'
/usr/lib/prosody/net/server_select.lua:943: in function </usr/lib/prosody/net/server_select.lua:927>
[C]: in function 'xpcall'
/usr/lib/prosody/../../bin/prosody:80: in function 'loop'
/usr/lib/prosody/../../bin/prosody:90: in main chunk
[C]: ?
What version of the product are you using? On what operating system?
Prosody trunk nightly build 1136 (2019-09-01, 6c804b6b2ca2) on Debian Stretch
Please provide any additional information below.
pubsub.beta.kontalk.net does not exist in public internet, dunno whats going on there in general: https://forum.kontalk.org/t/expired-certificate-on-pubsub-beta-kontalk-net/685/2
Zash
on
Thanks for the report.
I'm not entirely sure whether the s2s connection is directly related,
more debug logs would help if you can catch this with debug logging enabled.
Changes
tags Status-NeedInfo
perflyst
on
This is what I could catch
Sep 04 20:22:05 socket debug server.lua: auto-starting ssl negotiation...
Sep 04 20:22:05 socket debug server.lua: attempting to start tls on tcp{client}: 0x55f010d93278
Sep 04 20:22:05 socket debug server.lua: accepted new client connection from IPV6-1:49688 to 5281
Sep 04 20:22:05 socket debug server.lua: ssl handshake done
Sep 04 20:22:05 socket debug server.lua: closed client handler and removed socket from list
Sep 04 20:22:06 general error Top-level error, please report:
/usr/lib/prosody/net/server_select.lua:528: attempt to call upvalue 'dispatch' (a nil value)
Sep 04 20:22:06 general error
stack traceback:
/usr/lib/prosody/net/server_select.lua:528: in function 'readbuffer'
/usr/lib/prosody/net/server_select.lua:948: in function </usr/lib/prosody/net/server_select.lua:932>
[C]: in function 'xpcall'
/usr/lib/prosody/../../bin/prosody:80: in function 'loop'
/usr/lib/prosody/../../bin/prosody:90: in main chunk
[C]: ?
Sep 04 20:22:06 socket debug server.lua: client IPV6-2:clientport read error: closed
Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] Connection attempt failed: closed
Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] Checking for targets...
Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] No more connection targets to try
Sep 04 20:22:06 s2sout55f00f870ca0 debug s2s connection attempt failed: closed
Sep 04 20:22:06 s2sout55f00f870ca0 debug s2s disconnected: snopyta.org->chinwag.im (closed)
Sep 04 20:22:06 s2sout55f00f870ca0 debug Destroying outgoing session snopyta.org->chinwag.im: closed
Sep 04 20:22:06 s2sout55f00f870ca0 info Sending error replies for 2 queued stanzas because of failed outgoing connection to chinwag.im
Sep 04 20:22:06 stanzarouter debug Received[s2sin]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x@chinwag.im'>
Sep 04 20:22:06 c2s55f0135836a0 debug Sending[c2s]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x@chinwag.im'>
Sep 04 20:22:06 stanzarouter debug Received[s2sin]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x2@chinwag.im'>
Sep 04 20:22:06 c2s55f0135836a0 debug Sending[c2s]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x2@chinwag.im'>
Sep 04 20:22:06 socket debug server.lua: closed client handler and removed socket from list
Sep 04 20:22:06 socket debug server.lua: found no handler and closed socket (writelist)
I believe this comes from net.connect not having an 'onincoming' listener callback, but it shouldn't need to because it replaces the listeners on connect.
Zash
on
Changes
tags Milestone-0.12 Component-Network
Zash
on
server_select
connection attempt to example.org (literally that) results in this (extended tracebacks enabled):
Dec 01 19:31:36 general error Top-level error, please report:
./net/server_select.lua:528: attempt to call a nil value (upvalue 'dispatch')
Dec 01 19:31:36 general error
stack traceback:
v--------------------- ./util/debug.lua ----------------------v
>(0) [Lua] ./util/debug.lua line 143 in (defined on line 121)
Locals: { thread = thread: 0x5567d22d7268, start_level = 2,
levels = table: 0x5567d2852510, level = 2, info = table: 0x5567d2852550 }
Upvals: { _ENV = table: 0x5567d22d7b80,
get_traceback_table = function(debug.lua:93), getstring = function(termcolours.lua:56),
styles = table: 0x5567d230f940, build_source_boundary_marker = function(debug.lua:114),
string_from_var_table = function(debug.lua:57), optimal_line_length = 65 }
v-------------------------- C code ---------------------------v
(1) [ C ] global C function "pcall"
Locals: { thread = thread: 0x5567d22d7268, message = "\
", level = 2 }
v--------------------- ./util/debug.lua ----------------------v
(2) [Lua] ./util/debug.lua line 195 in field "traceback" (defined on line 194)
Upvals: { _ENV = table: 0x5567d22d7b80, _traceback = function(debug.lua:121) }
v------------------------- ./prosody -------------------------v
(3) [Lua] ./prosody line 69 in upvalue "dispatch" (defined on line 63)
Upvals: { _ENV = table: 0x5567d22d7b80 }
v------------------ ./net/server_select.lua ------------------v
(4) [Lua] ./net/server_select.lua line 528 in field "readbuffer" (defined on line 514)
Locals: {
err = "./net/server_select.lua:528: attempt to call a nil value (upv… }
Upvals: { receive = function([C]:-1), socket = tcp{client}: 0x5567d283aae8,
pattern = "*a", maxreadlen = 25600000, handler = table: 0x5567d2839d20, STAT_UNIT = 1,
readtraffic = 0, _readtraffic = 250, _readtimes = table: 0x5567d23f3dd0,
_currenttime = 1575225096.8625, dispatch = nil, out_put = function(server_select.lua:15),
tostring = function([C]:-1), ip = "93.184.216.34", clientport = "clientport", _ = nil }
(5) [Lua] ./net/server_select.lua line 948 in (defined on line 932)
Locals: { buffer = nil, err = "timeout", part = "", buffer = "", len = 0, count = 0 }
Upvals: { quitting = nil, _currenttime = 1575225096.8625,
luasocket_gettime = function([C]:-1), math_huge = inf, _timerlistlen = 1,
_timerlist = table: 0x5567d23f3d50, math_min = function([C]:-1), socket_select = function([C]:-1),
_readlist = table: 0x5567d23f3cd0, _sendlist = table: 0x5567d23f3d10, _selecttimeout = 1,
ipairs = function([C]:-1), _socketlist = table: 0x5567d23f3d90,
closesocket = function(server_select.lua:726), out_put = function(server_select.lua:15), pairs = function([C]:-1),
_closelist = table: 0x5567d240b530, _starttime = 1575225067.9047, _checkinterval = 30,
_writetimes = table: 0x5567d2400970, _sendtimeout = 60000, _readtimes = table: 0x5567d23f3dd0,
_readtimeout = 840, _fullservers = table: 0x5567d240b420, _accepretry = 10,
closeall = function(server_select.lua:820) }
v-------------------------- C code ---------------------------v
(6) [ C ] global C function "xpcall"
Locals: { once = nil, next_timer_time = 57.997311115265,
read = table: 0x5567d2851f80, write = table: 0x5567d2851ff0, err = nil, _ = 1,
socket = tcp{client}: 0x5567d283aae8, handler = table: 0x5567d2839d20 }
v------------------------- ./prosody -------------------------v
(7) [Lua] ./prosody line 80 in local function "loop" (defined on line 61)
Upvals: { _ENV = table: 0x5567d22d7b80 }
(8) [Lua] ./prosody line 90
Locals: { catch_uncaught_error = function(prosody:63),
sleep = function([C]:-1), server = table: 0x5567d240d1c0 }
Upvals: { _ENV = table: 0x5567d22d7b80 }
v-------------------------- C code ---------------------------v
(9) [ C ] C function (unknown name)
Locals: { is_relative = function(prosody:21), startup = table: 0x5567d22df6c0,
async = table: 0x5567d2390930, thread = table: 0x5567d2390e00, loop = function(prosody:61),
cleanup = function(prosody:85) }
Zash
on
After some testing it looks like server_select calls the callbacks in the weirdest order:
onincoming("") -- yes, the empty string, yes, before onconnect
onconnect()
ondrain()
ondisconnect("closed")
See #528
As a workaround, use libevent or server_epoll.
What steps will reproduce the problem? unknown What do you see instead? Sep 02 07:02:12 s2sin56534f572120 warn No certificate provided by pubsub.beta.kontalk.net Sep 02 07:02:12 mod_s2s warn Forbidding insecure connection to/from pubsub.beta.kontalk.net Sep 02 07:02:13 general error Top-level error, please report: /usr/lib/prosody/net/server_select.lua:523: attempt to call upvalue 'dispatch' (a nil value) Sep 02 07:02:13 general error stack traceback: /usr/lib/prosody/net/server_select.lua:523: in function 'readbuffer' /usr/lib/prosody/net/server_select.lua:943: in function </usr/lib/prosody/net/server_select.lua:927> [C]: in function 'xpcall' /usr/lib/prosody/../../bin/prosody:80: in function 'loop' /usr/lib/prosody/../../bin/prosody:90: in main chunk [C]: ? What version of the product are you using? On what operating system? Prosody trunk nightly build 1136 (2019-09-01, 6c804b6b2ca2) on Debian Stretch Please provide any additional information below. pubsub.beta.kontalk.net does not exist in public internet, dunno whats going on there in general: https://forum.kontalk.org/t/expired-certificate-on-pubsub-beta-kontalk-net/685/2
Thanks for the report. I'm not entirely sure whether the s2s connection is directly related, more debug logs would help if you can catch this with debug logging enabled.
ChangesThis is what I could catch Sep 04 20:22:05 socket debug server.lua: auto-starting ssl negotiation... Sep 04 20:22:05 socket debug server.lua: attempting to start tls on tcp{client}: 0x55f010d93278 Sep 04 20:22:05 socket debug server.lua: accepted new client connection from IPV6-1:49688 to 5281 Sep 04 20:22:05 socket debug server.lua: ssl handshake done Sep 04 20:22:05 socket debug server.lua: closed client handler and removed socket from list Sep 04 20:22:06 general error Top-level error, please report: /usr/lib/prosody/net/server_select.lua:528: attempt to call upvalue 'dispatch' (a nil value) Sep 04 20:22:06 general error stack traceback: /usr/lib/prosody/net/server_select.lua:528: in function 'readbuffer' /usr/lib/prosody/net/server_select.lua:948: in function </usr/lib/prosody/net/server_select.lua:932> [C]: in function 'xpcall' /usr/lib/prosody/../../bin/prosody:80: in function 'loop' /usr/lib/prosody/../../bin/prosody:90: in main chunk [C]: ? Sep 04 20:22:06 socket debug server.lua: client IPV6-2:clientport read error: closed Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] Connection attempt failed: closed Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] Checking for targets... Sep 04 20:22:06 net.connect debug [pending connection i5sHRKm-] No more connection targets to try Sep 04 20:22:06 s2sout55f00f870ca0 debug s2s connection attempt failed: closed Sep 04 20:22:06 s2sout55f00f870ca0 debug s2s disconnected: snopyta.org->chinwag.im (closed) Sep 04 20:22:06 s2sout55f00f870ca0 debug Destroying outgoing session snopyta.org->chinwag.im: closed Sep 04 20:22:06 s2sout55f00f870ca0 info Sending error replies for 2 queued stanzas because of failed outgoing connection to chinwag.im Sep 04 20:22:06 stanzarouter debug Received[s2sin]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x@chinwag.im'> Sep 04 20:22:06 c2s55f0135836a0 debug Sending[c2s]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x@chinwag.im'> Sep 04 20:22:06 stanzarouter debug Received[s2sin]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x2@chinwag.im'> Sep 04 20:22:06 c2s55f0135836a0 debug Sending[c2s]: <iq id='xx' type='error' to='x@snopyta.org/a' from='x2@chinwag.im'> Sep 04 20:22:06 socket debug server.lua: closed client handler and removed socket from list Sep 04 20:22:06 socket debug server.lua: found no handler and closed socket (writelist)
#1456 is a duplicate of this issue.
I believe this comes from net.connect not having an 'onincoming' listener callback, but it shouldn't need to because it replaces the listeners on connect.
server_select connection attempt to example.org (literally that) results in this (extended tracebacks enabled): Dec 01 19:31:36 general error Top-level error, please report: ./net/server_select.lua:528: attempt to call a nil value (upvalue 'dispatch') Dec 01 19:31:36 general error stack traceback: v--------------------- ./util/debug.lua ----------------------v >(0) [Lua] ./util/debug.lua line 143 in (defined on line 121) Locals: { thread = thread: 0x5567d22d7268, start_level = 2, levels = table: 0x5567d2852510, level = 2, info = table: 0x5567d2852550 } Upvals: { _ENV = table: 0x5567d22d7b80, get_traceback_table = function(debug.lua:93), getstring = function(termcolours.lua:56), styles = table: 0x5567d230f940, build_source_boundary_marker = function(debug.lua:114), string_from_var_table = function(debug.lua:57), optimal_line_length = 65 } v-------------------------- C code ---------------------------v (1) [ C ] global C function "pcall" Locals: { thread = thread: 0x5567d22d7268, message = "\ ", level = 2 } v--------------------- ./util/debug.lua ----------------------v (2) [Lua] ./util/debug.lua line 195 in field "traceback" (defined on line 194) Upvals: { _ENV = table: 0x5567d22d7b80, _traceback = function(debug.lua:121) } v------------------------- ./prosody -------------------------v (3) [Lua] ./prosody line 69 in upvalue "dispatch" (defined on line 63) Upvals: { _ENV = table: 0x5567d22d7b80 } v------------------ ./net/server_select.lua ------------------v (4) [Lua] ./net/server_select.lua line 528 in field "readbuffer" (defined on line 514) Locals: { err = "./net/server_select.lua:528: attempt to call a nil value (upv… } Upvals: { receive = function([C]:-1), socket = tcp{client}: 0x5567d283aae8, pattern = "*a", maxreadlen = 25600000, handler = table: 0x5567d2839d20, STAT_UNIT = 1, readtraffic = 0, _readtraffic = 250, _readtimes = table: 0x5567d23f3dd0, _currenttime = 1575225096.8625, dispatch = nil, out_put = function(server_select.lua:15), tostring = function([C]:-1), ip = "93.184.216.34", clientport = "clientport", _ = nil } (5) [Lua] ./net/server_select.lua line 948 in (defined on line 932) Locals: { buffer = nil, err = "timeout", part = "", buffer = "", len = 0, count = 0 } Upvals: { quitting = nil, _currenttime = 1575225096.8625, luasocket_gettime = function([C]:-1), math_huge = inf, _timerlistlen = 1, _timerlist = table: 0x5567d23f3d50, math_min = function([C]:-1), socket_select = function([C]:-1), _readlist = table: 0x5567d23f3cd0, _sendlist = table: 0x5567d23f3d10, _selecttimeout = 1, ipairs = function([C]:-1), _socketlist = table: 0x5567d23f3d90, closesocket = function(server_select.lua:726), out_put = function(server_select.lua:15), pairs = function([C]:-1), _closelist = table: 0x5567d240b530, _starttime = 1575225067.9047, _checkinterval = 30, _writetimes = table: 0x5567d2400970, _sendtimeout = 60000, _readtimes = table: 0x5567d23f3dd0, _readtimeout = 840, _fullservers = table: 0x5567d240b420, _accepretry = 10, closeall = function(server_select.lua:820) } v-------------------------- C code ---------------------------v (6) [ C ] global C function "xpcall" Locals: { once = nil, next_timer_time = 57.997311115265, read = table: 0x5567d2851f80, write = table: 0x5567d2851ff0, err = nil, _ = 1, socket = tcp{client}: 0x5567d283aae8, handler = table: 0x5567d2839d20 } v------------------------- ./prosody -------------------------v (7) [Lua] ./prosody line 80 in local function "loop" (defined on line 61) Upvals: { _ENV = table: 0x5567d22d7b80 } (8) [Lua] ./prosody line 90 Locals: { catch_uncaught_error = function(prosody:63), sleep = function([C]:-1), server = table: 0x5567d240d1c0 } Upvals: { _ENV = table: 0x5567d22d7b80 } v-------------------------- C code ---------------------------v (9) [ C ] C function (unknown name) Locals: { is_relative = function(prosody:21), startup = table: 0x5567d22df6c0, async = table: 0x5567d2390930, thread = table: 0x5567d2390e00, loop = function(prosody:61), cleanup = function(prosody:85) }
After some testing it looks like server_select calls the callbacks in the weirdest order: onincoming("") -- yes, the empty string, yes, before onconnect onconnect() ondrain() ondisconnect("closed") See #528 As a workaround, use libevent or server_epoll.
Changes