Connection rejected for MTLS forward proxy

[gksalil]

Hello

I have setup a MTLS forward proxy with ATS. But what happens is -
connection to forward proxy is getting reset - I mean ATS is sending RST
message to the client.
I have verified the certificate that client is sending with the root CA
certificate that ATS using for verifying the client certificate. That shows
verified.

~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
/tmp/tomcat.pem: OK

But from Wireshark I can see the following sequence

client to server -> Certificate , client key exchange, certificate verify
client to server -> Change Cipher spec, Encrypted handshake message
Server to client -> [RST, ACK]

How do I fix this issue - any clues ?

from my records.conf

CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
CONFIG proxy.config.ssl.server.cert.path STRING <location where certificates
are stored>

CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
certificates are stored>

Is there any way I can make ATS log more ssl logs ?

Thanks in advance
~S





--
Sent from: http://apache-traffic-server.24303.n7.nabble.com/

[Alan Carroll]

You can enable the debug tag 'ssl' to get more data.

See
https://docs.trafficserver.apache.org/en/7.1.x/developer-guide/debugging/debug-tags.en.html?highlight=debug%20enable#other-useful-internal-debug-tags
https://docs.trafficserver.apache.org/en/7.1.x/admin-guide/files/records.config.en.html?highlight=debug%20enable#proxy.config.diags.debug.enabled

On Mon, Feb 19, 2018 at 11:12 AM, gksalil <***@gmail.com> wrote:

> Hello
>
> I have setup a MTLS forward proxy with ATS. But what happens is -
> connection to forward proxy is getting reset - I mean ATS is sending RST
> message to the client.
> I have verified the certificate that client is sending with the root CA
> certificate that ATS using for verifying the client certificate. That shows
> verified.
>
> ~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
> /tmp/tomcat.pem: OK
>
> But from Wireshark I can see the following sequence
>
> client to server -> Certificate , client key exchange, certificate verify
> client to server -> Change Cipher spec, Encrypted handshake message
> Server to client -> [RST, ACK]
>
> How do I fix this issue - any clues ?
>
> from my records.conf
>
> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
> CONFIG proxy.config.ssl.server.cert.path STRING <location where
> certificates
> are stored>
>
> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
> CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
> certificates are stored>
>
> Is there any way I can make ATS log more ssl logs ?
>
> Thanks in advance
> ~S
>
>
>
>
>
> --
> Sent from: http://apache-traffic-server.24303.n7.nabble.com/
>

[salil GK]

I can see the following lines in the ATS logs.

>>>

