[Ldap] Remove redundant details from error message. Add logging to ldap auth provider (#7060)

Author: molotkov-and

ydb/core/security/ldap_auth_provider/ldap_auth_provider.cpp

@@ -6,6 +6,7 @@
 #include <queue>
 #include "ldap_auth_provider.h"
 #include "ldap_utils.h"
+#include "ldap_auth_provider_log.h"
 
 // This temporary solution
 // These lines should be declared outside ldap_compat.h
@@ -172,11 +173,12 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
 
         int result = 0;
         if (Settings.GetScheme() != NKikimrLdap::LDAPS_SCHEME && Settings.GetUseTls().GetEnable()) {
+            LDAP_LOG_D("start TLS");
             result = NKikimrLdap::StartTLS(*ld);
             if (!NKikimrLdap::IsSuccess(result)) {
+                LDAP_LOG_D("Could not start TLS. " << NKikimrLdap::ErrorToString(result));
                 TEvLdapAuthProvider::TError error {
-                    .Message = "Could not start TLS\n" + NKikimrLdap::ErrorToString(result),
-                    .Retryable = NKikimrLdap::IsRetryableError(result)
+                    .Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)
                 };
                 // The Unbind operation is not the antithesis of the Bind operation as the name implies.
                 // Close the LDAP connection, free the resources contained in the LDAP structure
@@ -185,12 +187,13 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             }
         }
 
+        LDAP_LOG_D("bind: bindDn: " << Settings.GetBindDn());
         result = NKikimrLdap::Bind(*ld, Settings.GetBindDn(), Settings.GetBindPassword());
         if (!NKikimrLdap::IsSuccess(result)) {
+            LDAP_LOG_D("Could not perform initial LDAP bind for dn " << Settings.GetBindDn() << " on server " + UrisCreator.GetUris() << ". "
+                            << NKikimrLdap::ErrorToString(result));
             TEvLdapAuthProvider::TError error {
-                .Message = "Could not perform initial LDAP bind for dn " + Settings.GetBindDn() + " on server " + UrisCreator.GetUris() + "\n"
-                            + NKikimrLdap::ErrorToString(result),
-                .Retryable = NKikimrLdap::IsRetryableError(result)
+                .Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)
             };
             // The Unbind operation is not the antithesis of the Bind operation as the name implies.
             // Close the LDAP connection, free the resources contained in the LDAP structure
@@ -210,36 +213,37 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             const TString& caCertificateFile = Settings.GetUseTls().GetCaCertFile();
             result = NKikimrLdap::SetOption(*ld, NKikimrLdap::EOption::TLS_CACERTFILE, caCertificateFile.c_str());
             if (!NKikimrLdap::IsSuccess(result)) {
+                LDAP_LOG_D("Could not set LDAP ca certificate file \"" << caCertificateFile + "\": " << NKikimrLdap::ErrorToString(result));
                 NKikimrLdap::Unbind(*ld);
                 return {{NKikimrLdap::ErrorToStatus(result),
-                        {.Message = "Could not set LDAP ca certificate file \"" + caCertificateFile + "\": " + NKikimrLdap::ErrorToString(result),
-                        .Retryable = NKikimrLdap::IsRetryableError(result)}}};
+                        {.Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
             }
         }
 
