Re-negotiation handshake failed: Not accepted by client with OpenSSL 0.98m-beta1
Shotton, Fred
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.........B.6@..
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... |
[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
Dr. Stephen Henson
> 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:
>
Are you using OpenSSL 0.9.8m-beta1 for both Apache and s_client?
What happens if you include the -legacy_renegotiation flag in s_client?
Steve.
--
Dr Stephen N. Henson. OpenSSL project core developer.
Commercial tech support now available see: http://www.openssl.org
______________________________________________________________________
OpenSSL Project http://www.openssl.org
User Support Mailing List openss...@openssl.org
Automated List Manager majo...@openssl.org
Dr. Stephen Henson
> 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:
>
Does the s_client output indicate that secure renegotiation is supported?
What Apache configuration are you using to produce renegotiation?
Can you also include the complete outut of s_client with the -state switch and
no -debug switch.
Michael Stone
> 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
Fred,
In order to help you, I'm probably going to need to see a full packet
capture and a list of the actual command-lines used to run the debugging
commands available. I ask for these data because I see the following
suspicious item in the OpenSSL ChangeLog:
*) Add option SSL_OP_LEGACY_SERVER_CONNECT which will allow clients to
connect (but not renegotiate) with servers which do not support RI.
Until RI is more widely deployed this option is enabled by default.
[Steve Henson]
at http://www.openssl.org/news/changelog.html
Flagging this change is just blind guess on my part based on my reading
of the debug logs but it would certainly be consistent with the observed
data if your secure-renegotiation attempt were failing because one of
the initial ClientHello, ServerHello, or both is missing the appropriate
signalling.
Finally, have you talked to anyone on the OpenSSL or Apache mailing
lists about your test plan?
Regards,
Michael
P.S. - In case it helps, I think the output from commands similar to
tcpdump -i eth0 -w tls.pcap -s 0 port 443
and
script -t tls.log
# ... your test script
is about what I'm looking for.