Hi all
It seems like sometimes client connections over SSL does not properly
terminate after the keepalive socket closes. This happens with the
Synapse ESB (which uses HttpCore/NIO-4.0-beta1), but I am still
investigating if this is a problem with Synapse or HttpCore/NIO.. but my
guess is its on HttpCore/NIO.. If you have any suggestions, please let
me know..
During normal operation (with localhost), I see:
2008-05-29 12:04:21,034 [127.0.1.1-asankha] [I/O dispatcher 1] DEBUG
SSLIOSession I/O session sslclient-2 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 0 bytes read
2008-05-29 12:04:21,037 [127.0.1.1-asankha] [I/O dispatcher 1] DEBUG
ClientHandler HTTP connection [localhost/127.0.0.1:9002]: Content
decoder [chunk-coded; completed: true]
.....
2008-05-29 12:04:21,084 [127.0.1.1-asankha] [I/O dispatcher 2] DEBUG
SSLIOSession I/O session sslclient-3 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 0 bytes read
2008-05-29 12:04:21,084 [127.0.1.1-asankha] [I/O dispatcher 2] DEBUG
ClientHandler HTTP connection [localhost/127.0.0.1:9002]: Content
decoder [chunk-coded; completed: true]
.......
....<after keepalive close>.....
.......
2008-05-29 12:05:21,012 [127.0.1.1-asankha] [I/O dispatcher 1] DEBUG
SSLIOSession I/O session sslclient-2 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: -1 bytes read
2008-05-29 12:05:21,013 [127.0.1.1-asankha] [I/O dispatcher 1] DEBUG
SSLIOSession I/O session sslclient-2 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: Close
2008-05-29 12:05:21,013 [127.0.1.1-asankha] [I/O dispatcher 1] DEBUG
ClientHandler HTTP connection [closed]: Closed
2008-05-29 12:05:21,092 [127.0.1.1-asankha] [I/O dispatcher 2] DEBUG
SSLIOSession I/O session sslclient-3 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: -1 bytes read
2008-05-29 12:05:21,093 [127.0.1.1-asankha] [I/O dispatcher 2] DEBUG
SSLIOSession I/O session sslclient-3 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: Close
2008-05-29 12:05:21,093 [127.0.1.1-asankha] [I/O dispatcher 2] DEBUG
ClientHandler HTTP connection [closed]: Closed
However, when talking to a real external server, we see:
2008-05-28 13:28:05,156 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 1430 bytes read
.....
2008-05-28 13:28:05,163 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG ClientHandler HTTP connection [xxx/x.x.x.x:443]: Input ready
2008-05-28 13:28:05,163 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 0 bytes read
2008-05-28 13:28:05,163 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 0 bytes read
2008-05-28 13:28:05,164 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][0][0]: 0 bytes read
......
2008-05-28 13:28:05,170 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG ClientHandler HTTP connection [xxx/x.x.x.x:443]: Content decoder
[chunk-coded; completed: true]
.......
....<after keepalive close>.....
.......
2008-05-28 13:28:35,197 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NEED_WRAP][0][0][0][0]: -1 bytes read
2008-05-28 13:28:35,197 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NEED_WRAP][0][0][0][0]: Close
*2008-05-28 13:28:35,198 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [r]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][23][0]: Clear event [r]
2008-05-28 13:28:35,198 [192.168.250.23-esbtest02] [I/O dispatcher 1]
DEBUG SSLIOSession I/O session 7 [interested ops: [w]; ready ops:
[r]][SSL handshake status: NOT_HANDSHAKING][0][0][23][0]: Clear event [r]
*This last line "SSLIOSession I/O session 7 [interested ops: [w]; ready
ops: [r]][SSL handshake status: NOT_HANDSHAKING][0][0][23][0]: Clear
event [r]" appears continuously in the log file. One thing I note is
that after you get the -1 bytes read, you move to 23 bytes of encrypted
data on the out buffer.. any idea as to why, or what went wrong?
thanks
asankha
