trafficserver-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alan Carroll <solidwallofc...@oath.com>
Subject Re: Connection rejected for MTLS forward proxy
Date Wed, 21 Feb 2018 19:11:33 GMT
This looks like the important part of the logs (you can drop by my desk for
further detail if you want, Susan & Persia). AFAICT this covers an entire
transaction. I checked the start up messages and saw no errors, but I did
not see any mention of 'ca.pem'. Is there some typo in his configuration?
Is the ATS version too old to support client certificate verification? I'm
beginning to suspect that.

2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNextProtocolAccept.cc:129 (mainEvent)> (ssl)
[SSLNextProtocolAccept:mainEvent] event 202 netvc 0x5567d9e4aca0
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:978 (sslStartHandShake)>
(ssl) IP context is (nil) for [XXX.XXX.XXX.33:34686] ->
[XXX.XXX.XXX.XXX:8445], default context 0x5567d9bcf430
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 16 ret: 1
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:284 (set_context_cert)> (ssl)
set_context_cert ssl=0x5567d9a86d30 server=gmt-dvor-vcsc1.cisco.com
handshake_complete=0
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:336 (set_context_cert)> (ssl)
ssl_cert_callback found SSL context 0x5567d9bcf430 for requested name '
gmt-dvor-vcsc1.cisco.com'
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1459 (callHooks)> (ssl)
callHooks sslHandshakeHookState=0
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.661+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8193 ret: 1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8194 ret: -1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8194 ret: -1
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1102
(sslServerHandShakeEvent)> (ssl) trace=FALSE
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1106
(sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_WANT_READ
(2), errno=0
2018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:514 (net_read_io)> (ssl) ssl
handshake for vc 0x5567d9e4aca0, took 0.018 seconds, configured
handshake_timer: 20
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 16392 ret: 552
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x5567d9a86d30 where: 8194 ret: -1
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:2154 (SSLAccept)> (ssl.error.accept)
SSL accept returned -1, ssl_error=1, ERR_get_error=336105671
(error:140890C7:SSL routines:ssl3_get_client_certificate:peer did not
return a certificate)
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1102
(sslServerHandShakeEvent)> (ssl) trace=FALSE
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1106
(sslServerHandShakeEvent)> (ssl) SSL::140565060720448:error:140890C7:SSL
routines:ssl3_get_client_certificate:peer did not return a
certificate:s3_srvr.c:3413: peer address is XXX.XXX.XXX.33
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1106
(sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_SSL (1),
errno=0
2018-02-21T10:21:42.749+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1234
(sslServerHandShakeEvent)> (ssl)
SSLNetVConnection::sslServerHandShakeEvent, SSL_ERROR_SSL errno=0

Here's a bit more from process start, which is the only certificate I see
loaded:

2018-02-21T08:32:50.209+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1835 (ssl_store_ssl_context)> (ssl)
importing SNI names from server.pem
2018-02-21T08:32:50.209+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLUtils.cc:1649 (ssl_index_certificate)> (ssl)
mapping 'gmt-dvor-vcsc1.cisco.com' to certificate server.pem
2018-02-21T08:32:50.209+00:00 gmt-dvor-vcsc1 traffic_server[10353]:
{0x7fd7da831740} DEBUG: <SSLCertLookup.cc:380 (insert)> (ssl) indexed '
gmt-dvor-vcsc1.cisco.com' with SSL_CTX 0x5567d9bcf430 [1]


On Wed, Feb 21, 2018 at 12:22 PM, Susan Hinrichs <shinrich@oath.com> wrote:

> If you are in a test environment where you can share your wireshark pcap
> file that might also be interesting.
>
> On Wed, Feb 21, 2018 at 11:58 AM, Persia Aziz <persia.aziz@yahoo.com>
> wrote:
>
>> Do you see this EOF if you have client verification disabled?
>>
>> Syeda Persia Aziz
>> Software Developer
>> Yahoo! Inc.
>> Champaign, Illinois
>>
>>
>> On Wednesday, February 21, 2018, 11:48:40 AM CST, Persia Aziz <
>> persia.aziz@yahoo.com> wrote:
>>
>>
>>
>> Hmm interesting. From  your debug log, looks like ATS wants to read more
>> data from the buffer which it can not find. Hence, throwing an EOF.
>>
>> Syeda Persia Aziz
>> Software Developer
>> Yahoo! Inc.
>> Champaign, Illinois
>>
>>
>> On Wednesday, February 21, 2018, 11:35:11 AM CST, salil GK <
>> gksalil@gmail.com> wrote:
>>
>>
>> I have assigned these variables also the same values -
>>
>> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
>>
>> CONFIG proxy.config.ssl.CA.cert.path STRING /directory/where/ca.pem
>>
>>
>> # and
>>
>>
>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>
>> CONFIG proxy.config.ssl.client.CA.cert.path STRING
>> /directory/where/ca.pem
>>
>> On 21 February 2018 at 22:48, Persia Aziz <persia.aziz@yahoo.com> wrote:
>>
>> Hi,
>>
>> What you want is 'proxy.config.ssl.CA.cert. filename' and proxy.config.ssl.CA.cert.
>> path not the client.CA configs. I know it is a bit confusing. The
>> client.CA ones are used to verify origin server certificates. Try the
>> configs and see if that works.
>>
>> Docs for the configs:
>>
>> records.config — Apache Traffic Server 8.0.0 documentation
>> <https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html?highlight=proxy%20config%20ssl%20ca%20cert%20filename#proxy.config.ssl.CA.cert.filename>
>>
>> records.config — Apache Traffic Server 8.0.0 documentation
>>
>>
>> <https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.config.en.html?highlight=proxy%20config%20ssl%20ca%20cert%20filename#proxy.config.ssl.CA.cert.filename>
>>
>>
>>
>> - Sincerely
>> Syeda Persia Aziz
>> Software Developer
>> Yahoo! Inc.
>> Champaign, Illinois
>>
>>
>> On Wednesday, February 21, 2018, 10:41:32 AM CST, Alan Carroll <
>> solidwallofcode@oath.com> wrote:
>>
>>
>> I meant more what *units* the handshake_timer is. Looking at the code, it
>> seems to be in seconds meaning it is unlikely that is the problem (if the
>> handshake took .5s with a 20s timeout).
>>
>> I'd recommend having any configuration value at most once, although I
>> don't think it would break anything.
>>
>> Looking at the code, it appears the client cert verify callback was hit
>> (SSLUtils.cc:1687) with a failure reported by openSSL. I'd look at debug
>> messages much earlier, during process start, to see if the certs are
>> getting loaded correctly.
>>
>>
>>
>>
>

Mime
View raw message