You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by Emmanuel Lécharny <el...@gmail.com> on 2022/01/14 17:48:20 UTC

MINA 2.2: some more test failures

Hi Jonathan,

I also have a failure in SslFilterTest.testMessageSentIsCalled_With_SSL.

What happens is that we try to send 2 messages (test-1 and test-2) with 
SSL established, but we do a SSL renegociation in between the first 
message sending and the second.

For some unknown reason, when we try to read the response on the client 
side (something we do in one shot after the second message has been 
sent), we never get back the second message.

I'm positive it has been sent, I strongly suspect that the client socket 
lose it during the SSL uncrypting *after* the Ssl reneg has occured.

At this point, I wonder if the SSL reneg has been properly handled on 
the server side.


I also noted another test failure due to some class renaming 
(SslConnectionfactory to SSLConnectionFactory and SslFilter to 
SSLFilter. It should work on Windows probably because its FS is not case 
sensitive).

-- 
*Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
T. +33 (0)4 89 97 36 50
P. +33 (0)6 08 33 32 61
emmanuel.lecharny@busit.com https://www.busit.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org


Re: MINA 2.2: some more test failures

Posted by Jonathan Valliere <jo...@apache.org>.
>
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive() - recursion
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> source HeapBuffer@1c745cf7[pos=74 lim=74 cap=1024: ]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> bytes-consumed 0, bytes-produced 0, status BUFFER_UNDERFLOW, handshake
> NOT_HANDSHAKING
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] flush() - no saved
> messages
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLFilter] - session
> (0x00000001: nio socket, server, /127.0.0.1:34152 => /127.0.0.1:52633)
> ack WriteRequest: HeapBuffer@2b3ccae0[pos=0 lim=88 cap=33418: 17 03 03 00
> 53 3E 95 F1 BB 69 CC 5A 1C EE 7C 86]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLFilter] - session
> (0x00000001: nio socket, server, /127.0.0.1:34152 => /127.0.0.1:52633)
> received HeapBuffer@a3aae2a[pos=0 lim=133 cap=1024: 17 03 03 00 28 07 09
> 86 C2 A3 16 B5 D0 2F A9 7A]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive() - message
> HeapBuffer@a3aae2a[pos=0 lim=133 cap=1024: 17 03 03 00 28 07 09 86 C2 A3
> 16 B5 D0 2F A9 7A]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> source HeapBuffer@a3aae2a[pos=0 lim=133 cap=1024: 17 03 03 00 28 07 09 86
> C2 A3 16 B5 D0 2F A9 7A]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> bytes-consumed 45, bytes-produced 7, status OK, handshake NOT_HANDSHAKING
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() - *result
> HeapBuffer@471c1e47[pos=0 lim=7 cap=16676: 74 65 73 74 2D 31 0A]*
> *[22:19:09] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
> Processing a MESSAGE_RECEIVED for session 1*
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLFilter] - session
> (0x00000001: nio socket, server, /127.0.0.1:34152 => /127.0.0.1:52633)
> write WriteRequest: test-1
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write() - source
> WriteRequest: test-1
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_user_loop() -
> source WriteRequest: test-1
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_user_loop() -
> bytes-consumed 7, bytes-produced 45, status OK, handshake NOT_HANDSHAKING
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_user_loop() -
> result WriteRequest: HeapBuffer@57de9203[pos=0 lim=45 cap=33418: 17 03 03
> 00 28 85 68 29 F9 91 D9 A6 E3 16 8C 5A]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> trying to decode more messages, looping
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> source HeapBuffer@a3aae2a[pos=45 lim=133 cap=1024: 17 03 03 00 26 94 1C
> 0B 5E 19 D8 38 D3 48 3C BE]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> bytes-consumed 43, bytes-produced 0, status OK, handshake NEED_WRAP
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> handshake needs wrap, invoking write
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_handshake() -
> internal
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_handshake_loop()
> - bytes-consumed 0, bytes-produced 43, status OK, handshake FINISHED
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_handshake_loop()
> - result HeapBuffer@10488d03[pos=0 lim=43 cap=33418: 17 03 03 00 26 58 5D
> FE 47 6F B4 62 2A 7D 32 52]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] write_handshake_loop()
> - handshake finished, flushing queue
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive() - recursion
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> source HeapBuffer@a3aae2a[pos=88 lim=133 cap=1024: 17 03 03 00 28 58 7B
> 99 DA B0 9C 48 DC A0 57 01]
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() -
> bytes-consumed 45, bytes-produced 7, status OK, handshake NOT_HANDSHAKING
> [22:19:09] DEBUG [org.apache.mina.filter.ssl.SSLHandler] -
> SSLHandlerG0@4240f14c[mode=server, connected=true] receive_loop() - *result
> HeapBuffer@5843a2bd[pos=0 lim=7 cap=16676: 74 65 73 74 2D 32 0A]*
> *[22:19:09] DEBUG [org.apache.mina.filter.codec.ProtocolCodecFilter] -
> Processing a MESSAGE_RECEIVED for session 1*


