How to Debug Client Certificate ESP Authentication issues
Scope
This article highlights some of the important steps to establish a successful Edge Security Pack (ESP) client certificate connection. This should prove useful in troubleshooting your client certificate connection. Comments are included in red.
This process involves:
- The LoadMaster requesting a valid client certificate from the user.
- Validating the SSL Certificate against your installed Intermediate Cert.
- Authenticating the extracted user against Active Directory.
- Requesting a Kerberos ticket from Active Directory for the extracted user.
Note: This article does not explain how to configure client certificates with Kerberos. To configure client certificates with Kerberos, refer to the documents below. This article will also be continually updated.
To collect ESP debug data, you must first enable verbose ESP logging.
To enable verbose ESP logging, navigate to: Logging Options > System Log Files > Debug Options > Enable SSOMGR Debug Traces.
To view the log data, navigate to: Logging Options > System Log Files > System Message File.
For firmware older than 7.2.41, navigate to: Logging Options > Extended Log Files > SSO MGR Audit Logs > SSO MGR > View
1. Client Certificate Received
During the SSL handshake the LoadMaster requests a client certificate from the client.
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: >>>
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: cert is in DER-format.
Feb 14 09:36:18 lb100 ssomgr: #684# ++++ 0x6d98d0 <-- malloc(1417)
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: der=0x6d98d0 sizeof(*der)=1416
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: peer=0x6d9170 sizeof(*peer)=184
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: der=0x6d9e57 der0=0x6d98d0 szder=1416
2. Extract Client Certificate Details
Information such as SAN names, domain names, and common names are extracted from the client certificate. This information is used to authenticate against the active directory (AD).
Feb 14 09:36:18 lb100 ssomgr: #684# ---- 0x6d98d0 --> free()
Feb 14 09:36:18 lb100 ssomgr: #684# get_x509_peer: <<<
Feb 14 09:36:18 lb100 ssomgr: #684# get_SAN_email: >>>
Feb 14 09:36:18 lb100 ssomgr: #684# get_SAN_email: altname=||
Feb 14 09:36:18 lb100 ssomgr: #684# get_SAN_email: <<<
Feb 14 09:36:18 lb100 ssomgr: #684# get_subject_cn: >>>
Feb 14 09:36:18 lb100 ssomgr: #684# >>>get_domain
Feb 14 09:36:18 lb100 ssomgr: #684# >>>get_domain_from_user
Feb 14 09:36:18 lb100 ssomgr: #684# get_domain_from_user: no domain to extract from []
Feb 14 09:36:18 lb100 ssomgr: #684# get_domain: client domain not provided, proceed with default domain [STREET.COM] for VS[23]
Feb 14 09:36:18 lb100 ssomgr: #684# get_sso_conf: domain=|STREET.COM| refcount=2
Feb 14 09:36:18 lb100 ssomgr: #684# >>> release_sso_conf(0x6b52b0), calling function(get_subject_cn)
Feb 14 09:36:18 lb100 ssomgr: #684# release_sso_conf: domain=|STREET.COM| refcount=1
Feb 14 09:36:18 lb100 ssomgr: #684# <<< release_sso_conf
Feb 14 09:36:18 lb100 ssomgr: #684# get_subject_cn: Attempting to determine Common Name (CN) from Subject |CN=darren@street.com,OU=administrator@street.com,O=KEMP,L=Munster,ST=Limerick,C=IE|
Feb 14 09:36:18 lb100 ssomgr: #684# get_subject_cn:
3. Allow Fallback to check Common Name
Depending on how your client certificate is created, the username may exist in the SAN name or common name. If Allow Fallback to check Common Name is checked, the LoadMaster checks the common name. Otherwise the user may not be extracted.
In the above example, the user exists in the common name.
Got a Common Name from Client Cert [darren@street.com]
Feb 14 09:36:18 lb100 ssomgr: #684# get_subject_cn: <<< cn[darren@street.com]
Feb 14 09:36:18 lb100 ssomgr: #684# auth_cert: e->user=|darren@street.com|
Feb 14 09:36:18 lb100 ssomgr: #684# auth_cert: e->kcd.data=[184]|<I>C=IE,S=Limerick,L=Munster,O=administrator@street.com,OU=darren@street.com,CN=darren@street.com,<S>C=IE,S=Limerick,L=Munster,O=KEMP,OU=administrator@street.com,CN=darren@street.com,|
Feb 14 09:36:18 lb100 ssomgr: #684# >>>get_domain
Feb 14 09:36:18 lb100 ssomgr: #684# >>>get_domain_from_user
Feb 14 09:36:18 lb100 ssomgr: #684# get_domain_from_user: extracted domain [street.com] from [darren@street.com]
Feb 14 09:36:18 lb100 ssomgr: #684# get_domain: client domain provided [street.com] and matches the configured default [STREET.COM] for VS[23]
Feb 14 09:36:18 lb100 ssomgr: #684# get_sso_conf: domain=|STREET.COM| refcount=2
Feb 14 09:36:18 lb100 ssomgr: #684# normalize_user: user:|darren@street.com|; nd1:|@street.com|; nd2:|(null)|; logonfmt:1 phase:1
4. Normalization
Regardless of your "Logon Format", the LoadMaster will use the UPN name in your Client Certificate to carry out an LDAP Bind.
Feb 14 09:36:18 lb100 ssomgr: #684# normalize_user: Logon Format : Principalname
Feb 14 09:36:18 lb100 ssomgr: #684# >>> release_sso_conf(0x6b52b0), calling function(normalize_user)
Feb 14 09:36:18 lb100 ssomgr: #684# release_sso_conf: domain=|STREET.COM| refcount=1
Feb 14 09:36:18 lb100 ssomgr: #684# <<< release_sso_conf
Feb 14 09:36:18 lb100 ssomgr: #684# normalize_user: normalized user: |darren@street.com|
Feb 14 09:36:18 lb100 ssomgr: >>find_user_by_user(darren@street.com,10.0.30.40)
Feb 14 09:36:18 lb100 ssomgr: >>find_user_by_user(): ts: 1518600920 [age=58] type: 4 user: darren@street.com samAccName: host: 10.0.30.40 domain: STREET.COM cookie: failed_auths: 0 lockout: 0 tout: type:900[1]
User Found on LDAP
Feb 14 09:36:18 lb100 ssomgr: #684# auth_cert: user found: up->lockout=0; up->domain=|STREET.COM| up->host=|10.0.30.40| up->user=|darren@street.com| up->pass=|nopass|
Feb 14 09:36:18 lb100 ssomgr: #684# user found
Feb 14 09:36:18 lb100 ssomgr: #684# handle_user_entry: <<< id: 929 operation: 0 type: 4 curlmode: 0 host: 10.0.30.40 user: darren@street.com dusername: domain: STREET.COM ispost: 0 sendform: 0 cookie: set_cookie: 0 pubpriv: 0 steering_group: 0 status: 0 rsaddr: 10.110.30.5 vid: 23 kcd.len: 0 kcd.data[(nil)]: [(null)...]
Feb 14 09:36:18 lb100 ssomgr: #684# 0000 00000000 00000000 ........
Feb 14 09:36:18 lb100 ssomgr: #684# handle_user_entry: >>> id: 930 operation: 2 type: 0 curlmode: 0 host: 10.0.30.40 user: darren@street.com dusername: domain: STREET.COM ispost: 0 sendform: 0 cookie: set_cookie: 0 pubpriv: 0 steering_group: 0 status: 0 rsaddr: 10.110.30.5 vid: 23 kcd.len: 9 kcd.data[0x69e800]: [Negotiate=Limerick,L=Munster,O=administrator@street.com,OU=darren@street.com,CN=darren@street.com,<S>C=IE,S=Limerick,L=Munster,O=KEMP,OU=administrator@street.com,CN=darren@street.com,...]
Information such as permitted groups and steering groups are also verified after the LDAP bind. In the example below, there is a group called agroup of which darren is a member.
Sep 18 13:23:22 lb100 ssomgr: #60482# do_sso_cert_check: ldap_search_ext(ld,dc=street,dc=com,,(userprincipalname=darren@street.com)): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_count_messages(): 1
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_count_entries(): 1
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_result(): rc=100
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_first_message(): msg=0x716190 msgtype=100
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: samAccountName=|darren|
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: userPrincipalName=|darren@street.com|
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_result(): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_count_messages(): 1
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_count_entries(): 0
Sep 18 13:23:22 lb100 ssomgr: #60482# get_attributes: ldap_result(): rc=115
Sep 18 13:23:22 lb100 ssomgr: #60482# do_sso_cert_check: Asi=[165][166]|<I>C=IE,S=Munster,L=Limerick,O=KEMP,OU=support,CN=*.street.com,E=admin@street.com,<S>C=IE,S=Munster,L=Limerick,O=KEMP,OU=Support,CN=*.street.com,E=darren@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# ci=[79]|C=IE,S=Munster,L=Limerick,O=KEMP,OU=support,CN=*.street.com,E=admin@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# cs=[80]|C=IE,S=Munster,L=Limerick,O=KEMP,OU=Support,CN=*.street.com,E=darren@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# ident=[79]|C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=support,S=Munster,E=admin@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# ident=[80]|C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=Support,S=Munster,E=darren@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# aSI=[165]|<I>C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=support,S=Munster,E=admin@street.com,<S>C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=Support,S=Munster,E=darren@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# do_sso_cert_check: Asi=[165][166]|<I>C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=support,S=Munster,E=admin@street.com,<S>C=IE,CN=*.street.com,L=Limerick,O=KEMP,OU=Support,S=Munster,E=darren@street.com,|
Sep 18 13:23:22 lb100 ssomgr: #60482# >>>group_processing: started group processing for do_sso_cert_check
Sep 18 13:23:22 lb100 ssomgr: #60482# >>> ldap_need_steering_groups: vid=13
Sep 18 13:23:22 lb100 ssomgr: #60482# group_processing: chk_sids = 0, chk_allowed_groups = 1, chk_steering_groups = 0
Sep 18 13:23:22 lb100 ssomgr: #60482# domain=|street.com| baseDN=|dc=street,dc=com|
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupFilter: >> basedn=|dc=street,dc=com| vid=|13|
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: >> basedn=|dc=street,dc=com| groupname=|agroup|
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: filter=|(&(objectClass=group)(cn=agroup))|
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: ldap_search_ext():rc=0(unknown),basedn=dc=street,dc=com,scope=2,filter=(&(objectClass=group)(cn=agroup)),attrs=dn,attrsonly=0,msgid=4
Sep 18 13:23:22 lb100 ssomgr: #60479# getGroupDN: ldap_result(): rc2=100 (search-entry)
Sep 18 13:23:22 lb100 ssomgr: #60479# getGroupDN: groupdn=|CN=agroup,CN=Users,DC=street,DC=com|
Sep 18 13:23:22 lb100 ssomgr: #60479# getGroupDN: ldap_result(): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60479# getGroupDN: <<< - rc=0
Sep 18 13:23:22 lb100 ssomgr: #60479# getGroupFilter: << vid=|13| groupfilter=|(memberOf=CN=agroup,CN=Users,DC=street,DC=com)|
Sep 18 13:23:22 lb100 ssomgr: #60479# do_check_group: attrs[0]=|userprincipalname| filter=|(&(samAccountType=805306368)(memberOf=CN=agroup,CN=Users,DC=street,DC=com)(userprincipalname=darren@street.com))| tout:5
Sep 18 13:23:22 lb100 ssomgr: #60479# do_check_group: ldap_search_ext(): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: ldap_result(): rc2=100 (search-entry)
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: groupdn=|CN=agroup,CN=Users,DC=street,DC=com|
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: ldap_result(): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupDN: <<< - rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# getGroupFilter: << vid=|13| groupfilter=|(memberOf=CN=agroup,CN=Users,DC=street,DC=com)|
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: attrs[0]=|userprincipalname|
LDAP Group Filter
filter=|(&(samAccountType=805306368)(memberOf=CN=agroup,CN=Users,DC=street,DC=com)(userprincipalname=darren@street.com))| tout:5
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: ldap_search_ext(): rc=0
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: ldap_result(): rc2=101 (search-result)
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: ldap_msg: msgid=5 type=100 (search-entry)
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: userPrincipalName=|darren@street.com|
Sep 18 13:23:22 lb100 ssomgr: #60482# do_check_group: user in group(s)
Sep 18 13:23:22 lb100 ssomgr: #60482# group_processing: Granted access - user in approved groups for VS [13]
Sep 18 13:23:22 lb100 ssomgr: #60482# <<<group_processing: completed group processing for do_sso_cert_check, groupOK=1
LDAP Response Codes
https://ldap.com/ldap-result-code-reference/
Error Couldn't start TLS
Couldn't start tls: 52, Server is unavailable [00000000: LdapErr: DSID-0C091269, comment: Error initializing SSL/TLS, data 0, v3839]
If you see the above error message, you nmust ensure that your ADis configured to handle TLS requests.
5. Kerberos
Once a successful front end connection is complete, the LoadMaster attempts to retrieve a Kerberos ticket for your back end server.
Reverse DNS Lookup
Depending on what destination server is chosen, the LoadMaster must perform a reverse DNS lookup on this server. Depending on the hostname returned from DNS, this name is used to form your Service Principal Name (SPN).
In the below example, the IP is 10.110.30.5 and the host name is exchange2013.street.com, so SPN becomes http/exchange2013.street.com@STREET.COM
Feb 14 09:36:21 lb100 ssomgr: #32301# baseUserName: basename=|darren|
Feb 14 09:36:21 lb100 ssomgr: #32301# >>> kcd_get_user_ticket
Feb 14 09:36:21 lb100 ssomgr: #32301# >>>resolve_destination_address: Attempt to resolve destination [10.110.30.5][2]
Feb 14 09:36:21 lb100 ssomgr: #32301# <<<resolve_destination_address: Resolved destination host name [exchange2013.street.com]
Feb 14 09:36:21 lb100 ssomgr: #32301# kcd_get_user_ticket: user=[darren@street.com] [basename=[darren]
Feb 14 09:36:21 lb100 ssomgr: #32301# kcd_get_user_ticket: Destination name=[http/exchange2013.street.com@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32301# kcd_get_user_ticket: kcd_ticket:0x7fde4f1f2ef0 [65536/65536]
Feb 14 09:36:21 lb100 ssomgr: #32301# >>> get_impersonator_cred_handle
Feb 14 09:36:21 lb100 ssomgr: #32301# >>> get_impersonator_cred_handle - handle=0x7fde300008c0
6. Contact Kerberos Server
In the example below, the LoadMaster attempts to retrieve a ticket on behalf of user Darren, using delegated name kempkcd, configured in your server side configuration.
Feb 14 09:36:21 lb100 ssomgr: #32301# kcd_get_user_ticket: Get a ticket on behalf of user darren
Feb 14 09:36:21 lb100 ssomgr: #32290# kcd_get_user_ticket: Credentials aquired
Feb 14 09:36:21 lb100 ssomgr: #32290# init_accept_sec_context(): Target name: [kempkcd@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32290# Target mech: [{ 1 3 6 1 5 5 2 }]
Feb 14 09:36:21 lb100 ssomgr: #32290# init_accept_sec_context(): Source name: [darren@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32290# init_accept_sec_context(): Source mech: [{ 1 2 840 113554 1 2 2 }]
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac: Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac:logon-info Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac:client-info Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac:upn-dns-info Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac:server-checksum Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Attribute urn:mspac:privsvr-checksum Authenticated Complete
Feb 14 09:36:21 lb100 ssomgr: #32290# Proxy name: [kempkcd@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32290# Target name: [http/exchange2013.street.com@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32290# Delegated name: [darren@STREET.COM]
Feb 14 09:36:21 lb100 ssomgr: #32290# Delegated mech: [{ 1 2 840 113554 1 2 2 }]
Feb 14 09:36:21 lb100 ssomgr: #32290# encode_ticket: sz=2060 ticket=0x7fde4f255ef0 len=65536 buf_sz=65536
7. Successfully Retrieved Kerberos Ticket
If successful, you will see the Negotiate authorization header with a long random string of characters.
Feb 14 09:36:21 lb100 ssomgr: #32290# <<< kcd_get_user_ticket - ret=0
Feb 14 09:36:21 lb100 ssomgr: #32290# kcd_reauth_thread: status and cookie are both OK
Feb 14 09:36:21 lb100 ssomgr: #32290# kcd_reauth_thread: up->kcd_data[Negotiate YIIF+wYJKoZIhvcSAQICAQBuggXqMIIF5qADAgEFoQMCAQ6iBwMFAAAAAACjggT+YYIE+jCCBPagAwIBBaEMGwpTVFJFRVQuQ09NoiowKKADAgEBoSEwHxsEaHR0cBsXZXhjaGFuZ2UyMDEzLnN0cmVldC5jb22jggSzMIIEr6ADAgESoQMCAQSiggShBIIEnag04R/bTzdmz+ZEjyNgYx9hm9gESS2aY3OwbxvT85NrqguM31y9HHBLRDehk/mfX13S0rEwtwyHT9EWwD5g7zNVpoeczaHN+waU74GjS7Th+WYrLHCNbaQK5v269n/L+s1E1M53QCARCSsoTYvfZDZDbLQNFNFDVBWR2JDE0s0iljupa+KBWampg//BPV0xLiUzQdKGYtScpec4buOS2eJmiaI7fcoj+OlnMnL47m2L/5IxjNC8QM5U1GdcLuSUSPdsnIdrinKjHsfXc8msyiXyWIbe2SnVxs18tPVVul0KGnzxAdB8X17RbKb7ViDVs3IZckF7azNqhwg3C0tBJlAys5ySQ3rXSLHBeF46Wyn8bLiGkLyVMQ6bRmb8fLPnEshakPrtuR+YuaZZ/uMEaeP7hIBQ2JkppX4xquAszoTwXOREgTjqL6BOdHGM9UKvevRQxa9x9Rod7kW532kUTc+ayB5S8DhW2FT79zvRhKmKXk8n2dsGLl2csiBC+bl9uMdCykFrWz+nl2DzHS8L+6tM0JjqxetmqNdQvuCMSLaBS1Upg2ZhR/2vNh641h7NzZSBNPXcfzionp1nRkk2jPYSmq45d+/c6/Jabied5PwvUYXur91ijjJ8+cnTmWZtQjN6I4EDW3Td/g9UnG/PzEzWivQN03lAjQwRa20K+HM4w4kOADw7DcEDErSF2RZsKjHh2cTvf4/sZlC1TY38l5BNHBLWu7bwnvChkjJAkxaC/A4
Feb 14 09:36:21 lb100 ssomgr: #32290# >>> release_sso_conf(0x6b52b0), calling function(kcd_reauth_thread)
Kerberos Errors
If you receive the following error, ensure that the delegated account credentials are correct, or if the account is locked out.
Feb 14 09:36 lb100 ssomgr: #57508# kinit_domain: Getting credentials for kempkcd@STREET.COM Feb 14 09:36 lb100 ssomgr: kinit_domain: Could not initialize credentials: error -1765328360
If you receive the following error:
Feb 14 09:36 lb100 ssomgr: #24663# gss_init_sec_context: Unspecified GSS failure. Minor code may provide more information Feb 14 09:36 lb100 ssomgr: #24663# gss_init_sec_context: KDC can't fulfill requested option
Ensure that you have your delegated account configured correctly. Ensure that you add the server name under the Delegated tab, and not the name of your SharePoint site, for example.
8. Wireshark
If you think that your configuration is correct, perform a TCP trace and filter on your Kerberos Server IP address.
To perform a TCP trace, navigate to:
Logging Options --> System Log files --> Debug Options --> TCP Dump. Select Interface = All and IP Address = <Domain Controller IP>.
When you open the Wireshark PCAP file, filter using the word Kerberos.
Pay attention to the following information
AS-REQ: This is where the client is authenticated and a ticket-granting ticket (TGT) is retrieved. In this case, your client is the Kemp delegated user.
TGS_REQ: Present your TGT to Kerberos where it is verified against its database.
KCD Error Codes and possible causes
For more information on Kerberos Constrained Delegation (KCD) error codes and possible causes, visit: Kerberos Errors in Network Captures
If you receive no errors in Wireshark, then a reboot of the LoadMaster may be required.
Related KBs