It would be a big task to change the ATS to 7.x in my server and do the test. And this particular issue actually happened in our production environment.
Thanks ~S On 22 February 2018 at 22:16, Susan Hinrichs <[email protected]> wrote: > 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 <[email protected]> > 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 < >> [email protected]> 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" <[email protected]> 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 <[email protected]> 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 <[email protected]> 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 <[email protected]> >> 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 <[email protected]> >> 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 <[email protected]> >> 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 < >> [email protected]> 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 < >> [email protected]> 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 <[email protected]> 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 < >> [email protected]> 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. >> >> >> >> >> >> >> >> >> >> >
