> > [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 <john...@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 <john...@apache.org> > wrote: > >> Can you send the server debugging logs? >> >> On Fri, Jan 14, 2022 at 7:46 PM Emmanuel Lécharny <elecha...@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.lecha...@busit.com https://www.busit.com/ >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org >>> For additional commands, e-mail: dev-h...@mina.apache.org >>> >>>
