Bug 129306 - SSL cnx early closure on EAGAIN
Summary: SSL cnx early closure on EAGAIN
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice Online
Classification: Unclassified
Component: LibreOffice (show other bugs)
Version:
(earliest affected)
unspecified
Hardware: All All
: medium critical
Assignee: Michael Meeks
URL:
Whiteboard: target:6.5.0 target:6.4.0.1
Keywords:
Depends on:
Blocks:
 
Reported: 2019-12-10 11:12 UTC by Michael Meeks
Modified: 2019-12-10 14:45 UTC (History)
0 users

See Also:
Crash report or crash signature:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Meeks 2019-12-10 11:12:41 UTC 
Just saw this frightening thing under load:

wsd-29423-29659 2019-12-10 09:50:46.582530 [ websrv_poll ] TRC  #36 Socket dtor.| ./net/Socket.hpp:116
wsd-29423-29659 2019-12-10 09:50:46.582594 [ websrv_poll ] TRC  #35: Incoming data buffer 405 bytes, closeSocket? false| ./net/Socket.hpp:1046
wsd-29423-29659 2019-12-10 09:50:46.582606 [ websrv_poll ] TRC  #35 handling incoming 405 bytes.| net/Socket.cpp:641
wsd-29423-29659 2019-12-10 09:50:46.582660 [ websrv_poll ] TRC  Fileserver request: /loleaflet/3ecc73d37/node_modules/jquery-ui/jquery-ui.js| wsd/FileServer.cpp:273
wsd-29423-29659 2019-12-10 09:50:46.582745 [ websrv_poll ] TRC  #35: Sending compressed : file [/loleaflet/dist/node_modules/jquery-ui/jquery-ui.js]: HTTP/1.0 200 OK
User-Agent: LOOLWSD HTTP Agent master..
Date: Tue, 10 Dec 2019 09:50:46
Content-Encoding: gzip
Content-Type: application/javascript
X-Content-Type-Options: nosniff