On Fri, Jan 14, 2022 at 10:17 PM Jonathan Valliere <jo...@apache.org>
wrote:

> Additionally, that unit test you referenced is passing for me on
> AdoptOpenJDK 11
>
> On Fri, Jan 14, 2022 at 10:10 PM Jonathan Valliere <jo...@apache.org>
> wrote:
>
>> Can you send the server debugging logs?
>>
>> On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny <el...@gmail.com>
>> wrote:
>>
>>>
>>>
>>> On 14/01/2022 18:48, Emmanuel Lécharny wrote:
>>> > Hi Jonathan,
>>> >
>>> > I also have a failure in
>>> SslFilterTest.testMessageSentIsCalled_With_SSL.
>>> >
>>> > What happens is that we try to send 2 messages (test-1 and test-2)
>>> with
>>> > SSL established, but we do a SSL renegociation in between the first
>>> > message sending and the second.
>>> >
>>> > For some unknown reason, when we try to read the response on the
>>> client
>>> > side (something we do in one shot after the second message has been
>>> > sent), we never get back the second message.
>>> >
>>> > I'm positive it has been sent, I strongly suspect that the client
>>> socket
>>> > lose it during the SSL uncrypting *after* the Ssl reneg has occured.
>>>
>>> So here are the data being sent by the server with MINA 2.1.5:
>>>
>>> HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51 03 03 61
>>> E2 12 0B 67] (ServerHello)
>>> HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01] (ChangeCipherSpec)
>>> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69 CD 46 99
>>> 0D A4 B2] (ServerHandshakeFinished)
>>> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72 31 73 EF
>>> 12 00 F6] (Data)
>>>
>>> rehandhsake
>>>
>>> HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00 34 46 FB
>>> 53 6C 16] (ServerHello)
>>> HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E FF 9A 7C
>>> 5C BA C7] (ChangeCipherSpec)
>>> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F B8 5A 5C
>>> 2D 46 26] (ServerHandshakeFinished)
>>> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB 18 F1 A4
>>> AA 75 27]
>>> HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8 2C 64 88
>>> F3 F5 A6]
>>>
>>>
>>> And with MLINA 2.2.0:
>>>
>>> HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02 00 00 51
>>> 03 03 61 E2 13 CE CD] (ServerHello)
>>> HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01 16 03 03
>>> 00 60 AA 0C 98 25 E0] (ChangeCipherSpec) + (ServerHandshakeFinished)
>>> HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1 D5 CB
>>> 5E 78 73 29 60 C0 FF] (Data)
>>>
>>> rehandshake
>>>
>>> HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD B1 5D
>>> F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
>>> (ServerHandshakeFinished)
>>> HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9 B7 57
>>> 5C A3 1D A0 14 26 87] (Data)
>>>
>>>
>>> It's pretty much like if the server sends HS data as a whole instead of
>>> splitting them in pieces. However, I think everything is there, so I
>>> don't understand why it fails in MINA 2.2...
>>>
>>> --
>>> *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
>>> T. +33 (0)4 89 97 36 50
>>> P. +33 (0)6 08 33 32 61
>>> emmanuel.lecharny@busit.com https://www.busit.com/
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
>>> For additional commands, e-mail: dev-help@mina.apache.org
>>>
>>>

Re: MINA 2.2: some more test failures

