How to troubleshoot LDAP issues in Windows Active Directory
Applies to
- ONTAP 9
Description
For more detailed and up-to-date information about Active Directory LDAP and clustered Data ONTAP, please see TR-4073: Secure Unified Authentication.
When using LDAP in Cluster-Mode, the mhost process 'secd
' is leveraged. This process is responsible for user authentication (name mapping). Issues occuring in name mapping get logged to the secd logs, located in the /mroot/etc/mlog
file.
By default, name mapping failures do not get logged in the secd logs unless specified:
::*> diag secd trace set -node node-01 -module-names name-mapping -trace-all YES
Trace spec set successfully.
::*> diag secd trace show -node node-01
Trace Spec
---------------------------------------
TraceAll: Tracing all RPCs
Modules: NameMapping
This behavior was the same in Data ONTAP 7-Mode, where options cifs.trace_login
has to be enabled to view trace match failures in the logs.
When a name mapping failure occurs, the following is seen:
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] |------------------------------------------------------------------------------
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | TRACE MATCH |
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | RPC secd_rpc_map_name succeeded and is being dumped because of a tracing |
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | match on: |
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | All |
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | RPC recevied at Thu Sep 15 16:55:38 2011 |
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] |------------------------------------------------------------------------------'
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.032] debug: SecD RPC Server received RPC from MGMT. RPC 351: secd_rpc_map_name { in secd_prog_1() at server/secd_rpc_server.cpp:806 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.103] debug: Setting thread context. VServerId = 6, Protocol = NONE, lifId = 0 { in setThreadContext() at utils/secd_thread_data_manager.cpp:172 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.121] debug: secd_rpc_map_name_1_svc called with vserverid = 6 { in secd_rpc_map_name_1_svc() at name_mapping/secd_rpc_map_name.cpp:50 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.168] debug: Attempting to map name ldap using the cluster mapping store { in getAppropriateWindowsToUnixMapping() at name_mapping/secd_name_mapping.cpp:385 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.207] debug: IDS_FROM_USER_NAME ldapInfoType requested.
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] { in getLdapInfoFromName() at authorization/secd_ldap_unix_authorization.cpp:552 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.239] debug: Looking for LDAP (NIS & Name Mapping) cache (key: "") in vserver 6 { in getConnectionCache() at connection_manager/secd_connection_cache.cpp:450 } 000000ad.0000150a 001db95a Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.255] debug: Looking for a connection to LDAP (NIS & Name Mapping) { in getConnection() at connection_manager/secd_connection_manager.cpp:547 } 000000ad.0000150b 001db95a Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.268] debug: Acquiring a new LDAP (NIS & Name Mapping) connection; favoring cache { in getBestConnection() at connection_manager/secd_connection_manager.cpp:716 } Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.282] debug: Did not find an available connection in the cache { in getBestCachedConnection() at connection_manager/secd_connection_cache.cpp:224 } 000000ad.0000150d 001db95a Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.304] debug: Reserving a new LDAP (NIS & Name Mapping) server from discovery { in getBestConnection() at connection_manager/secd_connection_manager.cpp:728 } 000000ad.0000150e 001db95a Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.324] debug: Created service key: 00000006..LDAP_NIS_AND_NAME_MAPPING { in makeServiceKey() at server_discovery/secd_service_list.cpp:150 } Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.356] debug: Discovery returned 10.61.70.5 (10.61.70.5) { in getBestConnection() at connection_manager/secd_connection_manager.cpp:743 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.000.377] debug: Connecting to LDAP (NIS & Name Mapping) server 10.61.70.5 { in addStartConnectionJournal() at connection_manager/secd_connection_manager.cpp:462 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.002.652] debug: Successfully authenticated over LDAP with 10.61.70.5 { in connect<LdapConnectionState>() at connection_manager/secd_connection.cpp:971 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.002.688] debug: Connected to new LDAP (NIS & Name Mapping) service on 10.61.70.5 { in makeConnectionAttempt() at connection_manager/secd_connection_manager.cpp:846 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.002.929] debug: Searching LDAP for the "uidNumber, gidNumber" attribute(s) within base "CN=users,DC=domain,DC=com" (scope: -1) using filter: (&(objectClass=User)(sAMAccountName=ldap)) { in searchLdap() at utils/secd_ldap_utils.cpp:200 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.352] ERR : 1057 in searchLdap() at utils/secd_ldap_utils.cpp:215
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.386] ERR : searchLdap: LDAP Error: (80): 'Internal (implementation specific) error':
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.399] ERR : 1057 in getLdapInfoFromName() at authorization/secd_ldap_unix_authorization.cpp:652
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.465] debug: Closing service handle; reporting status 1 { in ~SecdConnection() at ../bedrock/obj/x86_64/secd/../../../export/common/headers/include/secd/secd_connection.h:106 }
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.488] ERR : 1057 in getIdsFromUserName() at authorization/secd_ldap_unix_authorization.cpp:139
Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.505] warn : Failed to get an ID for name ldap using UNIX authorization source LDAP, Error: 1057; ignoring; will try next source { in handleNameAuthResult() at authorization/secd_unix_authorization.cpp:68 } 000000ad.0000151a 001db95a Thu Sep 15 2011 16:55:38 -04:00 [kern_secd:info:2402] | [000.003.575] debug: SecD RPC Server sending reply to RPC 351: secd_rpc_map_name { in secdSendRpcResponse() at server/secd_rpc_server.cpp:1093 }
The name map traces convey the following:
- The LDAP name mapping failure and the user being attempted
- LDAP used to map users
- Base DN used for searches
- Attributes requested during the failure
- Filter used
- LDAP server contacted and if it connected properly
- If the LDAP connection was cached or not
- The vserver ID requested