+        LDAP_LOG_D("init: scheme: " << Settings.GetScheme() << ", uris: " << UrisCreator.GetUris() << ", port: " << UrisCreator.GetConfiguredPort());
         result = NKikimrLdap::Init(ld, Settings.GetScheme(), UrisCreator.GetUris(), UrisCreator.GetConfiguredPort());
         if (!NKikimrLdap::IsSuccess(result)) {
+            LDAP_LOG_D("Could not initialize LDAP connection for uris: " << UrisCreator.GetUris() << ". " << NKikimrLdap::LdapError(*ld));
             return {{TEvLdapAuthProvider::EStatus::UNAVAILABLE,
-                    {.Message = "Could not initialize LDAP connection for uris: " + UrisCreator.GetUris() + ". " + NKikimrLdap::LdapError(*ld),
-                    .Retryable = false}}};
+                    {.Message = ERROR_MESSAGE, .Retryable = false}}};
         }
 
         result = NKikimrLdap::SetProtocolVersion(*ld);
         if (!NKikimrLdap::IsSuccess(result)) {
             NKikimrLdap::Unbind(*ld);
+            LDAP_LOG_D("Could not set LDAP protocol version: " << NKikimrLdap::ErrorToString(result));
             return {{NKikimrLdap::ErrorToStatus(result),
-                    {.Message = "Could not set LDAP protocol version: " + NKikimrLdap::ErrorToString(result),
-                    .Retryable = NKikimrLdap::IsRetryableError(result)}}};
+                    {.Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
         }
 
         if (Settings.GetScheme() == NKikimrLdap::LDAPS_SCHEME || Settings.GetUseTls().GetEnable()) {
             int requireCert = NKikimrLdap::ConvertRequireCert(Settings.GetUseTls().GetCertRequire());
             result = NKikimrLdap::SetOption(*ld, NKikimrLdap::EOption::TLS_REQUIRE_CERT, &requireCert);
             if (!NKikimrLdap::IsSuccess(result)) {
                 NKikimrLdap::Unbind(*ld);
+                LDAP_LOG_D("Could not set require certificate option: " << NKikimrLdap::ErrorToString(result));
                 return {{NKikimrLdap::ErrorToStatus(result),
-                        {.Message = "Could not set require certificate option: " + NKikimrLdap::ErrorToString(result),
-                        .Retryable = NKikimrLdap::IsRetryableError(result)}}};
+                        {.Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
             }
         }
 
@@ -249,16 +253,18 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
     TAuthenticateUserResponse AuthenticateUser(const TAuthenticateUserRequest& request) {
         char* dn = NKikimrLdap::GetDn(*request.Ld, request.Entry);
         if (dn == nullptr) {
+            LDAP_LOG_D("Could not get dn for the first entry matching " << FilterCreator.GetFilter(request.Login) << " on server " << UrisCreator.GetUris() << ". "
+                            << NKikimrLdap::LdapError(*request.Ld));
             return {{TEvLdapAuthProvider::EStatus::UNAUTHORIZED,
-                    {.Message = "Could not get dn for the first entry matching " + FilterCreator.GetFilter(request.Login) + " on server " + UrisCreator.GetUris() + "\n"
-                            + NKikimrLdap::LdapError(*request.Ld),
-                    .Retryable = false}}};
+                    {.Message = ERROR_MESSAGE, .Retryable = false}}};
         }
         TEvLdapAuthProvider::TError error;
+        LDAP_LOG_D("bind: bindDn: " << dn);
         int result = NKikimrLdap::Bind(*request.Ld, dn, request.Password);
         if (!NKikimrLdap::IsSuccess(result)) {
-            error.Message = "LDAP login failed for user " + TString(dn) + " on server " + UrisCreator.GetUris() + "\n"
-                            + NKikimrLdap::ErrorToString((result));
+            LDAP_LOG_D("LDAP login failed for user " << TString(dn) << " on server " << UrisCreator.GetUris() << ". "
+                            << NKikimrLdap::ErrorToString((result)));
+            error.Message = ERROR_MESSAGE;
             error.Retryable = NKikimrLdap::IsRetryableError(result);
         }
         NKikimrLdap::MemFree(dn);
@@ -269,6 +275,10 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
         LDAPMessage* searchMessage = nullptr;
         const TString searchFilter = FilterCreator.GetFilter(request.User);
 
+        LDAP_LOG_D("search: baseDn: " << Settings.GetBaseDn()
+                    << ", scope: " << ConvertSearchScopeToString(NKikimrLdap::EScope::SUBTREE)
+                    << ", filter: " << searchFilter
+                    << ", attributes: " << GetStringOfRequestedAttributes(request.RequestedAttributes));
         int result = NKikimrLdap::Search(request.Ld,
                                         Settings.GetBaseDn(),
                                         NKikimrLdap::EScope::SUBTREE,
@@ -278,23 +288,22 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
                                         &searchMessage);
         TSearchUserResponse response;
         if (!NKikimrLdap::IsSuccess(result)) {
+            LDAP_LOG_D("Could not search for filter " << searchFilter << " on server " << UrisCreator.GetUris() << ". "
+                                         << NKikimrLdap::ErrorToString(result));
             response.Status = NKikimrLdap::ErrorToStatus(result);
-            response.Error = {.Message = "Could not search for filter " + searchFilter + " on server " + UrisCreator.GetUris() + "\n"
-                                         + NKikimrLdap::ErrorToString(result),
-                              .Retryable = NKikimrLdap::IsRetryableError(result)};
+            response.Error = {.Message = ERROR_MESSAGE, .Retryable = NKikimrLdap::IsRetryableError(result)};
             return response;
         }
         const int countEntries = NKikimrLdap::CountEntries(request.Ld, searchMessage);
         if (countEntries != 1) {
             if (countEntries == 0) {
-                response.Error  = {.Message = "LDAP user " + request.User + " does not exist. "
-                                              "LDAP search for filter " + searchFilter + " on server " + UrisCreator.GetUris() + " return no entries",
-                                   .Retryable = false};
+                LDAP_LOG_D("LDAP user " << request.User << " does not exist. "
+                           "LDAP search for filter " << searchFilter << " on server " << UrisCreator.GetUris() << " return no entries");
             } else {
-                response.Error = {.Message = "LDAP user " + request.User + " is not unique. "
-                                             "LDAP search for filter " + searchFilter + " on server " + UrisCreator.GetUris() + " return " + countEntries + " entries",
-                                  .Retryable = false};
+                LDAP_LOG_D("LDAP user " << request.User << " is not unique. "
+                           "LDAP search for filter " << searchFilter << " on server " << UrisCreator.GetUris() << " return " << countEntries << " entries");
             }
+            response.Error = {.Message = ERROR_MESSAGE, .Retryable = false};
             response.Status = TEvLdapAuthProvider::EStatus::UNAUTHORIZED;
             NKikimrLdap::MsgFree(searchMessage);
             return response;
@@ -306,7 +315,14 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
     std::vector<TString> TryToGetGroupsUseMatchingRuleInChain(LDAP* ld, LDAPMessage* entry) const {
         static const TString matchingRuleInChain = "1.2.840.113556.1.4.1941"; // Only Active Directory supports
         TStringBuilder filter;
-        filter << "(member:" << matchingRuleInChain << ":=" << NKikimrLdap::GetDn(ld, entry) << ')';
+        char* dn = NKikimrLdap::GetDn(ld, entry);
+        filter << "(member:" << matchingRuleInChain << ":=" << dn << ')';
+        NKikimrLdap::MemFree(dn);
+        dn = nullptr;
+        LDAP_LOG_D("search: baseDn: " << Settings.GetBaseDn()
+                    << ", scope: " << ConvertSearchScopeToString(NKikimrLdap::EScope::SUBTREE)
+                    << ", filter: " << filter
+                    << ", attributes: " << GetStringOfRequestedAttributes(NKikimrLdap::noAttributes));
         LDAPMessage* searchMessage = nullptr;
         int result = NKikimrLdap::Search(ld, Settings.GetBaseDn(), NKikimrLdap::EScope::SUBTREE, filter, NKikimrLdap::noAttributes, 0, &searchMessage);
         if (!NKikimrLdap::IsSuccess(result)) {
@@ -320,13 +336,18 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
         std::vector<TString> groups;
         groups.reserve(countEntries);
         for (LDAPMessage* groupEntry = NKikimrLdap::FirstEntry(ld, searchMessage); groupEntry != nullptr; groupEntry = NKikimrLdap::NextEntry(ld, groupEntry)) {
-            groups.push_back(NKikimrLdap::GetDn(ld, groupEntry));
+            dn = NKikimrLdap::GetDn(ld, groupEntry);
+            groups.push_back(dn);
+            NKikimrLdap::MemFree(dn);
+            dn = nullptr;
         }
         NKikimrLdap::MsgFree(searchMessage);
         return groups;
     }
 
     void GetNestedGroups(LDAP* ld, std::vector<TString>* groups) {
+        LDAP_LOG_D("Try to get nested groups - tree traversal");
+
         std::unordered_set<TString> viewedGroups(groups->cbegin(), groups->cend());
         std::queue<TString> queue;
         for (const auto& group : *groups) {
@@ -344,6 +365,10 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
                 queue.pop();
             }
             filter << ')';
+            LDAP_LOG_D("search: baseDn: " << Settings.GetBaseDn()
+                    << ", scope: " << ConvertSearchScopeToString(NKikimrLdap::EScope::SUBTREE)
+                    << ", filter: " << filter
+                    << ", attributes: " << GetStringOfRequestedAttributes(RequestedAttributes));
             LDAPMessage* searchMessage = nullptr;
             int result = NKikimrLdap::Search(ld, Settings.GetBaseDn(), NKikimrLdap::EScope::SUBTREE, filter, RequestedAttributes, 0, &searchMessage);
             if (!NKikimrLdap::IsSuccess(result)) {
@@ -392,7 +417,35 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
         return {TEvLdapAuthProvider::EStatus::SUCCESS, {}};
     }
 
+    static TString ConvertSearchScopeToString(const NKikimrLdap::EScope& scope) {
+        switch (scope) {
+        case NKikimrLdap::EScope::BASE:
+            return "base";
+        case NKikimrLdap::EScope::ONE_LEVEL:
+            return "one level";
+        case NKikimrLdap::EScope::SUBTREE:
+            return "subtree";
+        }
+    }
+
+    static TString GetStringOfRequestedAttributes(char** attributes) {
+        if (!attributes) {
+            return "";
+        }
+        TStringBuilder result;
+        char* firstAttribute = *attributes;
+        if (firstAttribute) {
+            result << firstAttribute;
+            for (char* currentAttribute = *(++attributes); currentAttribute != nullptr; currentAttribute = *(++attributes)) {
+                result << ", " << currentAttribute;
+            }
+        }
+        return result;
+    }
+
 private:
+    static constexpr const char* ERROR_MESSAGE = "User is unauthorized in LDAP server";
+
     const NKikimrProto::TLdapAuthentication Settings;
     const TSearchFilterCreator FilterCreator;
     const TLdapUrisCreator UrisCreator;

ydb/core/security/ldap_auth_provider/ldap_auth_provider_log.h

@@ -0,0 +1,12 @@
+#pragma once
+
+#include <ydb/library/actors/core/log.h>
+
+#if defined LDAP_LOG_D || defined LDAP_LOG_W || defined LDAP_LOG_ERROR || defined LDAP_LOG_TRACE
+#error log macro definition clash
+#endif
+
+#define LDAP_LOG_D(stream) LOG_DEBUG_S(*TlsActivationContext, NKikimrServices::LDAP_AUTH_PROVIDER, stream)
+#define LDAP_LOG_TRACE(stream) LOG_TRACE_S(*TlsActivationContext, NKikimrServices::LDAP_AUTH_PROVIDER, stream)
+#define LDAP_LOG_ERROR(stream) LOG_ERROR_S(*TlsActivationContext, NKikimrServices::LDAP_AUTH_PROVIDER, stream)
+#define LDAP_LOG_W(stream) LOG_WARN_S(*TlsActivationContext, NKikimrServices::LDAP_AUTH_PROVIDER, stream)