[
https://issues.apache.org/jira/browse/DIRMINA-1145?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17391155#comment-17391155
]
Jonathan Valliere commented on DIRMINA-1145:
--------------------------------------------
Update your local copy of bugfix/DIRMINA-1132.
https://gitbox.apache.org/repos/asf?p=mina.git;a=commit;h=f3691724a48a11cd46395e5478f4e35c1afe78e9
I had to add a null check for the cipher suits and protocols. Other than that
it connects and the message it sent/received.
{noformat}
server
10:09:46.753 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
Adding the SSL Filter sslFilter to the chain
10:09:46.770 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
openend
10:09:46.772 [NioProcessor-3] DEBUG o.a.m.f.e.OrderedThreadPoolExecutor -
Adding event SESSION_OPENED to session 2
Queue : [SESSION_OPENED, ]10:09:46.774 [pool-1-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Firing a SESSION_OPENED event for
session 2
10:09:46.775 [pool-1-thread-1] DEBUG o.a.m.core.filterchain.IoFilterEvent -
Event SESSION_OPENED has been fired for session 2
10:09:46.824 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
received HeapBuffer@1779e5b3[pos=0 lim=375 cap=2048: 16 03 03 01 72 01 00 01 6E
03 03 B0 5C 16 95 31]
10:09:46.825 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] receive() - message
HeapBuffer@1779e5b3[pos=0 lim=375 cap=2048: 16 03 03 01 72 01 00 01 6E 03 03 B0
5C 16 95 31]
10:09:46.825 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() - source
HeapBuffer@1779e5b3[pos=0 lim=375 cap=2048: 16 03 03 01 72 01 00 01 6E 03 03 B0
5C 16 95 31]
10:09:46.841 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() -
bytes-consumed 375, bytes-produced 0, status OK, handshake NEED_TASK
10:09:46.842 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() - handshake
needs task, scheduling
10:09:46.843 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] task() - executing
sun.security.ssl.SSLEngineImpl$DelegatedTask@75fc335
10:09:46.947 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] task() - writing handshake
messages
10:09:46.947 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qwrite() - internal
10:09:46.948 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - bytes-consumed
0, bytes-produced 127, status OK, handshake NEED_WRAP
10:09:46.948 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - handshake needs
wrap, fast looping
10:09:46.948 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - bytes-consumed
0, bytes-produced 6, status OK, handshake NEED_WRAP
10:09:46.948 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - handshake needs
wrap, fast looping
10:09:46.963 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - bytes-consumed
0, bytes-produced 2094, status OK, handshake NEED_UNWRAP
10:09:46.963 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - result
HeapBuffer@55b4d784[pos=0 lim=2227 cap=33418: 16 03 03 00 7A 02 00 00 76 03 03
66 64 88 A2 F9]
10:09:46.964 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - handshake needs
unwrap, invoking receive
10:09:46.964 [ssl-exec-0] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] receive() - message
DirectBuffer@55256e63[pos=0 lim=0 cap=0: ]
10:09:46.965 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
ack WriteRequest: HeapBuffer@55b4d784[pos=0 lim=2227 cap=33418: 16 03 03 00 7A
02 00 00 76 03 03 66 64 88 A2 F9]
10:09:47.007 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
received HeapBuffer@13104957[pos=0 lim=6 cap=2048: 14 03 03 00 01 01]
10:09:47.007 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] receive() - message
HeapBuffer@13104957[pos=0 lim=6 cap=2048: 14 03 03 00 01 01]
10:09:47.007 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() - source
HeapBuffer@13104957[pos=0 lim=6 cap=2048: 14 03 03 00 01 01]
10:09:47.007 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() -
bytes-consumed 6, bytes-produced 0, status OK, handshake NEED_UNWRAP
10:09:47.067 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
received HeapBuffer@6f57045d[pos=0 lim=74 cap=1024: 17 03 03 00 45 65 10 4D 94
53 23 D8 F3 09 3A 66]
10:09:47.067 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] receive() - message
HeapBuffer@6f57045d[pos=0 lim=74 cap=1024: 17 03 03 00 45 65 10 4D 94 53 23 D8
F3 09 3A 66]
10:09:47.067 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() - source
HeapBuffer@6f57045d[pos=0 lim=74 cap=1024: 17 03 03 00 45 65 10 4D 94 53 23 D8
F3 09 3A 66]
10:09:47.071 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() -
bytes-consumed 74, bytes-produced 0, status OK, handshake NEED_WRAP
10:09:47.071 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qreceive() - handshake
needs wrap, invoking write
10:09:47.071 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] qwrite() - internal
10:09:47.072 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - bytes-consumed
0, bytes-produced 88, status OK, handshake FINISHED
10:09:47.072 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - result
HeapBuffer@36ec79be[pos=0 lim=88 cap=33418: 17 03 03 00 53 91 81 57 DD B9 E8 45
87 38 57 52]
10:09:47.072 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=false] lwrite() - handshake
finished, flushing queue
10:09:47.073 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=true] flush() - no saved messages
10:09:47.073 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
ack WriteRequest: HeapBuffer@36ec79be[pos=0 lim=88 cap=33418: 17 03 03 00 53 91
81 57 DD B9 E8 45 87 38 57 52]
10:09:47.073 [NioProcessor-3] DEBUG o.apache.mina.filter.ssl2.SSL2Filter -
session (0x00000002: nio socket, server, /127.0.0.1:39916 => /127.0.0.1:8888)
received HeapBuffer@7da68a4d[pos=0 lim=53 cap=1024: 17 03 03 00 30 84 EE 51 EE
CF A2 AC 84 25 38 E4]
10:09:47.074 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=true] receive() - message
HeapBuffer@7da68a4d[pos=0 lim=53 cap=1024: 17 03 03 00 30 84 EE 51 EE CF A2 AC
84 25 38 E4]
10:09:47.074 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=true] qreceive() - source
HeapBuffer@7da68a4d[pos=0 lim=53 cap=1024: 17 03 03 00 30 84 EE 51 EE CF A2 AC
84 25 38 E4]
10:09:47.074 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=true] qreceive() - bytes-consumed
53, bytes-produced 15, status OK, handshake NOT_HANDSHAKING
10:09:47.074 [NioProcessor-3] DEBUG o.a.mina.filter.ssl2.SSL2Handler -
SSL2HandlerG0@1ed4f920[mode=server, connected=true] qreceive() - result
HeapBuffer@28523dce[pos=0 lim=15 cap=16676: 48 65 6C 6C 6F 20 53 65 72 76 65 72
2E 2E 0A]
10:09:47.075 [NioProcessor-3] DEBUG o.a.m.f.codec.ProtocolCodecFilter -
Processing a MESSAGE_RECEIVED for session 2
10:09:47.076 [NioProcessor-3] DEBUG o.a.m.f.e.OrderedThreadPoolExecutor -
Adding event MESSAGE_RECEIVED to session 2
Queue : [MESSAGE_RECEIVED, ]10:09:47.077 [pool-1-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for
session 2
Aug 01, 2021 10:09:47 AM MinaServerHandler messageReceived
INFO: Message received in the server..
message is Hello Server..
Aug 01, 2021 10:09:47 AM MinaServerHandler messageReceived
INFO: Message is: Hello Server..
10:09:47.124 [pool-1-thread-1] DEBUG o.a.m.core.filterchain.IoFilterEvent -
Event MESSAGE_RECEIVED has been fired for session 2
{noformat}
> Mina Server is losing messages
> ------------------------------
>
> Key: DIRMINA-1145
> URL: https://issues.apache.org/jira/browse/DIRMINA-1145
> Project: MINA
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.1.4
> Reporter: Guy Itzhaki
> Assignee: Jonathan Valliere
> Priority: Major
> Fix For: 2.2.0
>
> Attachments: DIRMINA-1145.zip, mina-core-2.1.5-SNAPSHOT-ssl2.jar,
> mina_client_server.zip
>
>
> During our tests we found that in some circumstances Mina server loses
> messages.
> From what we understand this happens when client opens connection and then
> sends message(s) and the server is still busy processing the sessionOpened
> event while the message the client sent went through the server’s filterChain.
>
> Attached is a simple client and server that will help you reproduce the
> problem, before you run it please perform the following steps:
> *+Configuration:+*
> # In order to reproduce the problem SSL filter *must* be defined (already
> implemented in the attached example)
> # Update the keystore and truststore files locations in *addSSLFilter()*
> method in *MinaClient* and *MinaServer*
> # Set server break points at:
> # MinaServerHandler#sessionOpened
> # MinaServerHandler#messageReceived
> # org.apache.mina.core.filterchain.IoFilter.NextFilter#messageReceived
> # Set client break points at:
> # MinaClientHandler#sessionOpened
>
> *Since this is a timing problem you need to run a debugger as described
> below:*
> # Start server
> # Start client
> # At the client at *MinaClientHandler#sessionOpened* release the break point
> # Release all break points +except+ server’s
> *MinaServerHandler#sessionOpened*
> # After org.apache.mina.core.filterchain.IoFilter.NextFilter#messageReceived
> completed to process all events, you can release
> *MinaServerHandler#sessionOpened*
>
> +*Expected result:*+
> MinaServerHandler#messageReceived will be invoked with the message sent by
> the client
> *+Actual result:+*
> MinaServerHandler#messageReceived is not invoked.
>
> To use the example, add the following jars to your class path:
> commons-lang3-3.9.jar
> log4j-api-2.13.3.jar
> log4j-core-2.13.3.jar
> log4j-jcl-2.13.3.jar
> mina-core-2.1.4.jar
> slf4j-api-1.7.26.jar
> spring-jcl-5.2.12.RELEASE.jar
>
> The java we use is *AdoptJDK 11.0.8*
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
