Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 21/10/2013 15:26, Mark Thomas wrote: On 19/10/2013 23:31, Mark Thomas wrote: On 18/10/2013 19:37, Mark Thomas wrote: On 18/10/2013 13:54, Mark Thomas wrote: On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. I've made some progress. I've captured a failure with Wireshark with an SSL configuration that Wireshark can decrypt with the server's private key (SSLProtocol=SSLv3, SSLCipherSuite=RC4-MD5) and it shows nothing unusual until Tomcat initiates the close. To progress I need to create a new tcnative with some debug info so I guess I'll have to return to trying to get my local build environment set up correctly. No joy getting a Windows build environment created but the error also occurs on Linux and I do have a working build environment there. The various errors reported in ssl_socket_recv() are: SSL_READ returns -1 SSL_get_error returns 5 (SSL_ERROR_SYSCALL) apr_get_netos_error returns 11 (APR_STATUS_IS_ENOTSOCK) At this point it looks like the issue is in the tcnative / APR / OpenSSL integration and I am way out of my depth. Looking at the source code for APR reads, the InternalAprInputBuffer uses Socket.recvbb() whereas AprServletInputStream current uses Socket.recv(). My short-term plan is to switch AprServletInputStream to Socket.recvbb() for SSL and see if that fixes the problem. It doesn't. I have removed the code that swallowed this error and the easiest way to reproduce it is to open the drawing board app and hold down F5 to refresh the page. I'm going to spend a little more time looking at the Tomcat side of this but I'm fairly sure it is going to need someone more familiar with C to provide some pointers. Having tested various theories as to why this was happened I tried tested the theory is isn't an error, carry on and that appears to have worked. Treating the error in the same manner as EAGAIN does not drop the client connection and that connection continues to work. I have added some debug logging we can enable if we suspect this is causing problems in the future. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
RE: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
Hi Mark, -Original Message- From: Mark Thomas [mailto:ma...@apache.org] Sent: Tuesday, October 22, 2013 2:57 PM To: Tomcat Developers List Subject: Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46) On 21/10/2013 15:26, Mark Thomas wrote: On 19/10/2013 23:31, Mark Thomas wrote: On 18/10/2013 19:37, Mark Thomas wrote: On 18/10/2013 13:54, Mark Thomas wrote: On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. I've made some progress. I've captured a failure with Wireshark with an SSL configuration that Wireshark can decrypt with the server's private key (SSLProtocol=SSLv3, SSLCipherSuite=RC4-MD5) and it shows nothing unusual until Tomcat initiates the close. To progress I need to create a new tcnative with some debug info so I guess I'll have to return to trying to get my local build environment set up correctly. No joy getting a Windows build environment created but the error also occurs on Linux and I do have a working build environment there. The various errors reported in ssl_socket_recv() are: SSL_READ returns -1 SSL_get_error returns 5 (SSL_ERROR_SYSCALL) apr_get_netos_error returns 11 (APR_STATUS_IS_ENOTSOCK) At this point it looks like the issue is in the tcnative / APR / OpenSSL integration and I am way out of my depth. Looking at the source code for APR reads, the InternalAprInputBuffer uses Socket.recvbb() whereas AprServletInputStream current uses Socket.recv(). My short-term plan is to switch AprServletInputStream to Socket.recvbb() for SSL and see if that fixes the problem. It doesn't. I have removed the code that swallowed this error and the easiest way to reproduce it is to open the drawing board app and hold down F5 to refresh the page. I'm going to spend a little more time looking at the Tomcat side of this but I'm fairly sure it is going to need someone more familiar with C to provide some pointers. Having tested various theories as to why this was happened I tried tested the theory is isn't an error, carry on and that appears to have worked. Treating the error in the same manner as EAGAIN does not drop the client connection and that connection continues to work. I have added some debug logging we can enable if we suspect this is causing problems in the future. Mark Thanks a lot for fixing the problems. I can confirm that with r1534619, I can no longer reproduce the connection close issue. Regards, Konstantin Preißer - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 19/10/2013 23:31, Mark Thomas wrote: On 18/10/2013 19:37, Mark Thomas wrote: On 18/10/2013 13:54, Mark Thomas wrote: On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. I've made some progress. I've captured a failure with Wireshark with an SSL configuration that Wireshark can decrypt with the server's private key (SSLProtocol=SSLv3, SSLCipherSuite=RC4-MD5) and it shows nothing unusual until Tomcat initiates the close. To progress I need to create a new tcnative with some debug info so I guess I'll have to return to trying to get my local build environment set up correctly. No joy getting a Windows build environment created but the error also occurs on Linux and I do have a working build environment there. The various errors reported in ssl_socket_recv() are: SSL_READ returns -1 SSL_get_error returns 5 (SSL_ERROR_SYSCALL) apr_get_netos_error returns 11 (APR_STATUS_IS_ENOTSOCK) At this point it looks like the issue is in the tcnative / APR / OpenSSL integration and I am way out of my depth. Looking at the source code for APR reads, the InternalAprInputBuffer uses Socket.recvbb() whereas AprServletInputStream current uses Socket.recv(). My short-term plan is to switch AprServletInputStream to Socket.recvbb() for SSL and see if that fixes the problem. It doesn't. I have removed the code that swallowed this error and the easiest way to reproduce it is to open the drawing board app and hold down F5 to refresh the page. I'm going to spend a little more time looking at the Tomcat side of this but I'm fairly sure it is going to need someone more familiar with C to provide some pointers. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 18/10/2013 19:37, Mark Thomas wrote: On 18/10/2013 13:54, Mark Thomas wrote: On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. I've made some progress. I've captured a failure with Wireshark with an SSL configuration that Wireshark can decrypt with the server's private key (SSLProtocol=SSLv3, SSLCipherSuite=RC4-MD5) and it shows nothing unusual until Tomcat initiates the close. To progress I need to create a new tcnative with some debug info so I guess I'll have to return to trying to get my local build environment set up correctly. No joy getting a Windows build environment created but the error also occurs on Linux and I do have a working build environment there. The various errors reported in ssl_socket_recv() are: SSL_READ returns -1 SSL_get_error returns 5 (SSL_ERROR_SYSCALL) apr_get_netos_error returns 11 (APR_STATUS_IS_ENOTSOCK) At this point it looks like the issue is in the tcnative / APR / OpenSSL integration and I am way out of my depth. Looking at the source code for APR reads, the InternalAprInputBuffer uses Socket.recvbb() whereas AprServletInputStream current uses Socket.recv(). My short-term plan is to switch AprServletInputStream to Socket.recvbb() for SSL and see if that fixes the problem. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 17/10/2013 00:44, Konstantin Preißer wrote: snip/ Additional information: When I try this with r1532720, then when this close of the Websocket connection happens, Tomcat logs following exception: 17-Oct-2013 01:38:28.378 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [245,310,416]. java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [245,310,416]. at org.apache.coyote.http11.upgrade.AprServletInputStream.doRead(AprServletInputStream.java:104) at org.apache.coyote.http11.upgrade.AbstractServletInputStream.read(AbstractServletInputStream.java:116) at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:46) at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192) at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:169) at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640) at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:282) at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2461) at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2450) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) However, since r1532721, when the closing of Websocket/TCP connection happens, no exception is logged. I think this might be a bug in the tc-native library. I added some debug logging to AprServletInputStream and recorded the value of result in the doRead() method for every read. There is a long series of these results: Read result [1] Read result [48] Read result [-120002] which looks fairly normal (I need to look into why we see a single byte and then 48 bytes rather than 49 bytes). When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. which suggests to me that something goes wrong at a lower level than the Java code. I've checked the state of the byte array when the error occurs and it is an empty 8k array with offset of 0. The other possibility is that I am not using the API correctly. There was an issue with SSL writes that meant that I needed to use a dedicated ByteBuffer for all SSL writes. It might be the case that I need to do something similar for reads. Hopefully Mladen can comment on that. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
2013/10/18 Mark Thomas ma...@apache.org: On 17/10/2013 00:44, Konstantin Preißer wrote: snip/ There is a long series of these results: Read result [1] Read result [48] Read result [-120002] which looks fairly normal (I need to look into why we see a single byte and then 48 bytes rather than 49 bytes). A 1/(n-1) split is usually a counter-measure against BEAST attack on TLS 1.0 (CVE-2011-3389) (I have not looked whether it is what actually happens here, but just noting to save you some time, as the scheme sounds familiar). http://www.mail-archive.com/openssl-dev@openssl.org/msg29810.html http://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2011-3389 http://www.educatedguesswork.org/2011/11/rizzoduong_beast_countermeasur.html Best regards, Konstantin Kolinko - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 18/10/2013 13:46, Konstantin Kolinko wrote: 2013/10/18 Mark Thomas ma...@apache.org: On 17/10/2013 00:44, Konstantin Preißer wrote: snip/ There is a long series of these results: Read result [1] Read result [48] Read result [-120002] which looks fairly normal (I need to look into why we see a single byte and then 48 bytes rather than 49 bytes). A 1/(n-1) split is usually a counter-measure against BEAST attack on TLS 1.0 (CVE-2011-3389) (I have not looked whether it is what actually happens here, but just noting to save you some time, as the scheme sounds familiar). Thanks. That makes sense. Mark http://www.mail-archive.com/openssl-dev@openssl.org/msg29810.html http://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2011-3389 http://www.educatedguesswork.org/2011/11/rizzoduong_beast_countermeasur.html Best regards, Konstantin Kolinko - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
Re: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
On 18/10/2013 13:54, Mark Thomas wrote: On 18/10/2013 12:48, Mark Thomas wrote: When it goes wrong, the sequence is: Read result [1] Read result [48] Read result [-20014] 18-Oct-2013 12:23:25.298 SEVERE [http-apr-8443-exec-1] websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException: Unexpected error [20,014] reading data from the APR/native socket [364,180,784]. I've dug in to what could trigger the 20014 error code. I've got as far as ssl_socket_recv() in native\src\sslnetwork.c There appear to be a number of ways that the code could end up returning 20014. The next step is to figure out which it is. I've made some progress. I've captured a failure with Wireshark with an SSL configuration that Wireshark can decrypt with the server's private key (SSLProtocol=SSLv3, SSLCipherSuite=RC4-MD5) and it shows nothing unusual until Tomcat initiates the close. To progress I need to create a new tcnative with some debug info so I guess I'll have to return to trying to get my local build environment set up correctly. Mark - To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org For additional commands, e-mail: dev-h...@tomcat.apache.org
RE: Tomcat closes Websocket connection when using a SSL HTTP APR connector (was: RE: Tagging 7.0.46)
-Original Message-
From: Konstantin Preißer [mailto:kpreis...@apache.org]
Sent: Thursday, October 17, 2013 1:23 AM
To: 'Tomcat Developers List'
Subject: Tomcat closes Websocket connection when using a SSL HTTP APR
connector (was: RE: Tagging 7.0.46)
-Original Message-
From: Konstantin Preißer [mailto:kpreis...@apache.org]
Sent: Wednesday, October 16, 2013 3:33 PM
I also need to do more testing because the error is not very reproducible
on
my current machine (but I have another one where it was more
reproducible) to make sure what error exactly happens and when.
Hi,
I am now on a machine (Intel Core i7-3770, Win8 x64) where I can reproduce
the error very easily (after a few seconds of drawing at the drawboard).
In summary: When running current Tomcat trunk on Windows 8 x64 with Java
1.7.0_45 x64 and TC-Native 1.1.29, and using a SSL HTTP APR connector, then
Tomcat will close the Websocket connection after a few seconds of drawing
to the Drawboard Websocket example. This does not happen with a non-SSL
APR connector.
What I did was:
1) Checkout trunk (r1532781). Then update the path
webapps/examples/WEB-INF/classes/websocket to r1532286 because
after this revision I made a change to the Room implementation which makes
the error harder to reproduce.
2) Build the working copy, then copy the current v1.1.29 tcnative-1.dll into
the bin directory.
3) Configure a SSL HTTP APR connector in server.xml:
Connector
protocol=HTTP/1.1
port=8443 maxThreads=200
scheme=https secure=true SSLEnabled=true
connectionTimeout=2
SSLCertificateFile=${catalina.base}\conf\ssl\mycert.crt
SSLCertificateKeyFile=${catalina.base}\conf\ssl\mypem.pem
SSLVerifyClient=optional SSLProtocol=TLSv1
/
4) Run Tomcat; then open Firefox and visit
https://localhost:8443/examples/websocket/drawboard.xhtml
5) Draw continuously on the drawboard (e.g. by doing fast circular
movements with the mouse) using the Brush setting.
6) After a several seconds, Firefox will display Websocket connection
closed and you can't draw anymore. Tomcat doesn't log anything to the
console.
When using my TCP forwarder tool between Firefox and Tomcat, I can see
that Tomcat aborts/resets the TCP connection (Winsock error: 10053 and
10054) when this happens.
When you try this with a non-SSL HTTP APR connector, everything works
fine: The Websocket connection will not be closed, regardless of how long
you are drawing.
Additional information:
When I try this with r1532720, then when this close of the Websocket connection
happens, Tomcat logs following exception:
17-Oct-2013 01:38:28.378 SEVERE [http-apr-8443-exec-1]
websocket.drawboard.DrawboardEndpoint.onError onError: java.io.IOException:
Unexpected error [20,014] reading data from the APR/native socket [245,310,416].
java.io.IOException: Unexpected error [20,014] reading data from the
APR/native socket [245,310,416].
at
org.apache.coyote.http11.upgrade.AprServletInputStream.doRead(AprServletInputStream.java:104)
at
org.apache.coyote.http11.upgrade.AbstractServletInputStream.read(AbstractServletInputStream.java:116)
at
org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:46)
at
org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:192)
at
org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:169)
at
org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:640)
at
org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:282)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2461)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2450)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
However, since r1532721, when the closing of Websocket/TCP connection happens,
no exception is logged.
Regards,
Konstantin Preißer
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
