I'm running apache 2.2.14 with mod_ssl using OpenSSL 0.98m-beta1. When
renegotiating a client session, I get an error from apache: "Re-negotiation
handshake failed: Not accepted by client" and a fatal "unexpected_message"
alert in OpenSSL s_client. Below you will find log output for the renegotiation
failure and log output for a successful legacy renegotiation against OpenSSL
0.98k.
Here's the log output of Apache:
...
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(487): [client
72.247.216.129] Changed client verification type will force renegotiation
[Wed Jan 20 23:35:15 2010] [info] [client 72.247.216.129] Requesting
connection re-negotiation
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(724): [client
72.247.216.129] Performing full renegotiation: complete handshake protocol
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1875): OpenSSL:
Handshake: start
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSL renegotiate ciphers
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write hello request A
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 flush data
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write hello request C
[Wed Jan 20 23:35:15 2010] [info] [client 72.247.216.129] Awaiting
re-negotiation handshake
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1875): OpenSSL:
Handshake: start
[Wed Jan 20 23:35:15 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: before accept initialization
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
5/5 bytes from BIO#8425590 [mem: 8464e08] (BIO dump follows)
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0000: 17 03
01 ... |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1834): | 0005 -
<SPACES/NULS>
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
32/32 bytes from BIO#8425590 [mem: 8464e0d] (BIO dump follows)
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0000: 27 a1
4c ce 82 d0 d6 ab-a1 38 ce 43 a1 ac 1a 06 '.L......8.C.... |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0010: 97 8f
54 7e 5a 84 7c 1b-e8 51 63 54 ec a1 4a 3a ..T~Z.|..QcT..J: |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
5/5 bytes from BIO#8425590 [mem: 8464e08] (BIO dump follows)
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0000: 17 03
01 ... |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1834): | 0005 -
<SPACES/NULS>
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
32/32 bytes from BIO#8425590 [mem: 8464e0d] (BIO dump follows)
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0000: 37 8a
a5 a3 4e 3e 06 7c-56 8e 5b a0 68 5d 23 09 7...N>.|V.[.h]#. |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1830): | 0010: d6 c2
44 be 51 ed 30 dd-ef 66 76 92 d3 45 2f 0e ..D.Q.0..fv..E/. |
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_kernel.c(1893): OpenSSL:
Write: SSLv3 read client hello B
[Wed Jan 20 23:35:16 2010] [debug] ssl_engine_kernel.c(1912): OpenSSL:
Exit: error in SSLv3 read client hello B
[Wed Jan 20 23:35:16 2010] [error] [client 72.247.216.129]
Re-negotiation handshake failed: Not accepted by client!?
Here's the debug output for openssl s_client:
...
<<< TLS 1.0 Handshake [length 0004], HelloRequest
00 00 00 00
SSL_connect:SSL renegotiate ciphers
write to 0x80bff90 [0x80cafd0] (133 bytes => 133 (0x85))
0000 - 16 03 01 00 80 67 f7 7d-4d b0 92 07 f1 c9 13 68
.....g.}M......h
0010 - 45 f4 0a e2 c6 d5 80 a1-b7 19 42 c9 36 40 da 16
e............@..
0020 - fa f8 89 72 55 a3 67 20-46 0d 7d ab 50 fa 69 6c ...rU.g
F.}.P.il
0030 - 62 49 b2 0b 5a f1 1a 13-88 96 99 0f e6 64 27 d8
bI..Z........d'.
0040 - fe 74 76 60 4b 4a 7f d3-2a 01 1c a0 ca 70 28 af
.tv`KJ..*....p(.
0050 - 55 fe 2f f0 e5 53 3b 27-fe 0a 4a d0 33 6c fc 94
U./..S;'..J.3l..
0060 - e3 3a cd 78 e7 2b 03 6d-5f 22 af b7 8d 84 e1 a1
.:.x.+.m_"......
0070 - f2 cc 6a 15 7f 79 24 7d-66 ea 14 73 8e c2 62 82
..j..y$}f..s..b.
0080 - 09 50 bb 95 b1 .P...
>>> TLS 1.0 Handshake [length 006a], ClientHello
01 00 00 66 03 01 4b 57 93 34 6b ff 1f 08 2c 3a
44 0f 0f 55 23 bb 29 46 f9 72 ad ce e8 10 48 ae
09 95 41 17 9d bd 00 00 28 00 39 00 38 00 35 00
16 00 13 00 0a 00 33 00 32 00 2f 00 07 00 05 00
04 00 15 00 12 00 09 00 14 00 11 00 08 00 06 00
03 01 00 00 15 ff 01 00 0d 0c 8b 88 76 37 f9 7b
6e 06 ce d2 d4 cc 00 23 00 00
SSL_connect:SSLv3 write client hello A
read from 0x80bff90 [0x80c67c0] (5 bytes => 5 (0x5))
0000 - 15 03 01 ...
0005 - <SPACES/NULS>
read from 0x80bff90 [0x80c67c5] (32 bytes => 32 (0x20))
0000 - 57 a7 1e 25 a1 bc 9d 7f-cd a9 4c 7f e4 7d fb 37
W..%......L..}.7
0010 - 8e 1e 27 3c e8 58 55 3e-de 60 01 5c 1a b1 df 85
..'<.XU>.`.\....
<<< TLS 1.0 Alert [length 0002], fatal unexpected_message
02 0a
SSL3 alert read:fatal:unexpected_message
SSL_connect:failed in SSLv3 read server hello A
398:error:140943F2:SSL routines:SSL3_READ_BYTES:sslv3 alert unexpected
message:s3_pkt.c:1102:SSL alert number 10
398:error:140940E5:SSL routines:SSL3_READ_BYTES:ssl handshake
failure:s3_pkt.c:1006:
Using OpenSSL 0.98k, I get the following apache log output for a successful
renegotiation:
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(487): [client
72.247.216.129] Changed client verification type will force renegotiation
[Wed Jan 20 23:57:36 2010] [info] [client 72.247.216.129] Requesting
connection re-negotiation
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(724): [client
72.247.216.129] Performing full renegotiation: complete handshake protocol
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1875): OpenSSL:
Handshake: start
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSL renegotiate ciphers
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write hello request A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 flush data
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write hello request C
[Wed Jan 20 23:57:36 2010] [info] [client 72.247.216.129] Awaiting
re-negotiation handshake
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1875): OpenSSL:
Handshake: start
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: before accept initialization
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
5/5 bytes from BIO#845d5b8 [mem: 8464c48] (BIO dump follows)
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0000: 16 03
01 00 80 ..... |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1858): OpenSSL: read
128/128 bytes from BIO#845d5b8 [mem: 8464c4d] (BIO dump follows)
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1791):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0000: c2 fd
7a e4 b1 e4 75 82-7d d9 6d 23 56 b4 8b 52 ..z...u.}.m#V..R |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0010: 8c 10
11 8a e3 4d 7f d4-47 5f c9 14 a5 1d ff db .....M..G_...... |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0020: 26 e1
03 85 c2 09 cd 58-c1 64 09 32 ea df a2 ca &......X.d.2.... |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0030: c8 78
4b 3c 6e 8a 62 67-00 00 e3 fb 48 f2 48 08 .xK<n.bg....H.H. |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0040: dd 5d
c2 f1 99 9f 6d 62-49 fd de 11 1a d6 31 c1 .]....mbI.....1. |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0050: bd 6c
6e 0d 70 13 7d 57-18 c9 8f 7b 37 57 3c 4f .ln.p.}W...{7W<O |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0060: 8d 9d
40 45 ca 0f ca 04-46 e3 30 25 61 be c8 1e ....@e....f.0%a
<mailto:....@e....f.0%25a> ... |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1830): | 0070: 82 93
6a 8f c1 b2 53 ab-dd ba 92 96 b7 79 db 61 ..j...S......y.a |
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_io.c(1836):
+-------------------------------------------------------------------------+
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 read client hello A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write server hello A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write certificate A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1263): [client
72.247.216.129] handing out temporary 1024 bit DH key
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write key exchange A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 write certificate request A
[Wed Jan 20 23:57:36 2010] [debug] ssl_engine_kernel.c(1883): OpenSSL:
Loop: SSLv3 flush data
Here's the openssl s_client debug output for a successful legacy renegotiation:
<<< TLS 1.0 Handshake [length 0004], HelloRequest
00 00 00 00
SSL_connect:SSL renegotiate ciphers
write to 0x80bff90 [0x80cafd0] (133 bytes => 133 (0x85))
0000 - 16 03 01 00 80 c2 fd 7a-e4 b1 e4 75 82 7d d9 6d
.......z...u.}.m
0010 - 23 56 b4 8b 52 8c 10 11-8a e3 4d 7f d4 47 5f c9
#V..R.....M..G_.
0020 - 14 a5 1d ff db 26 e1 03-85 c2 09 cd 58 c1 64 09
.....&......X.d.
0030 - 32 ea df a2 ca c8 78 4b-3c 6e 8a 62 67 00 00 e3
2.....xK<n.bg...
0040 - fb 48 f2 48 08 dd 5d c2-f1 99 9f 6d 62 49 fd de
.H.H..]....mbI..
0050 - 11 1a d6 31 c1 bd 6c 6e-0d 70 13 7d 57 18 c9 8f
...1..ln.p.}W...
0060 - 7b 37 57 3c 4f 8d 9d 40-45 ca 0f ca 04 46 e3 30
{7W<o...@e....f.0
0070 - 25 61 be c8 1e 82 93 6a-8f c1 b2 53 ab dd ba 92
%a.....j...S....
0080 - 96 b7 79 db 61 ..y.a
>>> TLS 1.0 Handshake [length 006a], ClientHello
01 00 00 66 03 01 4b 57 98 70 e4 7e 84 8b 92 0d
18 21 7b 06 a1 e9 10 50 9d 96 4c 6a ef 7d a7 03
34 57 4d 9a 02 b0 00 00 28 00 39 00 38 00 35 00
16 00 13 00 0a 00 33 00 32 00 2f 00 07 00 05 00
04 00 15 00 12 00 09 00 14 00 11 00 08 00 06 00
03 01 00 00 15 ff 01 00 0d 0c 0d 79 f9 56 04 a3
b2 86 42 f4 70 9d 00 23 00 00
SSL_connect:SSLv3 write client hello A
read from 0x80bff90 [0x80c67c0] (5 bytes => 5 (0x5))
0000 - 16 03 01 00 60 ....`
read from 0x80bff90 [0x80c67c5] (96 bytes => 96 (0x60))
0000 - d1 8e 4a ac ad fa 0d 55-0b 4c 67 d5 38 cf b6 3c
..J....U.Lg.8..<
0010 - 78 bc e0 9a e5 13 71 76-ea b8 72 33 76 ac 44 5d
x.....qv..r3v.D]
0020 - 4d bf 5a de ca 01 fd b8-98 67 d1 96 5f 53 eb f4
M.Z......g.._S..
0030 - 0a 87 67 07 3b aa 52 be-99 c7 e4 4d fe 44 08 53
..g.;.R....M.D.S
0040 - 8f bb 1a 41 06 32 60 0f-2e be fc 32 8c df 86 84
...A.2`....2....
0050 - dd 28 09 9c 03 7f 54 a8-c2 cf 0b e7 17 79 47 18
.(....T......yG.
<<< TLS 1.0 Handshake [length 004a], ServerHello
02 00 00 46 03 01 4b 57 98 70 83 42 83 e5 1d 6a
52 3c e6 19 cc aa 9c 0d de db 38 62 2b fa 1c 56
9a d0 b2 c3 81 e5 20 bc 14 a6 77 47 fd db c5 68
fd 10 d6 25 f4 f4 d2 0e 1b a6 d5 f5 bd 5f 96 a8
ba 30 d0 ef 8d aa d2 00 39 00
SSL_connect:SSLv3 read server hello A
read from 0x80bff90 [0x80c67c0] (5 bytes => 5 (0x5))
0000 - 16 03 01 08 30 ....0
read from 0x80bff90 [0x80c67c5] (2096 bytes => 2096 (0x830))
0000 - 81 eb 89 5b 94 51 75 be-b8 7b dc a8 db 51 22 f7
...[.Qu..{...Q".
...
<<< TLS 1.0 Handshake [length 080e], Certificate
0b 00 08 0a 00 08 07 00 03 e9 30 82 03 e5 30 82
...
depth=1 /C=US/ST=California/L=San Mateo/O=Akamai Technologies/OU=Ghost
CA 2
verify error:num=19:self signed certificate in certificate chain
verify return:0
SSL_connect:SSLv3 read server certificate A
read from 0x80bff90 [0x80c67c0] (5 bytes => 5 (0x5))
0000 - 16 03 01 01 b0 .....
read from 0x80bff90 [0x80c67c5] (432 bytes => 432 (0x1B0))
0000 - 53 5f 53 b9 2c 90 3a 3d-b9 5d 8d 48 ef 5c 74 cc
S_S.,.:=.].H.\t.
...
<<< TLS 1.0 Handshake [length 018d], ServerKeyExchange
0c 00 01 89 00 80 d6 7d e4 40 cb bb dc 19 36 d6
SSL_connect:SSLv3 read server key exchange A
read from 0x80bff90 [0x80c67c0] (5 bytes => 5 (0x5))
0000 - 16 03 01 40 ...@
0005 - <SPACES/NULS>
read from 0x80bff90 [0x80c67c5] (16416 bytes => 16416 (0x4020))
0000 - 4f a3 13 46 9d 17 b8 2a-3b bc 19 2f 3f 73 1a 7b
O..F...*;../?s.{
...
If it is not a certificate problem, my guess is it's the new renegotiation code
in 0.98m-beta1.
Thanks,
Fred Shotton
