You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Mark Thomas <ma...@apache.org> on 2013/03/12 01:25:17 UTC
Strange APR/native behaviour
I have been tracking down a problem with the Autobahn test suite and
APR/native connector when using SSL (all is fine with non-SSL).
In the test Autobahn sends a 16MB frame to the server which the server
echos back to the client.
The problem I am seeing is with a non-blocking write in the
AprServletOutputStream [1].
If a write returns EAGAIN (line 97) the socket is added to the poller
for write notifications. The poller immediately returns the socket as
ready for write. Another write is attempted that returns EAGAIN and the
code enters an infinite loop with no more data ever written to the socket.
If I add a delay around line 46 that slows the rate of writing down,
EAGAIN is never returned and the test completes successfully.
I assume I am doing something wrong. Pointers appreciated.
Mark
[1]
http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/coyote/http11/upgrade/AprServletOutputStream.java?annotate=1455314
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 10:40 PM, Mark Thomas wrote:
> On 13/03/2013 21:20, Remy Maucherat wrote:
>> On Wed, 2013-03-13 at 20:52 +0000, Mark Thomas wrote:
>>>> I mean check for Socket.setsbb somewhere after the socket is
>>>> returned from poller. Either the new buffer has been set or
>>>> the buffer address is different because of Socket.sendbb's offset param
>>>> (in this case it would be -11530560 so some wrong calculation)
>>>>
>>>> Inside Socket.setsbb we get the ByteBuffer's direct address and later
>>>> reuse it inside Socket.sendbb(long socket, int offset, int len) call
>>>> by using 'socket->jsbuff + offset' and that offseted address is
>>>> displayed in
>>>> the upper debug trace (and if they are not the same OpenSSL will return
>>>> SSL_ERROR_SSL)
>>>
>>> I'm using Socket.send() with the same buffer.
>>>
That won't work cause each time we use different buffer
either from stack (up to 8192 bytes) or malloc'd for larger ones
because we need to copy from byte array.
>>> I'm looking at switching to sendb instead.
>>
>> If you spare some time to refactor and use sendsbb next after trying
>> sendb, it's supposed to be faster [I never did a real comparison test
>> though].
>
> I strongly suspect that sendb vs sendbb won't be the biggest bottleneck
> in my code.
There is an extra JNI call and passing object across JNI boundary
uses some time. But you are right, that's not the biggest bottleneck.
However like Remy said, since you have to use the same buffer anyhow
and that buffer must not change its address there's no point to pass it
on each call and internally call JNIEnv->GetDirectBufferAddress(buf).
Just use Socket.setsbb and then Socket.sendbb.
Socket.sendb is usually used for blocking sockets.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 21:20, Remy Maucherat wrote:
> On Wed, 2013-03-13 at 20:52 +0000, Mark Thomas wrote:
>>> I mean check for Socket.setsbb somewhere after the socket is
>>> returned from poller. Either the new buffer has been set or
>>> the buffer address is different because of Socket.sendbb's offset param
>>> (in this case it would be -11530560 so some wrong calculation)
>>>
>>> Inside Socket.setsbb we get the ByteBuffer's direct address and later
>>> reuse it inside Socket.sendbb(long socket, int offset, int len) call
>>> by using 'socket->jsbuff + offset' and that offseted address is
>>> displayed in
>>> the upper debug trace (and if they are not the same OpenSSL will return
>>> SSL_ERROR_SSL)
>>
>> I'm using Socket.send() with the same buffer.
>>
>> I'm looking at switching to sendb instead.
>
> If you spare some time to refactor and use sendsbb next after trying
> sendb, it's supposed to be faster [I never did a real comparison test
> though].
I strongly suspect that sendb vs sendbb won't be the biggest bottleneck
in my code. While I have tried not to do anything too stupid, my self
imposed requirement to have WebSocket running purely on the Servlet 3.1
API without taking any short-cuts directly from WebSocket to the
low-level IO has added some overhead. I'm pretty sure there is some fat
that could be trimmed there.
In the meantime it looks like sendb is working now I am using a directly
allocated buffer. I need to do some more testing but things are
(finally) looking up a bit.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Remy Maucherat <re...@apache.org>.
On Wed, 2013-03-13 at 20:52 +0000, Mark Thomas wrote:
> > I mean check for Socket.setsbb somewhere after the socket is
> > returned from poller. Either the new buffer has been set or
> > the buffer address is different because of Socket.sendbb's offset param
> > (in this case it would be -11530560 so some wrong calculation)
> >
> > Inside Socket.setsbb we get the ByteBuffer's direct address and later
> > reuse it inside Socket.sendbb(long socket, int offset, int len) call
> > by using 'socket->jsbuff + offset' and that offseted address is
> > displayed in
> > the upper debug trace (and if they are not the same OpenSSL will return
> > SSL_ERROR_SSL)
>
> I'm using Socket.send() with the same buffer.
>
> I'm looking at switching to sendb instead.
If you spare some time to refactor and use sendsbb next after trying
sendb, it's supposed to be faster [I never did a real comparison test
though].
Rémy
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 20:43, Mladen Turk wrote:
> On 03/13/2013 09:29 PM, Mladen Turk wrote:
>> On 03/13/2013 07:07 PM, Mark Thomas wrote:
>>> DEbug logs from v4 of your debug dll
>>>
>>>
>>> [3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
>>> [3296] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
>>> [3296] ssl_socket_send 4 bytes from 0000000016C2CFB0 with timeout -1
>>> [3296] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
>>> [3296] SSL_ERROR_SSL error in queue=336195711
>>> [3296] bad write retry
>>>
>>
>> I see here that buffer change occurs.
>> Those two calls should have the same buffer because those both
>> calls should send the same data (since the first call reported EAGAIN)
>>
>
> I mean check for Socket.setsbb somewhere after the socket is
> returned from poller. Either the new buffer has been set or
> the buffer address is different because of Socket.sendbb's offset param
> (in this case it would be -11530560 so some wrong calculation)
>
> Inside Socket.setsbb we get the ByteBuffer's direct address and later
> reuse it inside Socket.sendbb(long socket, int offset, int len) call
> by using 'socket->jsbuff + offset' and that offseted address is
> displayed in
> the upper debug trace (and if they are not the same OpenSSL will return
> SSL_ERROR_SSL)
I'm using Socket.send() with the same buffer.
I'm looking at switching to sendb instead.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 09:29 PM, Mladen Turk wrote:
> On 03/13/2013 07:07 PM, Mark Thomas wrote:
>> DEbug logs from v4 of your debug dll
>>
>>
>> [3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
>> [3296] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
>> [3296] ssl_socket_send 4 bytes from 0000000016C2CFB0 with timeout -1
>> [3296] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
>> [3296] SSL_ERROR_SSL error in queue=336195711
>> [3296] bad write retry
>>
>
> I see here that buffer change occurs.
> Those two calls should have the same buffer because those both
> calls should send the same data (since the first call reported EAGAIN)
>
I mean check for Socket.setsbb somewhere after the socket is
returned from poller. Either the new buffer has been set or
the buffer address is different because of Socket.sendbb's offset param
(in this case it would be -11530560 so some wrong calculation)
Inside Socket.setsbb we get the ByteBuffer's direct address and later
reuse it inside Socket.sendbb(long socket, int offset, int len) call
by using 'socket->jsbuff + offset' and that offseted address is displayed in
the upper debug trace (and if they are not the same OpenSSL will return SSL_ERROR_SSL)
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 07:07 PM, Mark Thomas wrote:
> DEbug logs from v4 of your debug dll
>
>
> [3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
> [3296] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
> [3296] ssl_socket_send 4 bytes from 0000000016C2CFB0 with timeout -1
> [3296] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
> [3296] SSL_ERROR_SSL error in queue=336195711
> [3296] bad write retry
>
I see here that buffer change occurs.
Those two calls should have the same buffer because those both
calls should send the same data (since the first call reported EAGAIN)
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
DEbug logs from v4 of your debug dll
[3296] ssl_socket_send 193 bytes from 0000000013615030 with timeout 60000000
[3296] SSL_write wrote 193 bytes
[3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 4 bytes
[3296] ssl_socket_send 8192 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 8192 bytes
[3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 4 bytes
[3296] ssl_socket_send 8192 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 8192 bytes
[3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 4 bytes
[3296] ssl_socket_send 8192 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write wrote 8192 bytes
[3296] ssl_socket_send 4 bytes from 000000001772C0F0 with timeout -1
[3296] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
[3296] ssl_socket_send 4 bytes from 0000000016C2CFB0 with timeout -1
[3296] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
[3296] SSL_ERROR_SSL error in queue=336195711
[3296] bad write retry
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 14:55, Mladen Turk wrote:
> On 03/13/2013 03:25 PM, Mark Thomas wrote:
>> On 13/03/2013 14:07, Mladen Turk wrote:
>>>
>>> Sending you a version that returns APR_EGENERAL on SLL_ERROR_SSL ...
>>
>> Thanks. That fails fast which is good but still fails. Fundamentally we
>> need to be able to handle the situation when we have some, but not
>> enough data for OpenSSL.
>>
>
> BTW, looking at some OpenSSL examples, whenever SSL_ERROR_SSL is returned
> it usually means connection needs to get recycled (closed).
> Perhaps we should check for a reason SSL_ERROR_SSL is returned cause that
> doesn't look like a normal thing.
Thanks for the updated debug dll. Results (from the last good write to
when it fails follow).
[880] ssl_socket_send 8192 bytes with timeout -1
[880] SSL_write wrote 8192 bytes
[880] ssl_socket_send 4 bytes with timeout -1
[880] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
[880] ssl_socket_send 4 bytes with timeout -1
[880] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
[880] SSL_ERROR_SSL error in queue=336195711
[880] bad write retry
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 03:25 PM, Mark Thomas wrote:
> On 13/03/2013 14:07, Mladen Turk wrote:
>>
>> Sending you a version that returns APR_EGENERAL on SLL_ERROR_SSL ...
>
> Thanks. That fails fast which is good but still fails. Fundamentally we
> need to be able to handle the situation when we have some, but not
> enough data for OpenSSL.
>
BTW, looking at some OpenSSL examples, whenever SSL_ERROR_SSL is returned
it usually means connection needs to get recycled (closed).
Perhaps we should check for a reason SSL_ERROR_SSL is returned cause that
doesn't look like a normal thing.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 18:11, Mark Thomas wrote:
> On 13/03/2013 14:46, Mladen Turk wrote:
>
>> SSL_write is weird. Docs says that if the return value is EAGAIN the
>> next SSL_write *must* be called with the same params. I presume it
>> internally
>> maintains a state logic or something.
>
> Ah. I might not be doing this. Let me take a look...
I'm not but fixing that doesn't seem to help. Looking at the debug logs
it appears that the APR code is taking a copy of the data since the
pointer stays the same for the first few calls even though I'm using
different objects in the Java code.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 14:46, Mladen Turk wrote:
> SSL_write is weird. Docs says that if the return value is EAGAIN the
> next SSL_write *must* be called with the same params. I presume it
> internally
> maintains a state logic or something.
Ah. I might not be doing this. Let me take a look...
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 03:25 PM, Mark Thomas wrote:
> On 13/03/2013 14:07, Mladen Turk wrote:
>>
>> 00000026 7.85627747 [3976] SSL_write returned -1,
>> apr_get_netos_error=0 SSL_get_error=1
>>
>> That's a problem
>> apr_get_netos_error returned zero (and thats what we return)
>> However SSL_get_error returned SSL_ERROR_SSL (1) and we don't handle that!
>>
>> Sending you a version that returns APR_EGENERAL on SLL_ERROR_SSL ...
>
> Thanks. That fails fast which is good but still fails. Fundamentally we
> need to be able to handle the situation when we have some, but not
> enough data for OpenSSL.
>
Sure. I just returned APR_EGENERAL. Some dedicated retval would be
required so that Java part figures out more data is needed.
Are there any error descriptions in dbgview window?
> On a possibly related topic...
>
> I've noticed that the non-blocking writes via APR/native doesn't behave
> as I would expect. Consider the output from the test case [1]
>
SSL_write is weird. Docs says that if the return value is EAGAIN the
next SSL_write *must* be called with the same params. I presume it internally
maintains a state logic or something.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 14:07, Mladen Turk wrote:
> On 03/13/2013 02:47 PM, Mark Thomas wrote:
>> On 13/03/2013 13:36, Mark Thomas wrote:
>>> On 13/03/2013 13:12, Mladen Turk wrote:
>>
>>>> I can create a debug version which would write couple of lines to
>>>> the dbgview.exe window (from SysInternals
>>>> http://technet.microsoft.com/en-us/sysinternals/bb896647)
>>>>
>>>> Fancy to give it a shot.
>>>> It would be cool to see what are the actual internal results of
>>>> SSL_write API call
>>>
>>> Thanks. Setting up to test with that now.
>>
>> http://people.apache.org/~markt/random/2013-03-13-apr-sos-ssl-debug.log
>>
>> Hope this helps find a fix.
>>
>
> 00000024 7.85507011 [3976] SSL_write returned -1,
> apr_get_netos_error=730035 SSL_get_error=3
>
> Ok, that's a first failure with is WSAEWOULDBLOCK and SSL_get_error=3 is
> SSL_ERROR_WANT_WRITE
>
> 00000026 7.85627747 [3976] SSL_write returned -1,
> apr_get_netos_error=0 SSL_get_error=1
>
> That's a problem
> apr_get_netos_error returned zero (and thats what we return)
> However SSL_get_error returned SSL_ERROR_SSL (1) and we don't handle that!
>
> Sending you a version that returns APR_EGENERAL on SLL_ERROR_SSL ...
Thanks. That fails fast which is good but still fails. Fundamentally we
need to be able to handle the situation when we have some, but not
enough data for OpenSSL.
On a possibly related topic...
I've noticed that the non-blocking writes via APR/native doesn't behave
as I would expect. Consider the output from the test case [1]
The writes at line 3 and 8 suggest (to me at least) that the server
hasn't yet written any data as the return value from the Socket.send
call is zero. However, clearly data has been written since line 5 tells
us that the client has read some data. I am certain this isn't a timing
issue with the log messages because I have stepped through this with a
debugger.
Why doesn't APR/native return the bytes written for Socket.send?
Mark
[1] http://people.apache.org/~markt/random/2013-03-13-TestSocket-output.txt
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 02:47 PM, Mark Thomas wrote:
> On 13/03/2013 13:36, Mark Thomas wrote:
>> On 13/03/2013 13:12, Mladen Turk wrote:
>
>>> I can create a debug version which would write couple of lines to
>>> the dbgview.exe window (from SysInternals
>>> http://technet.microsoft.com/en-us/sysinternals/bb896647)
>>>
>>> Fancy to give it a shot.
>>> It would be cool to see what are the actual internal results of
>>> SSL_write API call
>>
>> Thanks. Setting up to test with that now.
>
> http://people.apache.org/~markt/random/2013-03-13-apr-sos-ssl-debug.log
>
> Hope this helps find a fix.
>
00000024 7.85507011 [3976] SSL_write returned -1, apr_get_netos_error=730035 SSL_get_error=3
Ok, that's a first failure with is WSAEWOULDBLOCK and SSL_get_error=3 is SSL_ERROR_WANT_WRITE
00000026 7.85627747 [3976] SSL_write returned -1, apr_get_netos_error=0 SSL_get_error=1
That's a problem
apr_get_netos_error returned zero (and thats what we return)
However SSL_get_error returned SSL_ERROR_SSL (1) and we don't handle that!
Sending you a version that returns APR_EGENERAL on SLL_ERROR_SSL ...
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 13:36, Mark Thomas wrote:
> On 13/03/2013 13:12, Mladen Turk wrote:
>> I can create a debug version which would write couple of lines to
>> the dbgview.exe window (from SysInternals
>> http://technet.microsoft.com/en-us/sysinternals/bb896647)
>>
>> Fancy to give it a shot.
>> It would be cool to see what are the actual internal results of
>> SSL_write API call
>
> Thanks. Setting up to test with that now.
http://people.apache.org/~markt/random/2013-03-13-apr-sos-ssl-debug.log
Hope this helps find a fix.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 13/03/2013 13:12, Mladen Turk wrote:
> On 03/13/2013 01:29 PM, Mark Thomas wrote:
>> Henri Gomez <he...@gmail.com> wrote:
>>
>>> What's your test platform (or tests platforms) ?
>>>
>>> Differents OS, kernel configuration, OpenSSL / APR could bring various
>>> results
>>
>> I've seen the same behaviour (either with the test case or with the
>> Autobahn test suite) on the following platforms:
>>
>> Windows Server 2008 R2 with 64 bit 1.1.27 native dll built with APR
>> 1.4.6 and OpenSSL 1.0.1d from dist.a.o
>>
>> Ubuntu 12.04 LTS 64 bit with native lib 1.1.27 built locally with APR
>> 1.4.6 and OpenSSL 1.0.1 running as a virtual machine on the above OS.
>>
>> There is certainly a timing aspect to this that does vary by platform.
>> The problem only happens when the server is writing fast enough for it
>> to fill up the send buffer triggering an EAGAIN from the socket write
>> and even then the error doesn't always occur.
>>
>
> I can create a debug version which would write couple of lines to
> the dbgview.exe window (from SysInternals
> http://technet.microsoft.com/en-us/sysinternals/bb896647)
>
> Fancy to give it a shot.
> It would be cool to see what are the actual internal results of
> SSL_write API call
Thanks. Setting up to test with that now.
Refactoring isn't looking like much fun right now and I am concerned
about handling of very short (e.g. 1 byte of data) WebSocket frames over
SSL.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 01:29 PM, Mark Thomas wrote:
> Henri Gomez <he...@gmail.com> wrote:
>
>> What's your test platform (or tests platforms) ?
>>
>> Differents OS, kernel configuration, OpenSSL / APR could bring various
>> results
>
> I've seen the same behaviour (either with the test case or with the
> Autobahn test suite) on the following platforms:
>
> Windows Server 2008 R2 with 64 bit 1.1.27 native dll built with APR
> 1.4.6 and OpenSSL 1.0.1d from dist.a.o
>
> Ubuntu 12.04 LTS 64 bit with native lib 1.1.27 built locally with APR
> 1.4.6 and OpenSSL 1.0.1 running as a virtual machine on the above OS.
>
> There is certainly a timing aspect to this that does vary by platform.
> The problem only happens when the server is writing fast enough for it
> to fill up the send buffer triggering an EAGAIN from the socket write
> and even then the error doesn't always occur.
>
I can create a debug version which would write couple of lines to
the dbgview.exe window (from SysInternals http://technet.microsoft.com/en-us/sysinternals/bb896647)
Fancy to give it a shot.
It would be cool to see what are the actual internal results of SSL_write API call
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
Henri Gomez <he...@gmail.com> wrote:
>What's your test platform (or tests platforms) ?
>
>Differents OS, kernel configuration, OpenSSL / APR could bring various
>results
I've seen the same behaviour (either with the test case or with the
Autobahn test suite) on the following platforms:
Windows Server 2008 R2 with 64 bit 1.1.27 native dll built with APR
1.4.6 and OpenSSL 1.0.1d from dist.a.o
Ubuntu 12.04 LTS 64 bit with native lib 1.1.27 built locally with APR
1.4.6 and OpenSSL 1.0.1 running as a virtual machine on the above OS.
There is certainly a timing aspect to this that does vary by platform.
The problem only happens when the server is writing fast enough for it
to fill up the send buffer triggering an EAGAIN from the socket write
and even then the error doesn't always occur.
Mark
>
>2013/3/13 Mladen Turk <mt...@apache.org>
>
>> On 03/13/2013 01:20 AM, Mark Thomas wrote:
>>
>>>
>>> And an infinite loop is entered.
>>>
>>> I believe I can fix this by changing how I do the buffering in
>WebSocket
>>> so I don't end up having to write short 4 byte chunks. I have been
>>> meaning to do this for a while anyway.
>>>
>>> That said, this does look like an issue with APR/native and SSL.
>>>
>>> Thoughts?
>>>
>>>
>> The only solution would be to have some sort of different
>> retvals for real EAGAIN (network layer) and case when encryption
>> cannot be made (protocol layer) due to insufficient data.
>> That is if OpenSSL returns some distinct error in such case.
>>
>> Perhaps the internal buffering would be a way to go, cause
>> we poll only on network events, and if that's satisfied we
>> need a different kind of queue for filling the minimum write
>> buffer. I'll try to dig and see if we can distinguish between
>> those different EAGAIN retvals.
>>
>>
>> Regards
>> --
>> ^TM
>>
>>
>>
>------------------------------**------------------------------**---------
>> To unsubscribe, e-mail:
>dev-unsubscribe@tomcat.apache.**org<de...@tomcat.apache.org>
>> For additional commands, e-mail: dev-help@tomcat.apache.org
>>
>>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Henri Gomez <he...@gmail.com>.
What's your test platform (or tests platforms) ?
Differents OS, kernel configuration, OpenSSL / APR could bring various
results
2013/3/13 Mladen Turk <mt...@apache.org>
> On 03/13/2013 01:20 AM, Mark Thomas wrote:
>
>>
>> And an infinite loop is entered.
>>
>> I believe I can fix this by changing how I do the buffering in WebSocket
>> so I don't end up having to write short 4 byte chunks. I have been
>> meaning to do this for a while anyway.
>>
>> That said, this does look like an issue with APR/native and SSL.
>>
>> Thoughts?
>>
>>
> The only solution would be to have some sort of different
> retvals for real EAGAIN (network layer) and case when encryption
> cannot be made (protocol layer) due to insufficient data.
> That is if OpenSSL returns some distinct error in such case.
>
> Perhaps the internal buffering would be a way to go, cause
> we poll only on network events, and if that's satisfied we
> need a different kind of queue for filling the minimum write
> buffer. I'll try to dig and see if we can distinguish between
> those different EAGAIN retvals.
>
>
> Regards
> --
> ^TM
>
>
> ------------------------------**------------------------------**---------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.**org<de...@tomcat.apache.org>
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
Re: Strange APR/native behaviour
Posted by Mladen Turk <mt...@apache.org>.
On 03/13/2013 01:20 AM, Mark Thomas wrote:
>
> And an infinite loop is entered.
>
> I believe I can fix this by changing how I do the buffering in WebSocket
> so I don't end up having to write short 4 byte chunks. I have been
> meaning to do this for a while anyway.
>
> That said, this does look like an issue with APR/native and SSL.
>
> Thoughts?
>
The only solution would be to have some sort of different
retvals for real EAGAIN (network layer) and case when encryption
cannot be made (protocol layer) due to insufficient data.
That is if OpenSSL returns some distinct error in such case.
Perhaps the internal buffering would be a way to go, cause
we poll only on network events, and if that's satisfied we
need a different kind of queue for filling the minimum write
buffer. I'll try to dig and see if we can distinguish between
those different EAGAIN retvals.
Regards
--
^TM
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 12/03/2013 18:25, Remy Maucherat wrote:
> On Tue, 2013-03-12 at 13:25 +0000, Mark Thomas wrote:
>> Thanks for the pointers. I tried a few of them (the less invasive ones)
>> with no luck. I'm putting together a test case that demonstrates the
>> problem. That should make it very simple to determine if the root cause
>> lies in APR or my code.
>
> Ok, too bad. I was thinking the timeout trick could do it since the
> "proper" non blocking option + EAGAIN didn't work that well for me then.
> But that was a while ago. Using a 0 timeout is simpler overall, but
> obviously it looks like a hack.
>
> Yes, if you can write a simple test case, it would probably be much
> easier to isolate an issue in APR, it's likely far too complex
> otherwise.
And we have a test case. Run the latest TestSocket with:
LIMIT=100000
SSL_ENABLED=true
CHUNK_SIZE=2
The problem isn't 100% reproducible but:
- I have never been able to repeat it with SSL disabled
- I saw the problem once with a chunk size of 4
- I have never seen the problem with a chunk size > 4
Based on what this test does any my observations I have a theory but it
will need someone who understands the APR/native code better than I do
to confirm the theory and (if correct) produce a fix.
I am assuming the the SSL encryption processes the data in chunks where
the chunk size is a small number of bytes (e.g. 8).
What I think happens is this:
Lots of data is written to the socket.
The write buffers become 99.9% full.
The client writes a very small amount of data (e.g. 4 bytes).
This is enough for the SSL encryption to output a little more data so
the write buffers are now 100% full.
Not all of the 4 bytes from the client were read.
Socket gets added to the Poller.
Other end of the socket reads some data.
Poller fires write possible.
StartLoop:
Client writes remaining bytes (<4).
There is not enough new input for the SSL encryption to generate more
output so it reports 0 bytes written.
Client believes write buffers are still full.
Socket gets added to the Poller.
Poller instantly fires write possible
Goto StartLoop
And an infinite loop is entered.
I believe I can fix this by changing how I do the buffering in WebSocket
so I don't end up having to write short 4 byte chunks. I have been
meaning to do this for a while anyway.
That said, this does look like an issue with APR/native and SSL.
Thoughts?
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Remy Maucherat <re...@apache.org>.
On Tue, 2013-03-12 at 13:25 +0000, Mark Thomas wrote:
> Thanks for the pointers. I tried a few of them (the less invasive ones)
> with no luck. I'm putting together a test case that demonstrates the
> problem. That should make it very simple to determine if the root cause
> lies in APR or my code.
Ok, too bad. I was thinking the timeout trick could do it since the
"proper" non blocking option + EAGAIN didn't work that well for me then.
But that was a while ago. Using a 0 timeout is simpler overall, but
obviously it looks like a hack.
Yes, if you can write a simple test case, it would probably be much
easier to isolate an issue in APR, it's likely far too complex
otherwise.
Rémy
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
On 12/03/2013 09:47, Remy Maucherat wrote:
> On Tue, 2013-03-12 at 00:25 +0000, Mark Thomas wrote:
<snip/>
>> I assume I am doing something wrong. Pointers appreciated.
>
> So I don't know precisely, but for non blocking, you're not doing the
> same thing I'm doing (which went through stress tests successfully on
> some platforms - but not on OS X, the OS is too cool for using it for
> this kind of dirty work, I presume).
>
> Here are some differences (that could be attempted):
> - to set non blocking, I don't use optSet with APR_SO_NONBLOCK (it did
> weird things at that time, not 100% sure now), but
> Socket.timeoutSet(socket, 0) since Mladen told me that is the proper way
> to set non blocking mode
> - to do the actual send of the bytes, I use sendibb (which is sendib
> with an internal byte buffer), I think it's not the same as the regular
> send since it doesn't retry (says the javadoc, not sure if it can be
> fully trusted ;) )
> - I check if it needs to be put in the poller using the number of bytes
> wrtten (if 0, it goes to the poller, if not, write again if there's more
> data), not some status like EAGAIN (IMO that's riskier, since the exact
> bahavior of statuses are sometimes platform specific)
> - to exit non blocking mode, I set the previous timeout value and use
> sendbb (again, with the internal byte buffer)
> - I don't use syncs on IO, the design of the async in Servlet 3.1 is
> supposed to allow avoiding that (of course, if the user does concurrent
> writes without a lock on his own, it will bomb, but IMO, it should)
Thanks for the pointers. I tried a few of them (the less invasive ones)
with no luck. I'm putting together a test case that demonstrates the
problem. That should make it very simple to determine if the root cause
lies in APR or my code.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Strange APR/native behaviour
Posted by Remy Maucherat <re...@apache.org>.
On Tue, 2013-03-12 at 00:25 +0000, Mark Thomas wrote:
> I have been tracking down a problem with the Autobahn test suite and
> APR/native connector when using SSL (all is fine with non-SSL).
>
> In the test Autobahn sends a 16MB frame to the server which the server
> echos back to the client.
>
> The problem I am seeing is with a non-blocking write in the
> AprServletOutputStream [1].
>
> If a write returns EAGAIN (line 97) the socket is added to the poller
> for write notifications. The poller immediately returns the socket as
> ready for write. Another write is attempted that returns EAGAIN and the
> code enters an infinite loop with no more data ever written to the socket.
>
> If I add a delay around line 46 that slows the rate of writing down,
> EAGAIN is never returned and the test completes successfully.
>
> I assume I am doing something wrong. Pointers appreciated.
So I don't know precisely, but for non blocking, you're not doing the
same thing I'm doing (which went through stress tests successfully on
some platforms - but not on OS X, the OS is too cool for using it for
this kind of dirty work, I presume).
Here are some differences (that could be attempted):
- to set non blocking, I don't use optSet with APR_SO_NONBLOCK (it did
weird things at that time, not 100% sure now), but
Socket.timeoutSet(socket, 0) since Mladen told me that is the proper way
to set non blocking mode
- to do the actual send of the bytes, I use sendibb (which is sendib
with an internal byte buffer), I think it's not the same as the regular
send since it doesn't retry (says the javadoc, not sure if it can be
fully trusted ;) )
- I check if it needs to be put in the poller using the number of bytes
wrtten (if 0, it goes to the poller, if not, write again if there's more
data), not some status like EAGAIN (IMO that's riskier, since the exact
bahavior of statuses are sometimes platform specific)
- to exit non blocking mode, I set the previous timeout value and use
sendbb (again, with the internal byte buffer)
- I don't use syncs on IO, the design of the async in Servlet 3.1 is
supposed to allow avoiding that (of course, if the user does concurrent
writes without a lock on his own, it will bomb, but IMO, it should)
Rémy
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
RE: Strange APR/native behaviour
Posted by Mark Thomas <ma...@apache.org>.
"Caldarale, Charles R" <Ch...@unisys.com> wrote:
>> From: Mark Thomas [mailto:markt@apache.org]
>> Subject: Strange APR/native behaviour
>
>> The problem I am seeing is with a non-blocking write in the
>> AprServletOutputStream [1].
>
>> If a write returns EAGAIN (line 97) the socket is added to the poller
>> for write notifications. The poller immediately returns the socket as
>> ready for write. Another write is attempted that returns EAGAIN and
>the
>> code enters an infinite loop with no more data ever written to the
>socket.
>
>> If I add a delay around line 46 that slows the rate of writing down,
>> EAGAIN is never returned and the test completes successfully.
>
>Are you positive the EAGAIN path is being taken? Or could it be an
>exception is being thrown (and swallowed), leaving result = 0, thereby
>adding the socket to the poller at line 93 and returning zero?
>
> - Chuck
Yes, I am positive. I was using a debugger and had a break point in the EAGAIN path.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
RE: Strange APR/native behaviour
Posted by "Caldarale, Charles R" <Ch...@unisys.com>.
> From: Mark Thomas [mailto:markt@apache.org]
> Subject: Strange APR/native behaviour
> The problem I am seeing is with a non-blocking write in the
> AprServletOutputStream [1].
> If a write returns EAGAIN (line 97) the socket is added to the poller
> for write notifications. The poller immediately returns the socket as
> ready for write. Another write is attempted that returns EAGAIN and the
> code enters an infinite loop with no more data ever written to the socket.
> If I add a delay around line 46 that slows the rate of writing down,
> EAGAIN is never returned and the test completes successfully.
Are you positive the EAGAIN path is being taken? Or could it be an exception is being thrown (and swallowed), leaving result = 0, thereby adding the socket to the poller at line 93 and returning zero?
- Chuck
THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and is thus for use only by the intended recipient. If you received this in error, please contact the sender and delete the e-mail and its attachments from all computers.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org