Hello all,
As I stated in my message in the chatroom some time ago, I've
experienced some full hangs of prosody on my OpenBSD based server. After
some inspection with top and ktrace it turned out that prosody is
hanging on the netio channel, and specifically hanging on a blocking
write. It was suggested in the chatroom by Zash that it's luasec that
puts the socket in blocking mode. The attached diffs address this and I
can cautiously say that it fixes my problem. Since the issue is very
sporadic I can't be 100% certain.
So first my analysis of luasec. in ssl.c the socket is put into blocking
mode right before calling SSL_shutdown() inside meth_destroy(). My best
guess to why this is is because meth_destroy is linked to the __close
and __gc methods, which can't exactly be called multiple times and
luasec does want to make sure that a tls session is shutdown as clean
as possible.
I can't say I disagree with this reasoning and don't want to change this
behaviour. My solution to this without changing the current behaviour is
to introduce a shutdown() method. I am aware that this overlaps in a
conflicting way with tcp's shutdown method, but it stays close to the
OpenSSL name. This method calls SSL_shutdown() in the current
(non)blocking mode of the underlying socket and returns a boolean
whether or not the shutdown is completed (matching SSL_shutdown()'s 0
or 1 return values), and returns the familiar ssl_ioerror() strings on
error with a false for completion. This error can then be used to
determine if we have wantread/wantwrite to finalize things. Once
meth_shutdown() has been called once a shutdown flag will be set, which
indicates to meth_destroy() that the SSL_shutdown() has been handled
by the application and it shouldn't be needed to set the socket to
blocking mode. I've left the SSL_shutdown() call in the
LSEC_STATE_CONNECTED to prevent TOCTOU if the application reaches a
timeout for the shutdown code, which might allow SSL_shutdown() to
clean up anyway at the last possible moment.
Another thing I've changed to luasec is the call to socket_setblocking()
right before calling close(2) in socket_destroy() in usocket.c.
According to the latest POSIX[0]:
Note that the requirement for close() on a socket to block for up to
the current linger interval is not conditional on the O_NONBLOCK
setting.
Which I read to mean that removing O_NONBLOCK on the socket before close
doesn't impact the behaviour and only causes noise in system call
tracers. I didn't touch the windows bits of this, since I don't do
windows.
For the prosody side of things I've made the TLS shutdown bits resemble
interface:onwritable(), and put it under a combined guard of self._tls
and self.conn.shutdown. The self._tls bit is there to prevent getting
stuck on this condition, and self.conn.shutdown is there to prevent the
code being called by instances where the patched luasec isn't deployed.
The destroy() method can be called from various places and is read by
me as the "we give up" error path. To accommodate for these unexpected
entrypoints I've added a single call to self.conn:shutdown() to prevent
the socket being put into blocking mode. I have no expectations that
there is any other use here. Same as previous, the self.conn.shutdown
check is there to make sure it's not called on unpatched luasec
deployments and self._tls is there to make sure we don't call shutdown()
on tcp sockets.
I wouldn't recommend logging of the conn:shutdown() error inside
close(), since a lot of clients simply close the connection before
SSL_shutdown() is done.
With both patches in place and running it for 2 days with tracing on I
get the following result:
$ doas kdump | grep 'fcntl.*F_SETFL' | grep -v O_NONBLOCK | sort | uniq -c
350 15188 lua54 CALL fcntl(16,F_SETFL,0x2<O_RDWR>)
350 15188 lua54 CALL fcntl(17,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(18,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(19,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(20,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(22,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(23,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(24,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(25,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(26,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(28,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(29,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(30,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(31,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(32,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(33,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(34,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(35,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(36,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(37,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(38,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(39,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(40,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(41,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(42,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(43,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(44,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(45,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(46,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(47,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(51,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(52,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(57,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(59,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(60,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(62,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(64,F_SETFL,0x2<O_RDWR>)
1 15188 lua54 CALL fcntl(65,F_SETFL,0x2<O_RDWR>)
$ doas fstat -p $(pgrep lua) | grep '1[67]\*'
_prosody lua54 15188 16* unix stream 0xfffffd8092e305c8 <->
0xfffffd8092e30ad8
_prosody lua54 15188 17* unix stream 0xfffffd8098ba9520 <->
0xfffffd8098ba91c0
Since fd 16, and 17 are unix sockets and in control of the application
I'm not too concerned about these. The fcntl calls on all the other
sockets are after I've ^C the server, which makes me expect that these
are calls to meth_destroy() from __gc, or __close and I'm not concerned
about this context.
Please note that this only covers net/server_epoll.lua.
server_event.lua, server.select.lua, and maybe others have been ignored
here.
I haven't gone to luasec with this proposal yet, since I reckon it's
better to have the consumer(s) agree with the change first.
Martijn van Duren
[0] https://pubs.opengroup.org/onlinepubs/9799919799/functions/close.html
--
You received this message because you are subscribed to the Google Groups
"prosody-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion visit
https://groups.google.com/d/msgid/prosody-dev/6f9795e43206e8b9e2c2e2234c7927d420d58c59.camel%40list.imperialat.at.
diff /tmp/luasec
commit - 4c06287052d68fdbe7429b8f967cdc8ee94aa44a
path + /tmp/luasec
blob - 49e618c41bf13d960826bfe334f30a35d82458cc
file + src/luasocket/usocket.c
--- src/luasocket/usocket.c
+++ src/luasocket/usocket.c
@@ -82,7 +82,6 @@ int socket_close(void) {
\*-------------------------------------------------------------------------*/
void socket_destroy(p_socket ps) {
if (*ps != SOCKET_INVALID) {
- socket_setblocking(ps);
close(*ps);
*ps = SOCKET_INVALID;
}
blob - 934bb81b60b5000f35eae4560a4c5afdf2ad20d4
file + src/ssl.c
--- src/ssl.c
+++ src/ssl.c
@@ -86,7 +86,8 @@ static int meth_destroy(lua_State *L)
{
p_ssl ssl = (p_ssl)luaL_checkudata(L, 1, "SSL:Connection");
if (ssl->state == LSEC_STATE_CONNECTED) {
- socket_setblocking(&ssl->sock);
+ if (!ssl->shutdown)
+ socket_setblocking(&ssl->sock);
SSL_shutdown(ssl->ssl);
}
if (ssl->sock != SOCKET_INVALID) {
@@ -304,6 +305,7 @@ static int meth_create(lua_State *L)
return luaL_argerror(L, 1, "invalid context");
}
ssl->state = LSEC_STATE_NEW;
+ ssl->shutdown = 0;
SSL_set_fd(ssl->ssl, (int)SOCKET_INVALID);
SSL_set_mode(ssl->ssl, SSL_MODE_ENABLE_PARTIAL_WRITE |
SSL_MODE_ACCEPT_MOVING_WRITE_BUFFER);
@@ -340,6 +342,56 @@ static int meth_receive(lua_State *L) {
}
/**
+ * SSL shutdown function
+ */
+static int meth_shutdown(lua_State *L) {
+ p_ssl ssl = (p_ssl)luaL_checkudata(L, 1, "SSL:Connection");
+ int err;
+ p_timeout tm = timeout_markstart(&ssl->tm);
+
+ ssl->shutdown = 1;
+ if (ssl->state == LSEC_STATE_CLOSED) {
+ lua_pushboolean(L, 1);
+ return 1;
+ }
+
+ err = SSL_shutdown(ssl->ssl);
+ switch (err) {
+ case 0:
+ lua_pushboolean(L, 0);
+ lua_pushnil(L);
+ return 2;
+ case 1:
+ lua_pushboolean(L, 1);
+ lua_pushnil(L);
+ ssl->state = LSEC_STATE_CLOSED;
+ return 2;
+ case -1:
+ lua_pushboolean(L, 0);
+ ssl->error = SSL_get_error(ssl->ssl, err);
+ switch (ssl->error) {
+ case SSL_ERROR_WANT_READ:
+ err = socket_waitfd(&ssl->sock, WAITFD_R, tm);
+ lua_pushstring(L, ssl_ioerror((void *)ssl, err == IO_TIMEOUT ? LSEC_IO_SSL : err));
+ break;
+ case SSL_ERROR_WANT_WRITE:
+ err = socket_waitfd(&ssl->sock, WAITFD_W, tm);
+ lua_pushstring(L, ssl_ioerror((void *)ssl, err == IO_TIMEOUT ? LSEC_IO_SSL : err));
+ break;
+ case SSL_ERROR_SYSCALL:
+ if (ERR_peek_error())
+ ssl->error = SSL_ERROR_SSL;
+ lua_pushstring(L, ssl_ioerror((void *)ssl, LSEC_IO_SSL));
+ break;
+ default:
+ lua_pushstring(L, ssl_ioerror((void *)ssl, LSEC_IO_SSL));
+ break;
+ }
+ return 2;
+ }
+}
+
+/**
* Get the buffer's statistics.
*/
static int meth_getstats(lua_State *L) {
@@ -990,6 +1042,7 @@ static int meth_tlsa(lua_State *L)
*/
static luaL_Reg methods[] = {
{"close", meth_close},
+ {"shutdown", meth_shutdown},
{"getalpn", meth_getalpn},
{"getfd", meth_getfd},
{"getfinished", meth_getfinished},
blob - 2362ffe5310c01782f00f5efb647b26f7da2aa22
file + src/ssl.h
--- src/ssl.h
+++ src/ssl.h
@@ -32,6 +32,7 @@ typedef struct t_ssl_ {
t_timeout tm;
SSL *ssl;
int state;
+ int shutdown;
int error;
} t_ssl;
typedef t_ssl* p_ssl;
diff -r c71feb7686c0 net/server_epoll.lua
--- a/net/server_epoll.lua Fri Dec 20 14:22:25 2024 +0000
+++ b/net/server_epoll.lua Tue Dec 24 12:43:05 2024 +0100
@@ -657,6 +657,7 @@
-- Close, possibly after writing is done
function interface:close()
+ local status, err;
if self.writebuffer and #self.writebuffer ~= 0 then
self._connected = false;
self:set(false, true); -- Flush final buffer contents
@@ -665,6 +666,24 @@
self.write, self.send = noop, noop; -- No more writing
self:debug("Close after writing remaining buffered data");
self.ondrain = interface.close;
+ elseif self.conn.shutdown and self._tls then
+ status, err = self.conn:shutdown();
+ self.onreadable = interface.close;
+ self.onwritable = interface.close;
+ if err == nil then
+ if status == true then
+ self._tls = false;
+ end
+ return self:close();
+ elseif err == "wantread" then
+ self:set(true, nil);
+ self:setreadtimeout();
+ elseif err == "wantwrite" then
+ self:set(nil, true);
+ self:setwritetimeout();
+ else
+ self._tls = false;
+ end
else
self:debug("Closing now");
self.write, self.send = noop, noop;
@@ -675,6 +694,8 @@
end
function interface:destroy()
+ -- make sure tls sockets aren't put in blocking mode
+ if self.conn.shutdown and self._tls then self.conn:shutdown(); end
self:del();
self:setwritetimeout(false);
self:setreadtimeout(false);
