auditlog: fix logging for unsuccessful ldap logins (ydb-platform#11438)

Move audit logging of login operations from schemeshard to grpc service auth (`AuthService`).
Update web-login service login to utilize `AuthService.Login`.
Establish `AuthService` as the sole gateway and single audit point for all login operations.

KIKIMR-22173

Author: ijon

ydb/core/grpc_services/audit_logins.cpp

@@ -0,0 +1,59 @@
+#include "defs.h"
+
+#include <ydb/core/util/address_classifier.h>
+#include <ydb/core/audit/audit_log.h>
+
+#include <ydb/public/api/protos/ydb_auth.pb.h>
+
+#include "base/base.h"
+#include "audit_logins.h"
+
+namespace NKikimr {
+namespace NGRpcService {
+
+void AuditLogLogin(IAuditCtx* ctx, const TString& database, const Ydb::Auth::LoginRequest& request, const Ydb::Auth::LoginResponse& response, const TString& errorDetails)
+{
+    static const TString GrpcLoginComponentName = "grpc-login";
+    static const TString LoginOperationName = "LOGIN";
+
+    //NOTE: EmptyValue couldn't be an empty string as AUDIT_PART() skips parts with an empty values
+    static const TString EmptyValue = "{none}";
+
+    auto peerName = NKikimr::NAddressClassifier::ExtractAddress(ctx->GetPeerName());
+
+    auto status = response.operation().status();
+    TString detailed_status;
+    TString reason;
+    if (status != Ydb::StatusIds::SUCCESS) {
+        detailed_status = Ydb::StatusIds::StatusCode_Name(status);
+        if (response.operation().issues_size() > 0) {
+            reason = response.operation().issues(0).message();
+        }
+        if (errorDetails) {
+            if (!reason.empty()) {
+                reason += ": ";
+            }
+            reason += errorDetails;
+        }
+    }
+
+    // NOTE: audit field set here must be in sync with ydb/core/security/login_page.cpp, AuditLogWebUILogout()
+    AUDIT_LOG(
+        AUDIT_PART("component", GrpcLoginComponentName)
+        AUDIT_PART("remote_address", (!peerName.empty() ? peerName : EmptyValue))
+        AUDIT_PART("database", (!database.empty() ? database : EmptyValue))
+        AUDIT_PART("operation", LoginOperationName)
+        AUDIT_PART("status", (status == Ydb::StatusIds::SUCCESS ? TString("SUCCESS") : TString("ERROR")))
+        AUDIT_PART("detailed_status", detailed_status, status != Ydb::StatusIds::SUCCESS)
+        AUDIT_PART("reason", reason, status != Ydb::StatusIds::SUCCESS)
+
+        // Login
+        AUDIT_PART("login_user", (!request.user().empty() ? request.user() : EmptyValue))
+
+        //TODO: (?) it is possible to show masked version of the resulting token here
+    );
+}
+
+}
+}
+

ydb/core/grpc_services/audit_logins.h

@@ -0,0 +1,18 @@
+#pragma once
+#include "defs.h"
+
+namespace Ydb::Auth {
+
+class LoginRequest;
+class LoginResponse;
+
+}
+
+namespace NKikimr::NGRpcService {
+
+class IAuditCtx;
+
+// logins log
+void AuditLogLogin(IAuditCtx* ctx, const TString& database, const Ydb::Auth::LoginRequest& request, const Ydb::Auth::LoginResponse& response, const TString& errorDetails);
+
+} // namespace NKikimr::NGRpcService

ydb/core/grpc_services/rpc_login.cpp

@@ -1,5 +1,6 @@
 #include "grpc_request_proxy.h"
 #include "service_auth.h"
+#include "audit_logins.h"
 
 #include "rpc_request_base.h"
 
@@ -28,8 +29,6 @@ class TLoginRPC : public TRpcRequestActor<TLoginRPC, TEvLoginRequest, true> {
 public:
     using TRpcRequestActor::TRpcRequestActor;
 
-    THolder<TEvSchemeShard::TEvLoginResult> Result;
-    Ydb::StatusIds_StatusCode Status = Ydb::StatusIds::SUCCESS;
     TDuration Timeout = TDuration::MilliSeconds(60000);
     TActorId PipeClient;
 
@@ -50,8 +49,7 @@ class TLoginRPC : public TRpcRequestActor<TLoginRPC, TEvLoginRequest, true> {
     }
 
     void HandleTimeout() {
-        Status = Ydb::StatusIds::TIMEOUT;
-        ReplyAndPassAway();
+        ReplyErrorAndPassAway(Ydb::StatusIds::TIMEOUT, "Login timeout");
     }
 
     void HandleNavigate(TEvTxProxySchemeCache::TEvNavigateKeySetResult::TPtr& ev) {
@@ -68,42 +66,39 @@ class TLoginRPC : public TRpcRequestActor<TLoginRPC, TEvLoginRequest, true> {
                 return;
             }
         }
-        Status = Ydb::StatusIds::SCHEME_ERROR;
-        ReplyAndPassAway();
+        ReplyErrorAndPassAway(Ydb::StatusIds::SCHEME_ERROR, "No database found");
     }
 
     void Handle(TEvLdapAuthProvider::TEvAuthenticateResponse::TPtr& ev) {
-        TEvLdapAuthProvider::TEvAuthenticateResponse* response = ev->Get();
-        if (response->Status == TEvLdapAuthProvider::EStatus::SUCCESS) {
+        const TEvLdapAuthProvider::TEvAuthenticateResponse& response = *ev->Get();
+        if (response.Status == TEvLdapAuthProvider::EStatus::SUCCESS) {
             Send(MakeSchemeCacheID(), new TEvTxProxySchemeCache::TEvNavigateKeySet(CreateNavigateKeySetRequest(PathToDatabase).Release()));
         } else {
-            TResponse loginResponse;
-            Ydb::Operations::Operation& operation = *loginResponse.mutable_operation();
-            Ydb::Issue::IssueMessage* issue = operation.add_issues();
-            issue->set_message(response->Error.Message);
-            Status = ConvertLdapStatus(response->Status);
-            issue->set_issue_code(Status);
-            operation.set_ready(true);
-            operation.set_status(Status);
-            Reply(loginResponse);
+            ReplyErrorAndPassAway(ConvertLdapStatus(response.Status), response.Error.Message, response.Error.LogMessage);
         }
     }
 
     void HandleResult(TEvSchemeShard::TEvLoginResult::TPtr& ev) {
-        Status = Ydb::StatusIds::SUCCESS;
-        Result = ev->Release();
-        ReplyAndPassAway();
+        const NKikimrScheme::TEvLoginResult& loginResult = ev->Get()->Record;
+        if (loginResult.error()) {
+            // explicit error takes precedence
+            ReplyErrorAndPassAway(Ydb::StatusIds::UNAUTHORIZED, loginResult.error(), /*loginResult.details()*/ TString());
+        } else if (loginResult.token().empty()) {
+            // empty token is still an error
+            ReplyErrorAndPassAway(Ydb::StatusIds::INTERNAL_ERROR, "Failed to produce a token");
+        } else {
+            // success = token + no errors
+            ReplyAndPassAway(loginResult.token());
+        }
     }
 
     void HandleUndelivered(TEvents::TEvUndelivered::TPtr&) {
-        Status = Ydb::StatusIds::UNAVAILABLE;
-        ReplyAndPassAway();
+        ReplyErrorAndPassAway(Ydb::StatusIds::UNAVAILABLE, "SchemeShard is unreachable");
     }
 
     void HandleConnect(TEvTabletPipe::TEvClientConnected::TPtr& ev) {
         if (ev->Get()->Status != NKikimrProto::OK) {
-            Status = Ydb::StatusIds::UNAVAILABLE;
-            ReplyAndPassAway();
+            ReplyErrorAndPassAway(Ydb::StatusIds::UNAVAILABLE, "SchemeShard is unavailable");
         }
     }
 
@@ -118,28 +113,46 @@ class TLoginRPC : public TRpcRequestActor<TLoginRPC, TEvLoginRequest, true> {
         }
     }
 
-    void ReplyAndPassAway() {
-        if (PipeClient) {
-            NTabletPipe::CloseClient(SelfId(), PipeClient);
-        }
+    void ReplyAndPassAway(const TString& resultToken) {
         TResponse response;
+
         Ydb::Operations::Operation& operation = *response.mutable_operation();
-        if (Result) {
-            const NKikimrScheme::TEvLoginResult& record = Result->Record;
-            if (record.error()) {
-                Ydb::Issue::IssueMessage* issue = operation.add_issues();
-                issue->set_message(record.error());
-                issue->set_issue_code(Ydb::StatusIds::UNAUTHORIZED);
-                Status = Ydb::StatusIds::UNAUTHORIZED;
-            }
-            if (record.token()) {
-                Ydb::Auth::LoginResult result;
-                result.set_token(record.token());
-                operation.mutable_result()->PackFrom(result);
-            }
+        operation.set_ready(true);
+        operation.set_status(Ydb::StatusIds::SUCCESS);
+        // Pack result to google::protobuf::Any
+        {
+            Ydb::Auth::LoginResult result;
+            result.set_token(resultToken);
+            operation.mutable_result()->PackFrom(result);
         }
+
+        AuditLogLogin(Request.Get(), PathToDatabase, *GetProtoRequest(), response, /* errorDetails */ TString());
+
+        return CleanupAndReply(response);
+    }
+
+    void ReplyErrorAndPassAway(const Ydb::StatusIds_StatusCode status, const TString& error, const TString& reason = "") {
+        TResponse response;
+
+        Ydb::Operations::Operation& operation = *response.mutable_operation();
         operation.set_ready(true);
-        operation.set_status(Status);
+        operation.set_status(status);
+        if (error) {
+            Ydb::Issue::IssueMessage* issue = operation.add_issues();
+            issue->set_issue_code(status);
+            issue->set_message(error);
+        }
+
+        AuditLogLogin(Request.Get(), PathToDatabase, *GetProtoRequest(), response, reason);
+
+        return CleanupAndReply(response);
+    }
+
+    void CleanupAndReply(const TResponse& response) {
+        if (PipeClient) {
+            NTabletPipe::CloseClient(SelfId(), PipeClient);
+        }
+
         return Reply(response);
     }
 

ydb/core/grpc_services/ya.make

@@ -3,6 +3,7 @@ LIBRARY()
 SRCS(
     audit_log.cpp
     audit_dml_operations.cpp
+    audit_logins.cpp
     db_metadata_cache.h
     grpc_endpoint_publish_actor.cpp
     grpc_helper.cpp

ydb/core/security/ldap_auth_provider/ldap_auth_provider.cpp

@@ -181,6 +181,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             if (!NKikimrLdap::IsSuccess(result)) {
                 TStringBuilder logErrorMessage;
                 logErrorMessage << "Could not start TLS. " << NKikimrLdap::ErrorToString(result);
+                LDAP_LOG_D(logErrorMessage);
                 TEvLdapAuthProvider::TError error {
                     .Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)
                 };
@@ -197,6 +198,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             TStringBuilder logErrorMessage;
             logErrorMessage << "Could not perform initial LDAP bind for dn " << Settings.GetBindDn() << " on server " + UrisCreator.GetUris() << ". "
                             << NKikimrLdap::ErrorToString(result);
+            LDAP_LOG_D(logErrorMessage);
             TEvLdapAuthProvider::TError error {
                 .Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)
             };
@@ -220,6 +222,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             if (!NKikimrLdap::IsSuccess(result)) {
                 TStringBuilder logErrorMessage;
                 logErrorMessage << "Could not set LDAP ca file \"" << caCertificateFile + "\": " << NKikimrLdap::ErrorToString(result);
+                LDAP_LOG_D(logErrorMessage);
                 NKikimrLdap::Unbind(*ld);
                 return {{NKikimrLdap::ErrorToStatus(result),
                         {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
@@ -231,6 +234,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
         if (!NKikimrLdap::IsSuccess(result)) {
             TStringBuilder logErrorMessage;
             logErrorMessage << "Could not initialize LDAP connection for uris: " << UrisCreator.GetUris() << ". " << NKikimrLdap::LdapError(*ld);
+            LDAP_LOG_D(logErrorMessage);
             return {{TEvLdapAuthProvider::EStatus::UNAVAILABLE,
                     {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = false}}};
         }
@@ -240,6 +244,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             NKikimrLdap::Unbind(*ld);
             TStringBuilder logErrorMessage;
             logErrorMessage << "Could not set LDAP protocol version: " << NKikimrLdap::ErrorToString(result);
+            LDAP_LOG_D(logErrorMessage);
             return {{NKikimrLdap::ErrorToStatus(result),
                     {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
         }
@@ -251,6 +256,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
                 NKikimrLdap::Unbind(*ld);
                 TStringBuilder logErrorMessage;
                 logErrorMessage << "Could not set require certificate option: " << NKikimrLdap::ErrorToString(result);
+                LDAP_LOG_D(logErrorMessage);
                 return {{NKikimrLdap::ErrorToStatus(result),
                         {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)}}};
             }
@@ -265,12 +271,14 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             TStringBuilder logErrorMessage;
             logErrorMessage << "Could not get dn for the first entry matching " << FilterCreator.GetFilter(request.Login)
                             << " on server " << UrisCreator.GetUris() << ". " << NKikimrLdap::LdapError(*request.Ld);
+            LDAP_LOG_D(logErrorMessage);
             return {{TEvLdapAuthProvider::EStatus::UNAUTHORIZED,
                     {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = false}}};
         }
         if (request.Password.empty()) {
             TStringBuilder logErrorMessage;
             logErrorMessage << "LDAP login failed for user " << TString(dn) << ". Empty password";
+            LDAP_LOG_D(logErrorMessage);
             NKikimrLdap::MemFree(dn);
             return {{.Status = TEvLdapAuthProvider::EStatus::UNAUTHORIZED, .Error = {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = false}}};
         }
@@ -281,6 +289,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             TStringBuilder logErrorMessage;
             logErrorMessage << "LDAP login failed for user " << TString(dn) << " on server " << UrisCreator.GetUris() << ". "
                             << NKikimrLdap::ErrorToString((result));
+            LDAP_LOG_D(logErrorMessage);
             error.Message = ERROR_MESSAGE;
             error.LogMessage = logErrorMessage;
             error.Retryable = NKikimrLdap::IsRetryableError(result);
@@ -311,6 +320,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
                             << NKikimrLdap::ErrorToString(result);
             response.Status = NKikimrLdap::ErrorToStatus(result);
             response.Error = {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = NKikimrLdap::IsRetryableError(result)};
+            LDAP_LOG_D(logErrorMessage);
             return response;
         }
         const int countEntries = NKikimrLdap::CountEntries(request.Ld, searchMessage);
@@ -326,6 +336,7 @@ class TLdapAuthProvider : public NActors::TActorBootstrapped<TLdapAuthProvider>
             response.Error = {.Message = ERROR_MESSAGE, .LogMessage = logErrorMessage, .Retryable = false};
             response.Status = TEvLdapAuthProvider::EStatus::UNAUTHORIZED;
             NKikimrLdap::MsgFree(searchMessage);
+            LDAP_LOG_D(logErrorMessage);
             return response;
         }
         response.SearchMessage = searchMessage;