Posted by Emmanuel Lécharny <el...@gmail.com>.
Jonathan,

I don't think it worth it to keep going the investigation in Java 8.

First because it works with Java 11
Second because reneg is not available in TLS V3

I would simply disable this test, or check the Java version when running 
the test, somtehing like:

     public void testMessageSentIsCalled_With_SSL() throws Exception {
         String javaVersion = System.getProperty("java.runtime.version");

         if (!javaVersion.startsWith("1.8")) {
             testMessageSentIsCalled(true);
         }
     }


On 15/01/2022 15:09, Jonathan Valliere wrote:
> Emmanuel,
> 
> Disabling the handshake aggregation by setting ENABLE_FAST_HANDSHAKE to
> false still has it fail on Java 8.
> 
> This could be a straight up bug in Java 8 with renegotiations.  I also
> tried disabling the CLOSE messages, but it didn't make any difference.
> 
> 
> 
> On Sat, Jan 15, 2022 at 1:05 AM Emmanuel Lécharny <el...@gmail.com>
> wrote:
> 
>>
>> Hi Jona than,
>>
>> indeed, same here. If I switch to Java 11, it passes.
>>
>> What puzzles me is that the same test passes with Java 8 on MINA 2.1.5...
>>
>> Now, let's face reality: in TLS 1.3, reneg has been deprecated, so this
>> test is soon going to be useless. And Java 8 is not anymore maintained
>> (unless you pay for it), so I don't really mind if we decide that Java
>> 11 is mandatory for MINA 2.2.
>>
>> I suspect there is some issue in the way Java 8 process incoming data.
>> In MINA 2.2, the read buffer contains all the HS server data
>> (ServerHello + ChangeCipherSpec +ServerHandshakeFinished) in one PDU,
>> while in MINA 2.1.5 the client has to read 3 PDUs to get the same data.
>> This may make a difference.
>>
>>
>> Thanks !
>>
>>
>> On 15/01/2022 04:17, Jonathan Valliere wrote:
>>> Additionally, that unit test you referenced is passing for me on
>>> AdoptOpenJDK 11
>>>
>>> On Fri, Jan 14, 2022 at 10:10 PM Jonathan Valliere <johnnyv@apache.org
>>> <ma...@apache.org>> wrote:
>>>
>>>      Can you send the server debugging logs?
>>>
>>>      On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny
>>>      <elecharny@gmail.com <ma...@gmail.com>> wrote:
>>>
>>>
>>>
>>>          On 14/01/2022 18:48, Emmanuel Lécharny wrote:
>>>           > Hi Jonathan,
>>>           >
>>>           > I also have a failure in
>>>          SslFilterTest.testMessageSentIsCalled_With_SSL.
>>>           >
>>>           > What happens is that we try to send 2 messages (test-1 and
>>>          test-2) with
>>>           > SSL established, but we do a SSL renegociation in between the
>>>          first
>>>           > message sending and the second.
>>>           >
>>>           > For some unknown reason, when we try to read the response on
>>>          the client
>>>           > side (something we do in one shot after the second message
>>>          has been
>>>           > sent), we never get back the second message.
>>>           >
>>>           > I'm positive it has been sent, I strongly suspect that the
>>>          client socket
>>>           > lose it during the SSL uncrypting *after* the Ssl reneg has
>>>          occured.
>>>
>>>          So here are the data being sent by the server with MINA 2.1.5:
>>>
>>>          HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51
>>>          03 03 61
>>>          E2 12 0B 67] (ServerHello)
>>>          HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01]
>> (ChangeCipherSpec)
>>>          HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69
>>>          CD 46 99
>>>          0D A4 B2] (ServerHandshakeFinished)
>>>          HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72
>>>          31 73 EF
>>>          12 00 F6] (Data)
>>>
>>>          rehandhsake
>>>
>>>          HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00
>>>          34 46 FB
>>>          53 6C 16] (ServerHello)
>>>          HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E
>>>          FF 9A 7C
>>>          5C BA C7] (ChangeCipherSpec)
>>>          HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F
>>>          B8 5A 5C
>>>          2D 46 26] (ServerHandshakeFinished)
>>>          HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB
>>>          18 F1 A4
>>>          AA 75 27]
>>>          HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8
>>>          2C 64 88
>>>          F3 F5 A6]
>>>
>>>
>>>          And with MLINA 2.2.0:
>>>
>>>          HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02
>>>          00 00 51
>>>          03 03 61 E2 13 CE CD] (ServerHello)
>>>          HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01
>>>          16 03 03
>>>          00 60 AA 0C 98 25 E0] (ChangeCipherSpec) +
>> (ServerHandshakeFinished)
>>>          HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1
>>>          D5 CB
>>>          5E 78 73 29 60 C0 FF] (Data)
>>>
>>>          rehandshake
>>>
>>>          HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD
>>>          B1 5D
>>>          F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
>>>          (ServerHandshakeFinished)
>>>          HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9
>>>          B7 57
>>>          5C A3 1D A0 14 26 87] (Data)
>>>
>>>
>>>          It's pretty much like if the server sends HS data as a whole
>>>          instead of
>>>          splitting them in pieces. However, I think everything is there,
>>>          so I
>>>          don't understand why it fails in MINA 2.2...
>>>
>>>          --
>>>          *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
>>>          T. +33 (0)4 89 97 36 50
>>>          P. +33 (0)6 08 33 32 61
>>>          emmanuel.lecharny@busit.com <ma...@busit.com>
>>>          https://www.busit.com/ <https://www.busit.com/>
>>>
>>>
>>   ---------------------------------------------------------------------
>>>          To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
>>>          <ma...@mina.apache.org>
>>>          For additional commands, e-mail: dev-help@mina.apache.org
>>>          <ma...@mina.apache.org>
>>>
>>
>> --
>> *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
>> T. +33 (0)4 89 97 36 50
>> P. +33 (0)6 08 33 32 61
>> emmanuel.lecharny@busit.com https://www.busit.com/
>>
> 