| wsd/FileServer.cpp:422
wsd-29423-29659 2019-12-10 09:50:46.582771 [ websrv_poll ] TRC  #35: Wrote outgoing data 188 bytes of 188 bytes buffered.| ./net/Socket.hpp:1114
wsd-29423-29659 2019-12-10 09:50:46.582829 [ websrv_poll ] TRC  #35: Wrote outgoing data 16384 bytes of 107389 bytes buffered.| ./net/Socket.hpp:1114
wsd-29423-29659 2019-12-10 09:50:46.582870 [ websrv_poll ] TRC  Socket #35 SSL error: WANT_WRITE (3).| ./net/SslSocket.hpp:215
wsd-29423-29659 2019-12-10 09:50:46.582898 [ websrv_poll ] TRC  #35: Async shutdown requested.| ./net/Socket.hpp:857
wsd-29423-29659 2019-12-10 09:50:46.582912 [ websrv_poll ] TRC  Poll start| ./net/Socket.hpp:511
wsd-29423-29659 2019-12-10 09:50:46.585441 [ websrv_poll ] TRC  #35: Incoming data buffer 0 bytes, closeSocket? false| ./net/Socket.hpp:1046
wsd-29423-29659 2019-12-10 09:50:46.585457 [ websrv_poll ] TRC  #35: Wrote outgoing data 16384 bytes of 91005 bytes buffered.| ./net/Socket.hpp:1114
wsd-29423-29659 2019-12-10 09:50:46.587312 [ websrv_poll ] TRC  #35: Incoming data buffer 0 bytes, closeSocket? false| ./net/Socket.hpp:1046
wsd-29423-29659 2019-12-10 09:50:46.587343 [ websrv_poll ] TRC  #35: Wrote outgoing data 16384 bytes of 74621 bytes buffered.| ./net/Socket.hpp:1114
wsd-29423-29659 2019-12-10 09:50:46.587369 [ websrv_poll ] TRC  Socket #35 SSL error: WANT_WRITE (3).| ./net/SslSocket.hpp:215
wsd-29423-29659 2019-12-10 09:50:46.587375 [ websrv_poll ] TRC  Socket #35 SSL error: WANT_WRITE (3).| ./net/SslSocket.hpp:215
wsd-29423-29659 2019-12-10 09:50:46.587379 [ websrv_poll ] TRC  Poll start| ./net/Socket.hpp:511
wsd-29423-29659 2019-12-10 09:50:46.593357 [ websrv_poll ] TRC  #35: Incoming data buffer 0 bytes, closeSocket? false| ./net/Socket.hpp:1046
wsd-29423-29659 2019-12-10 09:50:46.593376 [ websrv_poll ] TRC  #35: Wrote outgoing data 16384 bytes of 58237 bytes buffered.| ./net/Socket.hpp:1114
wsd-29423-29659 2019-12-10 09:50:46.593428 [ websrv_poll ] TRC  #35: Wrote outgoing data 16384 bytes of 41853 bytes buffered.| ./net/Socket.hpp:1114
...
wsd-29423-29659 2019-12-10 09:50:46.597629 [ websrv_poll ] TRC  Socket #35 SSL error: SSL (1).| ./net/SslSocket.hpp:244
wsd-29423-29659 2019-12-10 09:50:46.597643 [ websrv_poll ] ERR  Socket #35 SSL BIO error: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init (EAGAIN: Resource temporarily unavailable)| ./net/SslSocket.hpp:281
wsd-29423-29659 2019-12-10 09:50:46.597693 [ websrv_poll ] ERR  Error while handling poll for socket #35 in websrv_poll: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init| ./net/Socket.hpp:594
wsd-29423-29659 2019-12-10 09:50:46.597703 [ websrv_poll ] DBG  Removing socket #35 (of 2) from websrv_poll| ./net/Socket.hpp:601
wsd-29423-29659 2019-12-10 09:50:46.597711 [ websrv_poll ] DBG  SslStreamSocket dtor #35| ./net/SslSocket.hpp:61
wsd-29423-29659 2019-12-10 09:50:46.597735 [ websrv_poll ] DBG  StreamSocket dtor #35| ./net/Socket.hpp:834
wsd-29423-29659 2019-12-10 09:50:46.597749 [ websrv_poll ] TRC  #35 Socket dtor.| ./net/Socket.hpp:116

working on a patch.
Comment 1 Commit Notification 2019-12-10 11:46:22 UTC 
Michael Meeks committed a patch related to this issue.
It has been pushed to "master":

https://git.libreoffice.org/online/commit/1ff820de95b639895e5603a75553d61c79bedc3f

tdf#129306 SslSocket: handle EAGAIN properly.
Comment 2 Michael Meeks 2019-12-10 11:52:56 UTC 
Pushed a fix - we get the expected in the logs:

wsd-26664-26674 2019-12-10 11:39:02.950675 [ websrv_poll ] TRC  Socket #23 BIO asks for retry - underlying EAGAIN? 1| ./net/SslSocket.hpp:249
wsd-26664-26674 2019-12-10 11:39:02.950732 [ websrv_poll ] TRC  Socket #23 BIO asks for retry - underlying EAGAIN? 1| ./net/SslSocket.hpp:249
wsd-26664-26674 2019-12-10 11:39:02.950738 [ websrv_poll ] TRC  Socket #23 BIO asks for retry - underlying EAGAIN? 1| ./net/SslSocket.hpp:249
Comment 3 Commit Notification 2019-12-10 14:45:20 UTC 
Michael Meeks committed a patch related to this issue.
It has been pushed to "libreoffice-6-4":

https://git.libreoffice.org/online/commit/3d330d653f3b8f9795e32313ee27fc1af105320d

tdf#129306 SslSocket: handle EAGAIN properly.