[
https://issues.apache.org/jira/browse/DIRMINA-580?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
janardhanan vembunarayanan updated DIRMINA-580:
-----------------------------------------------
Priority: Blocker (was: Major)
Here is a step by step analysis of the bug
503sessionid = 82 Data Read: [EMAIL PROTECTED] (HeapBuffer[pos=0 lim=512
cap=512: 16 03 01 00 20 86 E4 DA BC C8 EA 3F 29 D8 2E 29 46 16 02 1F F0 47 93
0A 90 BB 95 B2 12 87 06 EA 6C 2E 6E 31 CD 17 03 01 04 88 0D 19 20 07 F4 1A E0
E2 19 4C 5B E6 A8 D4 B9 71 07 75 1E 3F 20 DF F9 E7 8E EE 2D 17 8C FA CE 8E 55
CC 4C DC DA D8 22 8B 15 D3 DD D6 12 25 5B 11 C2 E1 38 B6 D3 7A 91 DD 0A 25 91
08 E9 63 FF 57 54 12 47 53 DE 30 6D 2F 66 95 D6 2D 29 17 8B 40 C7 E9 C7 7A E8
79 25 AB D2 B4 0D CB 03 3E 7E 6B 62 A7 49 FC F5 7A DB F0 B4 8F 40 D3 20 DD 75
55 11 2C 6C 67 89 10 8E F4 F9 21 F7 72 E4 43 B6 77 9C FA 64 17 D4 84 9C 49 56
3C A5 BA 0A B9 E4 CA CA F8 3D 04 64 BA D2 50 18 00 95 59 3D F2 45 09 C3 21 B6
14 C0 7A CC E8 CD 7A 73 F9 B3 72 B5 6D A5 90 F0 21 31 AB A3 47 CD 3E DA D9 76
DF 97 7F FA B9 DC F3 AA 8D A4 92 2D 7D DB 27 BB 51 1D D2 FF 42 0F 32 AD 3B BE
F2 11 03 05 4C AB 6B FC 1E 4D 99 9D 5D 90 A5 5C FD 03 39 D8 8D 58 74 16 16 49
7D 96 F5 7E 28 43 9D 80 74 18 B2 2D B1 C8 E8 1B 8E 81 05 43 D1 89 6F B1 64 08
8D EC 73 F6 B2 64 48 F7 7C DC 7A 10 F4 AF EB D0 14 35 5E DB 24 9F DC 27 4F E1
D8 CB 22 15 14 3A 81 C4 D8 8F 44 C7 3D DC 9D B1 AE B5 FF 97 6B 9A A0 2C 6D AE
93 22 22 DB F3 8C FF 6B 06 27 FB C8 65 FB C7 7F E0 D4 06 CD 04 D1 60 F8 12 EE
C9 21 63 BB 39 BD A7 84 F6 34 C5 67 B2 43 32 1E E2 B3 99 EB C0 48 D4 77 D5 64
DF A9 41 4D 4A E4 FD 45 E9 E0 AB B1 4B F6 8E 71 CF B7 C0 3C 5F 1A C8 65 5E 3D
BA 52 27 4A B2 05 CF 38 30 81 3E 84 BE 4D 47 C5 72 29 1C 14 85 1F 2B 85 59 EA
D8 DB 99 7E 5D 2B 93 49 27 61 F6 55 EF 31 96 A8 C3 6D 2E 57 AC 62 76 6A D9 5B
1D 8C FD 0D 27 A8 8A BE 09 6F EA EA AC 59 86 05 9D 24 6F 56 C3])null
At this stage the information is copied
503sessionid = 82 inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=512
cap=16665]null
503sessionid = 82 appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330
cap=33330]null
and the status moves to FINISHED and OK
1210354840435 sslhandler unwrap0 503sessionid = 82 handshakestatus = FINISHED
status = OK
At this stage it is in the method unwrapHandshake it gets into the method
which calls unwrap0 again and the status
moves to NOT_HANDSHAKING and BUFFER_UNDERFLOW. After this the inNetBuffer is
compacted and this will cause the
method handshake() to break from the for(;;) loop
At this stage the buffer look like this
503sessionid = 82 inNetBuffer: java.nio.DirectByteBuffer[pos=37 lim=512
cap=16665]null
503sessionid = 82 appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330
cap=33330]null
1210354840435 sslhandler unwrap0 503sessionid = 82 handshakestatus =
NOT_HANDSHAKING status = BUFFER_UNDERFLOW
// If handshake finished, no data was produced, and the status is
still ok,
// try to unwrap more
if (handshakeStatus == SSLEngineResult.HandshakeStatus.FINISHED
&& res.getStatus() == SSLEngineResult.Status.OK
&& inNetBuffer.hasRemaining()) {
res = unwrap0();
// prepare to be written again
inNetBuffer.compact();
renegotiateIfNeeded(nextFilter, res);
}
After this the client sends its next set of messages as given below.
503sessionid = 82 Data Read: [EMAIL PROTECTED] (HeapBuffer[pos=0 lim=690
cap=1024: 35 CD B0 6A 74 E6 00 08 31 CA D5 F5 97 3C F3 87 2F A9 6A 05 1C 75 48
14 A8 51 D9 54 D7 6F B8 22 89 0E 14 96 89 6F E9 35 F4 93 0B A7 F3 26 8B 66 F5
72 99 1A 37 6E B6 19 DA CE 88 5B 78 79 E3 E4 93 6B 35 F2 68 D5 43 2D 8C D6 30
85 25 87 C0 C1 F3 5E 1D AB EF 42 6F 92 90 D3 B7 C3 3A 24 1E 80 63 5A B7 A9 00
25 79 59 92 8F 36 0E DE AF 9C 15 8E 40 6C BA AF 4A 22 0D 63 67 FB 24 2C 0F 70
95 7F 68 1D C1 98 4A 2C 81 FA 7C 6A 73 95 1D E8 C2 D2 FD 10 0F 8E 43 8F AE F8
E2 59 49 16 45 CE B2 38 1E 77 C8 FE 1D 49 78 0A A2 D6 60 44 2C 4F 8F 80 67 CC
6A 3E FA 10 A8 3D DF F0 AD 1A E7 00 69 D8 F3 14 71 BD 4D 99 95 3C AC CE BF 7B
66 3B 4E 59 E2 68 48 E8 ED 48 9C 33 3B 41 3C 9A F5 C3 47 6C 8E E3 20 94 F3 86
F2 9F 36 82 D8 2F D0 71 07 0B AC 69 31 57 EC 06 D3 A7 62 7B 49 60 A9 2E 3A 49
CB 28 90 A0 CD 7A A4 7C 37 B6 6B C5 6E 20 C6 5E 97 39 47 F1 B8 6A AF DD 03 04
DC 21 B7 BB A7 7D BF 09 B6 FA 43 32 F9 FF ED 49 7C 15 99 83 4A BD 3A EC E3 03
FC 0B 83 08 01 E9 4F 8C 86 C7 37 E2 81 D7 D5 00 2F A4 34 DB 3C 6B 5D 65 7C 53
AF 22 1B FB CE 3A C4 76 D8 14 C9 4A C6 35 90 0B 0D D2 F1 10 A5 E7 1A 8C 8E FA
B1 93 47 E6 67 AF 6F 10 7A 77 05 78 9A C5 43 C8 0E 81 78 57 A5 31 44 09 1C A7
48 17 DD 2B B4 B2 29 1D B9 2B 0C DD 23 84 1F F7 44 1C A1 CE 64 D5 B1 78 EB 2A
04 20 4D 26 63 6B 22 58 4D 1F 3C 1D 95 CF C8 B2 04 29 23 6E DD 06 BD 7D BD A1
94 62 55 86 4E 32 F4 82 89 7F C5 C6 87 0A 8E E6 CB DA F4 5D AA 25 DB 2D 56 14
62 C9 79 86 B8 64 F9 26 62 D8 A7 24 4D 0D 82 27 08 FA 75 D7 80 D0 E7 27 CA E7
AE 3C 8B 9E F9 92 A3 80 58 A7 5E CE 52 19 18 77 F5 09 44 B8 9C 59 DD 29 FB 45
9B 7D B4 36 86 52 53 C0 23 3A 83 B6 F6 B9 73 D2 08 56 EA A5 84 3F A7 34 21 A6
96 88 E3 41 9B D7 8F 84 6B F6 97 DD 99 F7 20 36 FA BD 8E 93 A2 A4 B8 8A 98 74
5C D5 BA 26 E3 8F 8C EB 00 53 F2 A3 78 87 9E FF C4 62 36 99 7A F8 10 EF F8 2F
74 F4 66 5B BE 9E 7F 3A 14 59 9D 91 A6 7E 8A F3 55 7A A7 60 A6 BD 24 02 D3 59
FA 7D B5 6A 8C A9 56 71 CD 0B C3 20 26 0E F2 9A 66 56 92 4F F6 0F 04 D6 72 64
3C 83 AB 5C D0 2A 5B 90 CA BF 2F 37 62 7F 1E 97 16 10 AA 3E D9 36 B5 B6 CE F5
3C 04 B0 B8 A3 BF D0 50 92 BF 29 70 36 67 E3 B3 B2])null
So we already have 476 bytes and then we are getting 690 bytes.
Now in the handshake() method we have
1210354840435 sslhandler handshake 503sessionid = 82 handshakeStatus =
FINISHED handshakeComplete = false
This gets into the block and the state is
1210354840435 sslhandler handshake 503sessionid = 82 handshakeStatus =
FINISHED handshakeComplete = true
for(;;;)
if (handshakeStatus == SSLEngineResult.HandshakeStatus.FINISHED) {
session.setAttribute(SSLFilter.SSL_SESSION,
sslEngine.getSession());
handshakeComplete = true;
...
break;
}
...
But at this point we have all the data but we are not doing anything with the
data and sitting there until the idle timeout
gets triggered and this is the issue in this case
Thus in the method messageReceived of SSLHandler the decrypt method never gets
called as the client is done with sending
the data and we have the data in the inNetBuffer and it never gets copied to
the appBuffer
if (!handshakeComplete) {
handshake(nextFilter);
} else {
decrypt(nextFilter);
}
> Session Idle times out when SSL is enabled
> ------------------------------------------
>
> Key: DIRMINA-580
> URL: https://issues.apache.org/jira/browse/DIRMINA-580
> Project: MINA
> Issue Type: Bug
> Components: Filter
> Affects Versions: 1.0.9
> Environment: Sun Solaris
> Reporter: janardhanan vembunarayanan
> Priority: Blocker
> Attachments: session82.txt
>
>
> I have developed an HTTP Routing server using Mina 1.0.9 and I am using
> SSLFilter for handling SSL Connections.
> 1. Using Jmeter as the client I am sending HTTPS requests to this server with
> 5 threads.
> 2. For some of the requests(10%) the sessionCreated method on the Handler is
> getting called and the data from the client is not read by the server.
> 3. sessionIdle() gets triggered and we close the connection.
> This happens for the ssl connections only and when the server is trying to
> resume the cached session.
> I enabled ssl debug using -Djavax.net.debug=all on the server and I got the
> following logs for the failed sessions
> 0240: EB 3E 28 AD 97 20 36 B7 C0 35 4E 3E 80 71 88 99 %% Created:
> [Session-17, SSL_RSA_WITH_RC4_128_MD5]
> 9uTWV0aG961 58 4Dk%% Cached server session: [Session-17,
> SSL_RSA_WITH_RC4_128_MD5]
> 10 7A 0F 37 59C 66 D3 18 2A 2B 3144 1F 5 D9 16A EB 1 1F%% Resuming
> [Session-17, SSL_RSA_WITH_RC4_128_MD5]
> org.apache.mina.filter.SSLFilter.SSLSession=[Session-17,
> SSL_RSA_WITH_RC4_128_MD5]
> %% Invalidated: [Session-17, SSL_RSA_WITH_RC4_128_MD5]
> Any ideas why this could happen?
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