-- 
*Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
T. +33 (0)4 89 97 36 50
P. +33 (0)6 08 33 32 61
emmanuel.lecharny@busit.com https://www.busit.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org


Re: MINA 2.2: some more test failures

Posted by Jonathan Valliere <jo...@apache.org>.
Emmanuel,

Disabling the handshake aggregation by setting ENABLE_FAST_HANDSHAKE to
false still has it fail on Java 8.

This could be a straight up bug in Java 8 with renegotiations.  I also
tried disabling the CLOSE messages, but it didn't make any difference.



On Sat, Jan 15, 2022 at 1:05 AM Emmanuel Lécharny <el...@gmail.com>
wrote:

>
> Hi Jona than,
>
> indeed, same here. If I switch to Java 11, it passes.
>
> What puzzles me is that the same test passes with Java 8 on MINA 2.1.5...
>
> Now, let's face reality: in TLS 1.3, reneg has been deprecated, so this
> test is soon going to be useless. And Java 8 is not anymore maintained
> (unless you pay for it), so I don't really mind if we decide that Java
> 11 is mandatory for MINA 2.2.
>
> I suspect there is some issue in the way Java 8 process incoming data.
> In MINA 2.2, the read buffer contains all the HS server data
> (ServerHello + ChangeCipherSpec +ServerHandshakeFinished) in one PDU,
> while in MINA 2.1.5 the client has to read 3 PDUs to get the same data.
> This may make a difference.
>
>
> Thanks !
>
>
> On 15/01/2022 04:17, Jonathan Valliere wrote:
> > Additionally, that unit test you referenced is passing for me on
> > AdoptOpenJDK 11
> >
> > On Fri, Jan 14, 2022 at 10:10 PM Jonathan Valliere <johnnyv@apache.org
> > <ma...@apache.org>> wrote:
> >
> >     Can you send the server debugging logs?
> >
> >     On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny
> >     <elecharny@gmail.com <ma...@gmail.com>> wrote:
> >
> >
> >
> >         On 14/01/2022 18:48, Emmanuel Lécharny wrote:
> >          > Hi Jonathan,
> >          >
> >          > I also have a failure in
> >         SslFilterTest.testMessageSentIsCalled_With_SSL.
> >          >
> >          > What happens is that we try to send 2 messages (test-1 and
> >         test-2) with
> >          > SSL established, but we do a SSL renegociation in between the
> >         first
> >          > message sending and the second.
> >          >
> >          > For some unknown reason, when we try to read the response on
> >         the client
> >          > side (something we do in one shot after the second message
> >         has been
> >          > sent), we never get back the second message.
> >          >
> >          > I'm positive it has been sent, I strongly suspect that the
> >         client socket
> >          > lose it during the SSL uncrypting *after* the Ssl reneg has
> >         occured.
> >
> >         So here are the data being sent by the server with MINA 2.1.5:
> >
> >         HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51
> >         03 03 61
> >         E2 12 0B 67] (ServerHello)
> >         HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01]
> (ChangeCipherSpec)
> >         HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69
> >         CD 46 99
> >         0D A4 B2] (ServerHandshakeFinished)
> >         HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72
> >         31 73 EF
> >         12 00 F6] (Data)
> >
> >         rehandhsake
> >
> >         HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00
> >         34 46 FB
> >         53 6C 16] (ServerHello)
> >         HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E
> >         FF 9A 7C
> >         5C BA C7] (ChangeCipherSpec)
> >         HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F
> >         B8 5A 5C
> >         2D 46 26] (ServerHandshakeFinished)
> >         HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB
> >         18 F1 A4
> >         AA 75 27]
> >         HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8
> >         2C 64 88
> >         F3 F5 A6]
> >
> >
> >         And with MLINA 2.2.0:
> >
> >         HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02
> >         00 00 51
> >         03 03 61 E2 13 CE CD] (ServerHello)
> >         HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01
> >         16 03 03
> >         00 60 AA 0C 98 25 E0] (ChangeCipherSpec) +
> (ServerHandshakeFinished)
> >         HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1
> >         D5 CB
> >         5E 78 73 29 60 C0 FF] (Data)
> >
> >         rehandshake
> >
> >         HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD
> >         B1 5D
> >         F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
> >         (ServerHandshakeFinished)
> >         HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9
> >         B7 57
> >         5C A3 1D A0 14 26 87] (Data)
> >
> >
> >         It's pretty much like if the server sends HS data as a whole
> >         instead of
> >         splitting them in pieces. However, I think everything is there,
> >         so I
> >         don't understand why it fails in MINA 2.2...
> >
> >         --
> >         *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
> >         T. +33 (0)4 89 97 36 50
> >         P. +33 (0)6 08 33 32 61
> >         emmanuel.lecharny@busit.com <ma...@busit.com>
> >         https://www.busit.com/ <https://www.busit.com/>
> >
> >
>  ---------------------------------------------------------------------
> >         To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
> >         <ma...@mina.apache.org>
> >         For additional commands, e-mail: dev-help@mina.apache.org
> >         <ma...@mina.apache.org>
> >
>
> --
> *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
> T. +33 (0)4 89 97 36 50
> P. +33 (0)6 08 33 32 61
> emmanuel.lecharny@busit.com https://www.busit.com/
>

