Skip to content

Commit

Permalink
Update logging during augmentation
Browse files Browse the repository at this point in the history
  • Loading branch information
@Yvand
Yvand committed Mar 8, 2019
1 parent 2fecf6e commit dbb4017
Showing 1 changed file with 27 additions and 19 deletions.
46 changes: 27 additions & 19 deletions LDAPCP/LDAPCP.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1169,7 +1169,7 @@ protected virtual List<SPClaim> GetGroupsFromActiveDirectory(LDAPConnection ldap
path = de.Path;
de.Dispose();
}
string loggingMessage = $"[{ProviderInternalName}] Getting AD groups of user {currentContext.IncomingEntity.Value} in \"{path}\" with AuthenticationType \"{ldapConnection.AuthenticationTypes}\" and authenticating ";
string loggingMessage = $"[{ProviderInternalName}] Augmentation of user {currentContext.IncomingEntity.Value} in AD server \"{path}\" with AuthenticationType \"{ldapConnection.AuthenticationTypes}\" and authenticating ";
loggingMessage += ldapConnection.UserServerDirectoryEntry ? "as process identity" : $"with credentials \"{ldapConnection.Username}\"";
ClaimsProviderLogging.Log(loggingMessage, TraceSeverity.Verbose, EventSeverity.Information, TraceCategory.Augmentation);
using (new SPMonitoredScope(loggingMessage, 2000))
Expand All @@ -1190,7 +1190,7 @@ protected virtual List<SPClaim> GetGroupsFromActiveDirectory(LDAPConnection ldap

try
{
using (new SPMonitoredScope($"[{ProviderInternalName}] Getting AD Principal for user {currentContext.IncomingEntity.Value} from Active Directory server \"{path}\"", 2000))
using (new SPMonitoredScope($"[{ProviderInternalName}] Get AD Principal of user {currentContext.IncomingEntity.Value} from AD server \"{path}\"", 2000))
{
// Constructor of PrincipalContext does connect to LDAP server and may throw an exception if it fails, so it should be in try/catch
if (ldapConnection.UserServerDirectoryEntry)
Expand Down Expand Up @@ -1226,20 +1226,20 @@ protected virtual List<SPClaim> GetGroupsFromActiveDirectory(LDAPConnection ldap
}

IEnumerable<Principal> adGroups;
using (new SPMonitoredScope($"[{ProviderInternalName}] Getting AD groups for {currentContext.IncomingEntity.Value} from Active Directory server \"{path}\"", 2000))
using (new SPMonitoredScope($"[{ProviderInternalName}] Get group membership of \"{currentContext.IncomingEntity.Value}\" from AD server \"{path}\"", 2000))
{
adGroups = adUser.GetAuthorizationGroups().Where(x => !String.IsNullOrEmpty(x.DistinguishedName));
}

using (new SPMonitoredScope($"[{ProviderInternalName}] Processing AD groups for {currentContext.IncomingEntity.Value} from Active Directory server \"{path}\"", 2000))
using (new SPMonitoredScope($"[{ProviderInternalName}] Process {adGroups.Count()} AD groups returned for \"{currentContext.IncomingEntity.Value}\" by AD server \"{path}\". Each group will trigger a LDAP query to get its DistinguishedName", 2000))
{
// https://docs.microsoft.com/en-us/dotnet/api/system.directoryservices.accountmanagement.userprincipal.getauthorizationgroups?view=netframework-4.7.1#System_DirectoryServices_AccountManagement_UserPrincipal_GetAuthorizationGroups
// UserPrincipal.GetAuthorizationGroups() only returns groups that are security groups; distribution groups are not returned.
// UserPrincipal.GetAuthorizationGroups() searches all groups recursively and returns the groups in which the user is a member. The returned set may also include additional groups that system would consider the user a member of for authorization purposes.
foreach (Principal adGroup in adGroups)
{
string groupDomainName, groupDomainFqdn;
// Call to getter of property Principal.DistinguishedName triggers a LDAP bind and may slow down the whole augmentation process
// Calling property Principal.DistinguishedName triggers a LDAP bind behind the scene, which may impact performance if there are many groups
OperationContext.GetDomainInformation(adGroup.DistinguishedName, out groupDomainName, out groupDomainFqdn);
string claimValue = adGroup.Name;
if (!String.IsNullOrEmpty(groupCTConfig.ClaimValuePrefix) && groupCTConfig.ClaimValuePrefix.Contains(ClaimsProviderConstants.LDAPCPCONFIG_TOKENDOMAINNAME))
Expand All @@ -1250,10 +1250,6 @@ protected virtual List<SPClaim> GetGroupsFromActiveDirectory(LDAPConnection ldap
groups.Add(claim);
}
}

stopWatch.Stop();
ClaimsProviderLogging.Log($"[{ProviderInternalName}] Got {groups.Count} group(s) for {currentContext.IncomingEntity.Value} in {stopWatch.ElapsedMilliseconds.ToString()} ms from Active Directory server \"{path}\".",
TraceSeverity.Medium, EventSeverity.Information, TraceCategory.Augmentation);
}
catch (PrincipalOperationException ex)
{
Expand All @@ -1273,6 +1269,10 @@ protected virtual List<SPClaim> GetGroupsFromActiveDirectory(LDAPConnection ldap
{
if (principalContext != null) principalContext.Dispose();
if (adUser != null) adUser.Dispose();

stopWatch.Stop();
ClaimsProviderLogging.Log($"[{ProviderInternalName}] Got and processed {groups.Count} group(s) for {currentContext.IncomingEntity.Value} in {stopWatch.ElapsedMilliseconds.ToString()} ms from Active Directory server \"{path}\".",
TraceSeverity.Medium, EventSeverity.Information, TraceCategory.Augmentation);
}
}
return groups;
Expand All @@ -1293,16 +1293,16 @@ protected virtual List<SPClaim> GetGroupsFromLDAPDirectory(LDAPConnection ldapCo
SetLDAPConnection(currentContext, ldapConnection);
#pragma warning restore CS0618 // Type or member is obsolete
string ldapFilter = string.Format("(&(ObjectClass={0}) ({1}={2}){3})", IdentityClaimTypeConfig.LDAPClass, IdentityClaimTypeConfig.LDAPAttribute, currentContext.IncomingEntity.Value, IdentityClaimTypeConfig.AdditionalLDAPFilter);
string loggMessage = $"[{ProviderInternalName}] Getting LDAP groups of user {currentContext.IncomingEntity.Value} in \"{ldapConnection.Directory.Path}\" with AuthenticationType \"{ldapConnection.Directory.AuthenticationType}\" and authenticating ";
string loggMessage = $"[{ProviderInternalName}] Augmentation of user {currentContext.IncomingEntity.Value} in LDAP server \"{ldapConnection.Directory.Path}\" with AuthenticationType \"{ldapConnection.Directory.AuthenticationType}\" and authenticating ";
loggMessage += String.IsNullOrWhiteSpace(ldapConnection.Directory.Username) ? "as process identity. " : $"with credentials \"{ldapConnection.Directory.Username}\". ";
loggMessage += $"LDAP filter used: \"{ldapFilter}\"";
ClaimsProviderLogging.Log(loggMessage, TraceSeverity.Verbose, EventSeverity.Information, TraceCategory.Augmentation);
using (new SPMonitoredScope(loggMessage, 2000))
{
Stopwatch stopWatch = new Stopwatch();
stopWatch.Start();
try
{
Stopwatch stopWatch = new Stopwatch();
stopWatch.Start();
using (DirectorySearcher searcher = new DirectorySearcher(ldapConnection.Directory))
{
searcher.ClientTimeout = new TimeSpan(0, 0, this.CurrentConfiguration.LDAPQueryTimeout); // Set the timeout of the query
Expand All @@ -1317,14 +1317,18 @@ protected virtual List<SPClaim> GetGroupsFromLDAPDirectory(LDAPConnection ldapCo
}

SearchResult result;
using (new SPMonitoredScope($"[{ProviderInternalName}] Doing LDAP query to get group(s) for {currentContext.IncomingEntity.Value} from LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\"", 2000))
using (new SPMonitoredScope($"[{ProviderInternalName}] Get group membership of \"{currentContext.IncomingEntity.Value}\" from LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\"", 2000))
{
result = searcher.FindOne();
}

if (result == null) return groups; // user was not found in this directory
if (result == null)
{
stopWatch.Stop();
return groups; // User was not found in this LDAP server
}

using (new SPMonitoredScope($"[{ProviderInternalName}] Processing LDAP groups for {currentContext.IncomingEntity.Value}, returned from LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\".", 2000))
using (new SPMonitoredScope($"[{ProviderInternalName}] Process LDAP groups of \"{currentContext.IncomingEntity.Value}\" returned by LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\".", 2000))
{
foreach (ClaimTypeConfig groupCTConfig in groupsCTConfig)
{
Expand Down Expand Up @@ -1382,18 +1386,22 @@ protected virtual List<SPClaim> GetGroupsFromLDAPDirectory(LDAPConnection ldapCo
}
}
}
stopWatch.Stop();
}
ClaimsProviderLogging.Log($"[{ProviderInternalName}] Got {groups.Count} group(s) for {currentContext.IncomingEntity.Value} in {stopWatch.ElapsedMilliseconds.ToString()} ms from LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\".",
TraceSeverity.Medium, EventSeverity.Information, TraceCategory.Augmentation);
}
catch (Exception ex)
{
ClaimsProviderLogging.LogException(ProviderInternalName, $"while getting LDAP groups of {currentContext.IncomingEntity.Value} in {ldapConnection.Path} with LDAP filter \"{ldapFilter}\".", TraceCategory.Augmentation, ex);
}
finally
{
if (ldapConnection.Directory != null) ldapConnection.Directory.Dispose();
if (ldapConnection.Directory != null)
{
ldapConnection.Directory.Dispose();
}
stopWatch.Stop();
ClaimsProviderLogging.Log($"[{ProviderInternalName}] Got {groups.Count} group(s) for {currentContext.IncomingEntity.Value} in {stopWatch.ElapsedMilliseconds.ToString()} ms from LDAP server \"{ldapConnection.Directory.Path}\" with LDAP filter \"{ldapFilter}\".",
TraceSeverity.Medium, EventSeverity.Information, TraceCategory.Augmentation);

}
}
return groups;
Expand Down

0 comments on commit dbb4017

Please sign in to comment.