Okay. here's what I think is happening : (Client => C Server -> S)
C -> S : initiates connection
C <-> S : handshake
S -> C : server sends application data
S -> C : server tries to read from the socket
-> finds nothing (0 bytes returned)
-> assumes transaction is completed, and starts cleanup process
-> closes the connection first
-> frees the pool, which invokes ssl_io_filter_cleanup() and inturn
ssl_io_filter_shutdown()
-> ssl_io_filter_shutdown() tries to send 'Close notify'
OOPS ! The connection has already been terminated
Any comments ?
-Madhu
>-----Original Message-----
>From: Mathihalli, Madhusudan
>Sent: Thursday, February 05, 2004 1:31 PM
>To: [EMAIL PROTECTED]
>Subject: RE: mod_ssl not sending Alert upon close ?
>
>
>I tried using all the three 'unclean', 'standard' and
>'accurate' shutdown methods. I'm using MSIE 6.0 (and can
>attach the ssldump comparision for both Apache 1.3 and 2.x if required)
>
>As regards reproducing, I think you can reproduce it in any
>standard installation. Here's a partial 'tusc' output. As you
>can see, the socket has been closed much before the Alert
>message was *tried* to be sent !
>
>-Madhu
>
>1076016143.543190 {621927} write(10, 0x7af0fcc8, 81) ..... = 81
> [ T h u F e b 0 5 1 3 : 2 2 : 2 3 2 0 0 4 ] [ i n f o
> ] b i o _ f i l t e r _ o u t _ f l u s h : t r y i n g t
> o f l u s h b l e n : 6 7 \n
>1076016143.543457 {621927} writev(13, 0x7af0fc88, 1) ..... = 67
> 1403\0\001011603\0\08 86e5adcaP q 5 b2bdd810ffc11adc- e aaa613cc
> \0H 9fe6d61 l D ! # cas M w W 80x b4\r` t cdce\n6 cd, P L f5x 4
> d0O e
>1076016143.543774 {621927} fcntl(12, F_SETLKW, 0x7b019574) = 0
>1076016143.543943 {621927} time(NULL) .................... = 1076016143
>1076016143.544052 {621927} fcntl(12, F_SETLKW, 0x7b019584) = 0
>1076016143.920487 {621927} poll(0x7af0fe50, 1, 300000) ... = 1
>1076016143.920587 {621927} read(13, 0x402b6810, 8000) .... = 0
>1076016143.920685 {621927} gettimeofday(0x7af0f448, NULL) = 0
>1076016143.920813 {621927} shutdown(13, SHUT_WR) ......... = 0
>1076016143.920898 {621927} poll(0x7af0f650, 1, 2000) ..... = 1
>1076016143.920984 {621927} read(13, 0x7af0f208, 512) ..... = 0
>1076016143.924105 {621927} close(13) ..................... = 0
>1076016143.924239 {621927} gettimeofday(0x7af11788, NULL) = 0
>1076016143.932207 {621927} write(10, 0x7af0f708, 98) ..... = 98
> [ T h u F e b 0 5 1 3 : 2 2 : 2 3 2 0 0 4 ] [ i n f o
> ] b i o _ f i l t e r _ o u t _ w r i t e : t r y i n g t
> o w r i t e i n l : 2 3 ( l e n g t h 0 b l e n 0
> ) \n
>1076016143.932510 {621927} gettimeofday(0x7af11788, NULL) = 0
>1076016143.932608 {621927} write(10, 0x7af0f708, 86) ..... = 86
> [ T h u F e b 0 5 1 3 : 2 2 : 2 3 2 0 0 4 ] [ i n f o
> ] b i o _ f i l t e r _ o u t _ w r i t e : b u f f e r i n
> g d a t a ( N O W R I T E Y E T ) \n
>1076016143.932844 {621927} gettimeofday(0x7af11448, NULL) = 0
>1076016143.932934 {621927} write(10, 0x7af0f3c8, 135) .... = 135
> [ T h u F e b 0 5 1 3 : 2 2 : 2 3 2 0 0 4 ] [ i n f o
> ] C o n n e c t i o n t o c h i l d 1 c l o s e d w
> i t h s t a n d a r d s h u t d o w n ( s e r v e r l u g
> i a . c u p . h p . c o m : 4 4 3 , c l i e n t 1 5 . 0 . 7
> 0 . 1 8 8 ) \n
>
>>-----Original Message-----
>>From: Joe Orton [mailto:[EMAIL PROTECTED]
>>Sent: Thursday, February 05, 2004 12:10 PM
>>To: [EMAIL PROTECTED]
>>Subject: Re: mod_ssl not sending Alert upon close ?
>>
>>
>>I've seen some unclean shutdown errors a few times but never
>managed to
>>get a repro case. What client are you using, how do you
>>reproduce this?
>>I presume you have the same SetEnvIf ssl-unclean-shutdown settings for
>>broken clients when comparing 1.3 and 2.0 behaviour?
>>
>>On Thu, Feb 05, 2004 at 11:06:57AM -0800, Mathihalli,
>Madhusudan wrote:
>>> Hi,
>>> It's been a while since I played with the Apache code,
>>and it'll
>>> be nice if somebody can help me here.
>>>
>>> I put some debug statements in the ssl_engine_io.c - in
>>> bio_filter_out_write() and bio_filter_in_read() to see if the alert
>>> message is actually being sent, and got the following output:
>>>
>>> bio_filter_out_write: trying to write inl: 900 (length 0 blen 0)
>>> bio_filter_out_write: buffering data (NO WRITE YET)
>>> bio_filter_out_flush: trying to flush blen: 900
>>> bio_filter_out_write: trying to write inl: 67 (length 0 blen 0)
>>> bio_filter_out_write: buffering data (NO WRITE YET)
>>> bio_filter_out_flush: trying to flush blen: 67
>>> (70014)End of file found: bio_filter_in_read: got EOF -
>>returning -1 (at the end)
>>> (70014)End of file found: SSL input filter read failed.
>>> ------>> Does the socket fd get closed at this point ?
>>> bio_filter_out_write: trying to write inl: 23 (length 0 blen 0)
>>> bio_filter_out_write: buffering data (NO WRITE YET)
>>> ------>> This is the close notify message that
>>SSL_set_shutdown() was trying to send - but it never gets sent
>>because the message is buffered. Maybe we need to revisit the
>>logic of bio_filter_out_write() ?
>>
>>And you're sure that the client sent a close notify alert before the
>>EOF?
>>
>>joe
>>
>