Re: MINA 2.2: some more test failures

Posted by Emmanuel Lécharny <el...@gmail.com>.
Hi Jona	than,

indeed, same here. If I switch to Java 11, it passes.

What puzzles me is that the same test passes with Java 8 on MINA 2.1.5...

Now, let's face reality: in TLS 1.3, reneg has been deprecated, so this 
test is soon going to be useless. And Java 8 is not anymore maintained 
(unless you pay for it), so I don't really mind if we decide that Java 
11 is mandatory for MINA 2.2.

I suspect there is some issue in the way Java 8 process incoming data. 
In MINA 2.2, the read buffer contains all the HS server data 
(ServerHello + ChangeCipherSpec +ServerHandshakeFinished) in one PDU, 
while in MINA 2.1.5 the client has to read 3 PDUs to get the same data. 
This may make a difference.


Thanks !


On 15/01/2022 04:17, Jonathan Valliere wrote:
> Additionally, that unit test you referenced is passing for me on 
> AdoptOpenJDK 11
> 
> On Fri, Jan 14, 2022 at 10:10 PM Jonathan Valliere <johnnyv@apache.org 
> <ma...@apache.org>> wrote:
> 
>     Can you send the server debugging logs?
> 
>     On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny
>     <elecharny@gmail.com <ma...@gmail.com>> wrote:
> 
> 
> 
>         On 14/01/2022 18:48, Emmanuel Lécharny wrote:
>          > Hi Jonathan,
>          >
>          > I also have a failure in
>         SslFilterTest.testMessageSentIsCalled_With_SSL.
>          >
>          > What happens is that we try to send 2 messages (test-1 and
>         test-2) with
>          > SSL established, but we do a SSL renegociation in between the
>         first
>          > message sending and the second.
>          >
>          > For some unknown reason, when we try to read the response on
>         the client
>          > side (something we do in one shot after the second message
>         has been
>          > sent), we never get back the second message.
>          >
>          > I'm positive it has been sent, I strongly suspect that the
>         client socket
>          > lose it during the SSL uncrypting *after* the Ssl reneg has
>         occured.
> 
>         So here are the data being sent by the server with MINA 2.1.5:
> 
>         HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51
>         03 03 61
>         E2 12 0B 67] (ServerHello)
>         HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01] (ChangeCipherSpec)
>         HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69
>         CD 46 99
>         0D A4 B2] (ServerHandshakeFinished)
>         HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72
>         31 73 EF
>         12 00 F6] (Data)
> 
>         rehandhsake
> 
>         HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00
>         34 46 FB
>         53 6C 16] (ServerHello)
>         HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E
>         FF 9A 7C
>         5C BA C7] (ChangeCipherSpec)
>         HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F
>         B8 5A 5C
>         2D 46 26] (ServerHandshakeFinished)
>         HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB
>         18 F1 A4
>         AA 75 27]
>         HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8
>         2C 64 88
>         F3 F5 A6]
> 
> 
>         And with MLINA 2.2.0:
> 
>         HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02
>         00 00 51
>         03 03 61 E2 13 CE CD] (ServerHello)
>         HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01
>         16 03 03
>         00 60 AA 0C 98 25 E0] (ChangeCipherSpec) + (ServerHandshakeFinished)
>         HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1
>         D5 CB
>         5E 78 73 29 60 C0 FF] (Data)
> 
>         rehandshake
> 
>         HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD
>         B1 5D
>         F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
>         (ServerHandshakeFinished)
>         HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9
>         B7 57
>         5C A3 1D A0 14 26 87] (Data)
> 
> 
>         It's pretty much like if the server sends HS data as a whole
>         instead of
>         splitting them in pieces. However, I think everything is there,
>         so I
>         don't understand why it fails in MINA 2.2...
> 
>         -- 
>         *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
>         T. +33 (0)4 89 97 36 50
>         P. +33 (0)6 08 33 32 61
>         emmanuel.lecharny@busit.com <ma...@busit.com>
>         https://www.busit.com/ <https://www.busit.com/>
> 
>         ---------------------------------------------------------------------
>         To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
>         <ma...@mina.apache.org>
>         For additional commands, e-mail: dev-help@mina.apache.org
>         <ma...@mina.apache.org>
> 

