Alan also pointed out that you are running ATS 6.x. Could you try your
test scenario on ATS 7.1.2? We've made considerable cleanup on the TLS
handshake and more debugging in the client cert verification.
Looking at your pcap file and your logs, it appears that the certs are
being exchanged. Both the server and the client certs are signed by the
same entities so setting the same CA files makes sense.
On Thu, Feb 22, 2018 at 10:17 AM, Persia Aziz <persia.a...@yahoo.com> wrote:
> ``CONFIG proxy.config.ssl.client.verify.server INT 0'' is disabling
> origin server certificate verification(i.e., when ATS initiates handshake
> to the origin server). From the configs you specified in this email, looks
> like you want the client cert to be verified by ATS. I have attached a
> screenshot of wireshark and ATS logs capturing ssl handshake where the
> client cert verification fails.
> Syeda Persia Aziz
> Software Developer
> Yahoo! Inc.
> Champaign, Illinois
>
>
> On Thursday, February 22, 2018, 9:05:27 AM CST, salil GK <
> gksa...@gmail.com> wrote:
>
>
> I wanted to have MTLS proxy. Hence we have to have client cert
> verification in server side. So proxy.config.ssl.client.CA.cert.filename
> and proxy.config.ssl.client.CA.cert.path are set
> I have verified tomcat certificate ( which is what client is using for
> connection ) using ca.pem in the server and they are good.
>
>
>
> On Feb 22, 2018 7:49 PM, "Susan Hinrichs" <shinr...@oath.com> wrote:
>
> I would assume that your CA files are not set correctly for ATS to verify
> the origin certificates sent to it. proxy.config.ssl.client.CA.
> cert.filename and proxy.config.ssl.client.CA. cert.path. If you don't
> care about having ATS verify the origin certificates, you can leave the
> proxy.config.ssl.client. verify.server set to 0.
>
> On Thu, Feb 22, 2018 at 5:46 AM, salil GK <gksa...@gmail.com> wrote:
>
> I have set client server verification to 'no'
>
> CONFIG proxy.config.ssl.client.verify .server INT 0
>
> and this time things went fie and ATS worked as forward proxy.
> So looks like client verification failure in server side only I guess ?
>
> Thanks
> ~S
>
> On 22 February 2018 at 01:14, Susan Hinrichs <shinr...@oath.com> wrote:
>
> It looks like in this exchange the client did not send a client
> certificate. But the other exchanges in the log file don't have the "
> ssl3_get_client_certificate:p eer did not return a certificate" message.
> So perhaps one test exchange had the client certificate missing.
>
> The server certificate is being selected, so I assume the server
> certificate message is being sent back to the client.
>
> On Wed, Feb 21, 2018 at 1:11 PM, Alan Carroll <solidwallofc...@oath.com>
> wrote:
>
> 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:mainEve nt] 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.co m
> <http://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_certi ficate: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:140 890C7:SSL
> routines:ssl3_get_client_certi ficate: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::sslServerHa
> ndShakeEvent, 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 <shinr...@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.a...@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.a...@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 <
> gksa...@gmail.com> wrote:
>
>
> I have assigned these variables also the same values -
>
> CONFIG proxy.config.ssl.CA.cert.filen ame STRING ca.pem
>
> CONFIG proxy.config.ssl.CA.cert.path STRING /directory/where/ca.pem
>
>
> # and
>
>
> CONFIG proxy.config.ssl.client.CA.cer t.filename STRING ca.pem
>
> CONFIG proxy.config.ssl.client.CA.cer t.path STRING
> /directory/where/ca.pem
>
> On 21 February 2018 at 22:48, Persia Aziz <persia.a...@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 <
> solidwallofc...@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.
>
>
>
>
>
>
>
>
>
>
