On Thu, 2008-05-29 at 12:38 +0530, Asankha C. Perera wrote: > 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? >
Asankha, The process of graceful termination of an SSL session involves some handshaking between the server and the client. Apparently what happens here is that the origin server dropped the persistent connection by closing the underlying network socket without the sending the orderly 'close notify' alert. It _appears_ HttpCore failed to detect the fact the session had been terminated abnormally and kept on trying to send out the 'close notify' alert. It is a fairly difficult to reproduce situation. Would you be able to run Synapse HTTP transport under a debugger and see where exactly the handling of abnormal termination of SSL sessions goes wrong? Cheers Oleg > thanks > asankha --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