-- 
*Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
T. +33 (0)4 89 97 36 50
P. +33 (0)6 08 33 32 61
emmanuel.lecharny@busit.com https://www.busit.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org


Re: MINA 2.2: some more test failures

Posted by Jonathan Valliere <jo...@apache.org>.
Additionally, that unit test you referenced is passing for me on
AdoptOpenJDK 11

On Fri, Jan 14, 2022 at 10:10 PM Jonathan Valliere <jo...@apache.org>
wrote:

> Can you send the server debugging logs?
>
> On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny <el...@gmail.com>
> wrote:
>
>>
>>
>> On 14/01/2022 18:48, Emmanuel Lécharny wrote:
>> > Hi Jonathan,
>> >
>> > I also have a failure in SslFilterTest.testMessageSentIsCalled_With_SSL.
>> >
>> > What happens is that we try to send 2 messages (test-1 and test-2) with
>> > SSL established, but we do a SSL renegociation in between the first
>> > message sending and the second.
>> >
>> > For some unknown reason, when we try to read the response on the client
>> > side (something we do in one shot after the second message has been
>> > sent), we never get back the second message.
>> >
>> > I'm positive it has been sent, I strongly suspect that the client
>> socket
>> > lose it during the SSL uncrypting *after* the Ssl reneg has occured.
>>
>> So here are the data being sent by the server with MINA 2.1.5:
>>
>> HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51 03 03 61
>> E2 12 0B 67] (ServerHello)
>> HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01] (ChangeCipherSpec)
>> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69 CD 46 99
>> 0D A4 B2] (ServerHandshakeFinished)
>> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72 31 73 EF
>> 12 00 F6] (Data)
>>
>> rehandhsake
>>
>> HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00 34 46 FB
>> 53 6C 16] (ServerHello)
>> HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E FF 9A 7C
>> 5C BA C7] (ChangeCipherSpec)
>> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F B8 5A 5C
>> 2D 46 26] (ServerHandshakeFinished)
>> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB 18 F1 A4
>> AA 75 27]
>> HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8 2C 64 88
>> F3 F5 A6]
>>
>>
>> And with MLINA 2.2.0:
>>
>> HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02 00 00 51
>> 03 03 61 E2 13 CE CD] (ServerHello)
>> HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01 16 03 03
>> 00 60 AA 0C 98 25 E0] (ChangeCipherSpec) + (ServerHandshakeFinished)
>> HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1 D5 CB
>> 5E 78 73 29 60 C0 FF] (Data)
>>
>> rehandshake
>>
>> HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD B1 5D
>> F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
>> (ServerHandshakeFinished)
>> HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9 B7 57
>> 5C A3 1D A0 14 26 87] (Data)
>>
>>
>> It's pretty much like if the server sends HS data as a whole instead of
>> splitting them in pieces. However, I think everything is there, so I
>> don't understand why it fails in MINA 2.2...
>>
>> --
>> *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
>> T. +33 (0)4 89 97 36 50
>> P. +33 (0)6 08 33 32 61
>> emmanuel.lecharny@busit.com https://www.busit.com/
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
>> For additional commands, e-mail: dev-help@mina.apache.org
>>
>>