2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
{0x7f66f43fb740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
ssl_callback_info ssl: 0x557514e03a00 where: 8194 ret: -1

2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
{0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1102
(sslServerHandShakeEvent)> (ssl) trace=FALSE

2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
{0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1106
(sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_WANT_READ
(2), errno=0

2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
{0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:514 (net_read_io)> (ssl) ssl
handshake for vc 0x55751507fca0, took 0.583 seconds, configured
handshake_timer: 20

2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
{0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1095
(sslServerHandShakeEvent)> (ssl) SSL handshake error: EOF

<<<


Is there any indication from this information - or do we need any more
information from the system ?

could this be the issue with handshake timeout window ? just wondering.


Regs

~S

On 20 February 2018 at 01:57, Alan Carroll <***@oath.com> wrote:

> You can enable the debug tag 'ssl' to get more data.
>
> See
> https://docs.trafficserver.apache.org/en/7.1.x/developer-
> guide/debugging/debug-tags.en.html?highlight=debug%20enable#
> other-useful-internal-debug-tags
> https://docs.trafficserver.apache.org/en/7.1.x/admin-
> guide/files/records.config.en.html?highlight=debug%20enable#
> proxy.config.diags.debug.enabled
>
> On Mon, Feb 19, 2018 at 11:12 AM, gksalil <***@gmail.com> wrote:
>
>> Hello
>>
>> I have setup a MTLS forward proxy with ATS. But what happens is -
>> connection to forward proxy is getting reset - I mean ATS is sending RST
>> message to the client.
>> I have verified the certificate that client is sending with the root CA
>> certificate that ATS using for verifying the client certificate. That
>> shows
>> verified.
>>
>> ~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
>> /tmp/tomcat.pem: OK
>>
>> But from Wireshark I can see the following sequence
>>
>> client to server -> Certificate , client key exchange, certificate verify
>> client to server -> Change Cipher spec, Encrypted handshake message
>> Server to client -> [RST, ACK]
>>
>> How do I fix this issue - any clues ?
>>
>> from my records.conf
>>
>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
>> CONFIG proxy.config.ssl.server.cert.path STRING <location where
>> certificates
>> are stored>
>>
>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>> CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
>> certificates are stored>
>>
>> Is there any way I can make ATS log more ssl logs ?
>>
>> Thanks in advance
>> ~S
>>
>>
>>
>>
>>
>> --
>> Sent from: http://apache-traffic-server.24303.n7.nabble.com/
>>
>
>

[Alan Carroll]

Based on just this, I would say it is the client rejecting the certificate
provided by ATS. I'm not sure what the units of the "configured
handshake_timer" are. You should also see a lot more logging data than
just this. In particular there should be messages about ATS loading up the
certificates, both client and server.

Do you really have 'CONFIG proxy.config.ssl.client.CA.cert.filename STRING
ca.pem' twice in your records.config? Also, I don't think ATS verifies the
client certificate unless told to do so and I don't see that in your
records.config.

On Tue, Feb 20, 2018 at 5:55 PM, salil GK <***@gmail.com> wrote:

> I can see the following lines in the ATS logs.
>
> >>>
>
> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
> {0x7f66f43fb740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
> ssl_callback_info ssl: 0x557514e03a00 where: 8194 ret: -1
>
> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1102
> (sslServerHandShakeEvent)> (ssl) trace=FALSE
>
> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1106
> (sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_WANT_READ
> (2), errno=0
>
> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:514 (net_read_io)> (ssl) ssl
> handshake for vc 0x55751507fca0, took 0.583 seconds, configured
> handshake_timer: 20
>
> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1095
> (sslServerHandShakeEvent)> (ssl) SSL handshake error: EOF
>
> <<<
>
>
> Is there any indication from this information - or do we need any more
> information from the system ?
>
> could this be the issue with handshake timeout window ? just wondering.
>
>
> Regs
>
> ~S
>
> On 20 February 2018 at 01:57, Alan Carroll <***@oath.com>
> wrote:
>
>> You can enable the debug tag 'ssl' to get more data.
>>
>> See
>> https://docs.trafficserver.apache.org/en/7.1.x/developer-gui
>> de/debugging/debug-tags.en.html?highlight=debug%20enable#oth
>> er-useful-internal-debug-tags
>> https://docs.trafficserver.apache.org/en/7.1.x/admin-guide/
>> files/records.config.en.html?highlight=debug%20enable#proxy
>> .config.diags.debug.enabled
>>
>> On Mon, Feb 19, 2018 at 11:12 AM, gksalil <***@gmail.com> wrote:
>>
>>> Hello
>>>
>>> I have setup a MTLS forward proxy with ATS. But what happens is -
>>> connection to forward proxy is getting reset - I mean ATS is sending RST
>>> message to the client.
>>> I have verified the certificate that client is sending with the root CA
>>> certificate that ATS using for verifying the client certificate. That
>>> shows
>>> verified.
>>>
>>> ~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
>>> /tmp/tomcat.pem: OK
>>>
>>> But from Wireshark I can see the following sequence
>>>
>>> client to server -> Certificate , client key exchange, certificate
>>> verify
>>> client to server -> Change Cipher spec, Encrypted handshake message
>>> Server to client -> [RST, ACK]
>>>
>>> How do I fix this issue - any clues ?
>>>
>>> from my records.conf
>>>
>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
>>> CONFIG proxy.config.ssl.server.cert.path STRING <location where
>>> certificates
>>> are stored>
>>>
>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>> CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
>>> certificates are stored>
>>>
>>> Is there any way I can make ATS log more ssl logs ?
>>>
>>> Thanks in advance
>>> ~S
>>>
>>>
>>>
>>>
>>>
>>> --
>>> Sent from: http://apache-traffic-server.24303.n7.nabble.com/
>>>
>>
>>
>

[salil GK]

Do you really have 'CONFIG proxy.config.ssl.client.CA
<http://proxy.config.ssl.client.ca/>.cert.filename STRING ca.pem' twice in
your records.config? Also, I don't think ATS verifies the client
certificate unless told to do so and I don't see that in your
records.config. - Yes I can see the entry twice in the records.conf file -
should I keep only one entry ?

I'm not sure what the units of the "configured handshake_timer" are. = it
is 20

CONFIG proxy.config.ssl.handshake_timeout_in INT 20

CONFIG proxy.config.ssl.client.certification_level INT 2

CONFIG proxy.config.ssl.client.verify.server INT 0

also I have the parameters CONFIG proxy.config.ssl.client.cert.path STRING
and CONFIG proxy.config.ssl.client.CA.cert.path configured - is it really
required - or will it create any issue ?

Thanks
Salil


On 21 February 2018 at 06:30, Alan Carroll <***@oath.com> wrote:

> Based on just this, I would say it is the client rejecting the certificate
> provided by ATS. I'm not sure what the units of the "configured
> handshake_timer" are. You should also see a lot more logging data than
> just this. In particular there should be messages about ATS loading up the
> certificates, both client and server.
>
> Do you really have 'CONFIG proxy.config.ssl.client.CA.cert.filename
> STRING ca.pem' twice in your records.config? Also, I don't think ATS
> verifies the client certificate unless told to do so and I don't see that
> in your records.config.
>
> On Tue, Feb 20, 2018 at 5:55 PM, salil GK <***@gmail.com> wrote:
>
>> I can see the following lines in the ATS logs.
>>
>> >>>
>>
>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>> {0x7f66f43fb740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
>> ssl_callback_info ssl: 0x557514e03a00 where: 8194 ret: -1
>>
>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1102
>> (sslServerHandShakeEvent)> (ssl) trace=FALSE
>>
>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1106
>> (sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_WANT_READ
>> (2), errno=0
>>
>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:514 (net_read_io)> (ssl) ssl
>> handshake for vc 0x55751507fca0, took 0.583 seconds, configured
>> handshake_timer: 20
>>
>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1095
>> (sslServerHandShakeEvent)> (ssl) SSL handshake error: EOF
>>
>> <<<
>>
>>
>> Is there any indication from this information - or do we need any more
>> information from the system ?
>>
>> could this be the issue with handshake timeout window ? just wondering.
>>
>>
>> Regs
>>
>> ~S
>>
>> On 20 February 2018 at 01:57, Alan Carroll <***@oath.com>
>> wrote:
>>
>>> You can enable the debug tag 'ssl' to get more data.
>>>
>>> See
>>> https://docs.trafficserver.apache.org/en/7.1.x/developer-gui
>>> de/debugging/debug-tags.en.html?highlight=debug%20enable#oth
>>> er-useful-internal-debug-tags
>>> https://docs.trafficserver.apache.org/en/7.1.x/admin-guide/f
>>> iles/records.config.en.html?highlight=debug%20enable#proxy.
>>> config.diags.debug.enabled
>>>
>>> On Mon, Feb 19, 2018 at 11:12 AM, gksalil <***@gmail.com> wrote:
>>>
>>>> Hello
>>>>
>>>> I have setup a MTLS forward proxy with ATS. But what happens is -
>>>> connection to forward proxy is getting reset - I mean ATS is sending RST
>>>> message to the client.
>>>> I have verified the certificate that client is sending with the root CA
>>>> certificate that ATS using for verifying the client certificate. That
>>>> shows
>>>> verified.
>>>>
>>>> ~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
>>>> /tmp/tomcat.pem: OK
>>>>
>>>> But from Wireshark I can see the following sequence
>>>>
>>>> client to server -> Certificate , client key exchange, certificate
>>>> verify
>>>> client to server -> Change Cipher spec, Encrypted handshake message
>>>> Server to client -> [RST, ACK]
>>>>
>>>> How do I fix this issue - any clues ?
>>>>
>>>> from my records.conf
>>>>
>>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>>> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
>>>> CONFIG proxy.config.ssl.server.cert.path STRING <location where
>>>> certificates
>>>> are stored>
>>>>
>>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>>> CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
>>>> certificates are stored>
>>>>
>>>> Is there any way I can make ATS log more ssl logs ?
>>>>
>>>> Thanks in advance
>>>> ~S
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> Sent from: http://apache-traffic-server.24303.n7.nabble.com/
>>>>
>>>
>>>
>>
>

[salil GK]

*-- added some formatting for clarity .. sorry for repeat post !*

*Q. Do you really have 'CONFIG proxy.config.ssl.client.CA
<http://proxy.config.ssl.client.ca/>.**cert.filename STRING ca.pem' twice
in your records.config? Also, I don't think ATS verifies the client
certificate unless told to do so and I don't see that in your
records.config. -*
*A. Yes I can see the entry twice in the records.conf file - should I keep
only one entry ?*

*Q. I'm not sure what the units of the "configured handshake_timer" are. *=
*A. it is 20*

CONFIG proxy.config.ssl.handshake_timeout_in INT 20

CONFIG proxy.config.ssl.client.certification_level INT 2

CONFIG proxy.config.ssl.client.verify.server INT 0

also I have the parameters
CONFIG proxy.config.ssl.client.cert.path STRING and
CONFIG proxy.config.ssl.client.CA.cert.path configured - is it really
required - or will it create any issue ?

Thanks
Salil

On 21 February 2018 at 06:54, salil GK <***@gmail.com> wrote:

> Do you really have 'CONFIG proxy.config.ssl.client.CA
> <http://proxy.config.ssl.client.ca/>.cert.filename STRING ca.pem' twice
> in your records.config? Also, I don't think ATS verifies the client
> certificate unless told to do so and I don't see that in your
> records.config. - Yes I can see the entry twice in the records.conf file -
> should I keep only one entry ?
>
> I'm not sure what the units of the "configured handshake_timer" are. = it
> is 20
>
> CONFIG proxy.config.ssl.handshake_timeout_in INT 20
>
> CONFIG proxy.config.ssl.client.certification_level INT 2
>
> CONFIG proxy.config.ssl.client.verify.server INT 0
>
> also I have the parameters CONFIG proxy.config.ssl.client.cert.path
> STRING and CONFIG proxy.config.ssl.client.CA.cert.path configured - is
> it really required - or will it create any issue ?
>
> Thanks
> Salil
>
>
> On 21 February 2018 at 06:30, Alan Carroll <***@oath.com>
> wrote:
>
>> Based on just this, I would say it is the client rejecting the
>> certificate provided by ATS. I'm not sure what the units of the "configured
>> handshake_timer" are. You should also see a lot more logging data than
>> just this. In particular there should be messages about ATS loading up the
>> certificates, both client and server.
>>
>> Do you really have 'CONFIG proxy.config.ssl.client.CA.cert.filename
>> STRING ca.pem' twice in your records.config? Also, I don't think ATS
>> verifies the client certificate unless told to do so and I don't see that
>> in your records.config.
>>
>> On Tue, Feb 20, 2018 at 5:55 PM, salil GK <***@gmail.com> wrote:
>>
>>> I can see the following lines in the ATS logs.
>>>
>>> >>>
>>>
>>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>>> {0x7f66f43fb740} DEBUG: <SSLUtils.cc:1687 (ssl_callback_info)> (ssl)
>>> ssl_callback_info ssl: 0x557514e03a00 where: 8194 ret: -1
>>>
>>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1102
>>> (sslServerHandShakeEvent)> (ssl) trace=FALSE
>>>
>>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1106
>>> (sslServerHandShakeEvent)> (ssl) SSL handshake error: SSL_ERROR_WANT_READ
>>> (2), errno=0
>>>
>>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:514 (net_read_io)> (ssl) ssl
>>> handshake for vc 0x55751507fca0, took 0.583 seconds, configured
>>> handshake_timer: 20
>>>
>>> 2018-02-20T10:46:49.496+00:00 gmt-dvor-vcsc1 traffic_server[7634]:
>>> {0x7f66f43fb740} DEBUG: <SSLNetVConnection.cc:1095
>>> (sslServerHandShakeEvent)> (ssl) SSL handshake error: EOF
>>>
>>> <<<
>>>
>>>
>>> Is there any indication from this information - or do we need any more
>>> information from the system ?
>>>
>>> could this be the issue with handshake timeout window ? just wondering.
>>>
>>>
>>> Regs
>>>
>>> ~S
>>>
>>> On 20 February 2018 at 01:57, Alan Carroll <***@oath.com>
>>> wrote:
>>>
>>>> You can enable the debug tag 'ssl' to get more data.
>>>>
>>>> See
>>>> https://docs.trafficserver.apache.org/en/7.1.x/developer-gui
>>>> de/debugging/debug-tags.en.html?highlight=debug%20enable#oth
>>>> er-useful-internal-debug-tags
>>>> https://docs.trafficserver.apache.org/en/7.1.x/admin-guide/f
>>>> iles/records.config.en.html?highlight=debug%20enable#proxy.c
>>>> onfig.diags.debug.enabled
>>>>
>>>> On Mon, Feb 19, 2018 at 11:12 AM, gksalil <***@gmail.com> wrote:
>>>>
>>>>> Hello
>>>>>
>>>>> I have setup a MTLS forward proxy with ATS. But what happens is -
>>>>> connection to forward proxy is getting reset - I mean ATS is sending
>>>>> RST
>>>>> message to the client.
>>>>> I have verified the certificate that client is sending with the root CA
>>>>> certificate that ATS using for verifying the client certificate. That
>>>>> shows
>>>>> verified.
>>>>>
>>>>> ~ # openssl verify -CAfile /tmp/ca.pem /tmp/tomcat.pem
>>>>> /tmp/tomcat.pem: OK
>>>>>
>>>>> But from Wireshark I can see the following sequence
>>>>>
>>>>> client to server -> Certificate , client key exchange, certificate
>>>>> verify
>>>>> client to server -> Change Cipher spec, Encrypted handshake message
>>>>> Server to client -> [RST, ACK]
>>>>>
>>>>> How do I fix this issue - any clues ?
>>>>>
>>>>> from my records.conf
>>>>>
>>>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>>>> CONFIG proxy.config.ssl.CA.cert.filename STRING ca.pem
>>>>> CONFIG proxy.config.ssl.server.cert.path STRING <location where
>>>>> certificates
>>>>> are stored>
>>>>>
>>>>> CONFIG proxy.config.ssl.client.CA.cert.filename STRING ca.pem
>>>>> CONFIG proxy.config.ssl.client.CA.cert.path STRING <location where
>>>>> certificates are stored>
>>>>>
>>>>> Is there any way I can make ATS log more ssl logs ?
>>>>>
>>>>> Thanks in advance
>>>>> ~S
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Sent from: http://apache-traffic-server.24303.n7.nabble.com/
>>>>>
>>>>
>>>>
>>>
>>
>

[Alan Carroll]

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.

[Persia Aziz]

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


|
|
| |
records.config — Apache Traffic Server 8.0.0 documentation


|

|

|




- SincerelySyeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 10:41:32 AM CST, Alan Carroll <***@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.

[salil GK]

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 <***@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 <
> ***@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.
>
>
>

[Persia Aziz]

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 DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 11:35:11 AM CST, salil GK <***@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 <***@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


|
|
| |
records.config — Apache Traffic Server 8.0.0 documentation


|

|

|




- SincerelySyeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 10:41:32 AM CST, Alan Carroll <***@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.

[Persia Aziz]

Do you see this EOF if you have client verification disabled?
Syeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 11:48:40 AM CST, 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 DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 11:35:11 AM CST, salil GK <***@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 <***@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


|
|
| |
records.config — Apache Traffic Server 8.0.0 documentation


|

|

|




- SincerelySyeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 10:41:32 AM CST, Alan Carroll <***@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.

[Susan Hinrichs]

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 <***@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 <
> ***@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 <
> ***@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 <***@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 <
> ***@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.
>
>
>
>

[Alan Carroll]

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 <***@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 <***@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 <
>> ***@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 <
>> ***@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 <***@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 <
>> ***@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.
>>
>>
>>
>>
>

[Susan Hinrichs]

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:peer 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 <***@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: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 <***@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 <***@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 <
>>> ***@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 <
>>> ***@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 <***@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 <
>>> ***@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.
>>>
>>>
>>>
>>>
>>
>

[salil GK]

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 <***@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:peer 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 <***@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: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 <***@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 <***@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 <
>>>> ***@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 <
>>>> ***@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 <***@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 <
>>>> ***@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.
>>>>
>>>>
>>>>
>>>>
>>>
>>
>

[Susan Hinrichs]

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 <***@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 <***@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:peer 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 <***@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: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 <***@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 <***@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 <
>>>>> ***@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 <
>>>>> ***@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 <***@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 <
>>>>> ***@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.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>

[salil GK]

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" <***@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 <***@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 <***@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:peer 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 <***@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: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 <***@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 <***@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 <
>>>>> ***@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 <
>>>>> ***@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 <***@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 <
>>>>> ***@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.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>

[Persia Aziz]

``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 DeveloperYahoo! Inc.Champaign, Illinois

On Thursday, February 22, 2018, 9:05:27 AM CST, salil GK <***@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 setI 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" <***@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 <***@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 <***@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 <***@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 0x5567d9e4aca02018-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 0x5567d9bcf4302018-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: 12018-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: 12018-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 handshake_complete=02018-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=02018-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: 12018-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: 12018-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: 12018-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: 12018-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: 12018-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: 12018-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: -12018-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: -12018-02-21T10:21:42.681+00:00 gmt-dvor-vcsc1 traffic_server[10353]: {0x7fd7da831740} DEBUG: <SSLNetVConnection.cc:1102 (sslServerHandShakeEvent)> (ssl) trace=FALSE2018-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=02018-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: 202018-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: 5522018-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: -12018-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=FALSE2018-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.332018-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=02018-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.pem2018-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 <***@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 <***@yahoo.com> wrote:

Do you see this EOF if you have client verification disabled?
Syeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 11:48:40 AM CST, 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 DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 11:35:11 AM CST, salil GK <***@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 <***@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


|
|
| |
records.config — Apache Traffic Server 8.0.0 documentation


|

|

|




- SincerelySyeda Persia Aziz
Software DeveloperYahoo! Inc.Champaign, Illinois

On Wednesday, February 21, 2018, 10:41:32 AM CST, Alan Carroll <***@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.

[Susan Hinrichs]

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 <***@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 <
> ***@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" <***@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 <***@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 <***@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 <***@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 <***@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 <***@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 <
> ***@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 <
> ***@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 <***@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 <
> ***@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.
>
>
>
>
>
>
>
>
>
>

[salil GK]

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 <***@oath.com> 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 <***@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 <
>> ***@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" <***@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 <***@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 <***@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 <***@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 <***@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 <***@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 <
>> ***@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 <
>> ***@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 <***@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 <
>> ***@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.
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>

[Susan Hinrichs]

You cannot try 7.1.x in your test environment?

On Thu, Feb 22, 2018 at 11:00 AM, salil GK <***@gmail.com> wrote:

> 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 <***@oath.com> 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 <***@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 <
>>> ***@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" <***@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 <***@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 <***@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 <***@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 <***@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 <***@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 <
>>> ***@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 <
>>> ***@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 <***@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 <
>>> ***@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.
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>
>