Re: MINA 2.2: some more test failures

Posted by Jonathan Valliere <jo...@apache.org>.
Can you send the server debugging logs?

On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny <el...@gmail.com>
wrote:

>
>
> On 14/01/2022 18:48, Emmanuel Lécharny wrote:
> > Hi Jonathan,
> >
> > I also have a failure in SslFilterTest.testMessageSentIsCalled_With_SSL.
> >
> > What happens is that we try to send 2 messages (test-1 and test-2) with
> > SSL established, but we do a SSL renegociation in between the first
> > message sending and the second.
> >
> > For some unknown reason, when we try to read the response on the client
> > side (something we do in one shot after the second message has been
> > sent), we never get back the second message.
> >
> > I'm positive it has been sent, I strongly suspect that the client socket
> > lose it during the SSL uncrypting *after* the Ssl reneg has occured.
>
> So here are the data being sent by the server with MINA 2.1.5:
>
> HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51 03 03 61
> E2 12 0B 67] (ServerHello)
> HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01] (ChangeCipherSpec)
> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69 CD 46 99
> 0D A4 B2] (ServerHandshakeFinished)
> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72 31 73 EF
> 12 00 F6] (Data)
>
> rehandhsake
>
> HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00 34 46 FB
> 53 6C 16] (ServerHello)
> HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E FF 9A 7C
> 5C BA C7] (ChangeCipherSpec)
> HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F B8 5A 5C
> 2D 46 26] (ServerHandshakeFinished)
> HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB 18 F1 A4
> AA 75 27]
> HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8 2C 64 88
> F3 F5 A6]
>
>
> And with MLINA 2.2.0:
>
> HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02 00 00 51
> 03 03 61 E2 13 CE CD] (ServerHello)
> HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01 16 03 03
> 00 60 AA 0C 98 25 E0] (ChangeCipherSpec) + (ServerHandshakeFinished)
> HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1 D5 CB
> 5E 78 73 29 60 C0 FF] (Data)
>
> rehandshake
>
> HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD B1 5D
> F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) +
> (ServerHandshakeFinished)
> HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9 B7 57
> 5C A3 1D A0 14 26 87] (Data)
>
>
> It's pretty much like if the server sends HS data as a whole instead of
> splitting them in pieces. However, I think everything is there, so I
> don't understand why it fails in MINA 2.2...
>
> --
> *Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
> T. +33 (0)4 89 97 36 50
> P. +33 (0)6 08 33 32 61
> emmanuel.lecharny@busit.com https://www.busit.com/
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
> For additional commands, e-mail: dev-help@mina.apache.org
>
>

Re: MINA 2.2: some more test failures

Posted by Emmanuel Lécharny <el...@gmail.com>.

On 14/01/2022 18:48, Emmanuel Lécharny wrote:
> Hi Jonathan,
> 
> I also have a failure in SslFilterTest.testMessageSentIsCalled_With_SSL.
> 
> What happens is that we try to send 2 messages (test-1 and test-2) with 
> SSL established, but we do a SSL renegociation in between the first 
> message sending and the second.
> 
> For some unknown reason, when we try to read the response on the client 
> side (something we do in one shot after the second message has been 
> sent), we never get back the second message.
> 
> I'm positive it has been sent, I strongly suspect that the client socket 
> lose it during the SSL uncrypting *after* the Ssl reneg has occured.

So here are the data being sent by the server with MINA 2.1.5:

HeapBuffer[pos=0 lim=1332 cap=2115: 16 03 03 05 2F 02 00 00 51 03 03 61 
E2 12 0B 67] (ServerHello)
HeapBuffer[pos=0 lim=6 cap=8: 14 03 03 00 01 01] (ChangeCipherSpec)
HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 43 27 00 F6 69 CD 46 99 
0D A4 B2] (ServerHandshakeFinished)
HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 6E 02 38 7C 72 31 73 EF 
12 00 F6] (Data)

rehandhsake

HeapBuffer[pos=0 lim=181 cap=264: 16 03 03 00 B0 7D 9A 82 9D 00 34 46 FB 
53 6C 16] (ServerHello)
HeapBuffer[pos=0 lim=85 cap=132: 14 03 03 00 50 99 F3 FC 9C 7E FF 9A 7C 
5C BA C7] (ChangeCipherSpec)
HeapBuffer[pos=0 lim=101 cap=132: 16 03 03 00 60 80 B1 2C C0 6F B8 5A 5C 
2D 46 26] (ServerHandshakeFinished)
HeapBuffer[pos=0 lim=85 cap=132: 17 03 03 00 50 0C D5 D8 0E CB 18 F1 A4 
AA 75 27]
HeapBuffer[pos=0 lim=85 cap=132: 15 03 03 00 50 42 7B BE AF B8 2C 64 88 
F3 F5 A6]


And with MLINA 2.2.0:

HeapBuffer@4b38503[pos=0 lim=1332 cap=33842: 16 03 03 05 2F 02 00 00 51 
03 03 61 E2 13 CE CD] (ServerHello)
HeapBuffer@58e57fe3[pos=0 lim=107 cap=33842: 14 03 03 00 01 01 16 03 03 
00 60 AA 0C 98 25 E0] (ChangeCipherSpec) + (ServerHandshakeFinished)
HeapBuffer@26e25a06[pos=0 lim=85 cap=33842: 17 03 03 00 50 F9 A1 D5 CB 
5E 78 73 29 60 C0 FF] (Data)

rehandshake

HeapBuffer@1558ae1[pos=0 lim=367 cap=33842: 16 03 03 00 B0 BF CD B1 5D 
F9 5B FC 56 11 52 69] (ServerHello) + ChangeCipherSpec) + 
(ServerHandshakeFinished)
HeapBuffer@5038afc9[pos=0 lim=85 cap=33842: 17 03 03 00 50 6A F9 B7 57 
5C A3 1D A0 14 26 87] (Data)


It's pretty much like if the server sends HS data as a whole instead of 
splitting them in pieces. However, I think everything is there, so I 
don't understand why it fails in MINA 2.2...

-- 
*Emmanuel Lécharny - CTO* 205 Promenade des Anglais – 06200 NICE
T. +33 (0)4 89 97 36 50
P. +33 (0)6 08 33 32 61
emmanuel.lecharny@busit.com https://www.busit.com/

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org