auth: For NTLM and KDC authentication, log the authentication duration
authorAndrew Bartlett <abartlet@samba.org>
Sun, 10 Jun 2018 11:00:34 +0000 (13:00 +0200)
committerAndrew Bartlett <abartlet@samba.org>
Mon, 25 Jun 2018 06:32:14 +0000 (08:32 +0200)
This is not a general purpose profiling solution, but these JSON logs are already being
generated and stored, so this is worth adding.

Some administrators are very keen to know how long authentication
takes, particularly due to long replication transactions in other
processes.

This complements a similar patch set to log the transaction duration.

Signed-off-by: Andrew Bartlett <abartlet@samba.org>
Reviewed-by: Gary Lockyer <gary@catalyst.net.nz>
13 files changed:
auth/auth_log.c
auth/common_auth.h
python/samba/tests/auth_log.py
source3/auth/auth.c
source3/include/auth.h
source4/auth/ntlm/auth.c
source4/auth/ntlm/auth_simple.c
source4/dsdb/samdb/ldb_modules/password_hash.c
source4/heimdal/kdc/kerberos5.c
source4/heimdal/lib/hdb/hdb.h
source4/kdc/hdb-samba4.c
source4/rpc_server/netlogon/dcerpc_netlogon.c
source4/rpc_server/samr/samr_password.c

index 369a5c9..67d23c1 100644 (file)
@@ -114,6 +114,7 @@ static void log_json(struct imessaging_context *msg_ctx,
 static void log_authentication_event_json(
        struct imessaging_context *msg_ctx,
        struct loadparm_context *lp_ctx,
+       const struct timeval *start_time,
        const struct auth_usersupplied_info *ui,
        NTSTATUS status,
        const char *domain_name,
@@ -180,6 +181,22 @@ static void log_authentication_event_json(
        json_add_string(&authentication, "passwordType", get_password_type(ui));
        json_add_object(&wrapper, AUTH_JSON_TYPE, &authentication);
 
+       /*
+        * While not a general-purpose profiling solution this will
+        * assist some to determine how long NTLM and KDC
+        * authentication takes once this process can handle it.  This
+        * covers transactions elsewhere but not (eg) the delay while
+        * this is waiting unread on the input socket.
+        */
+       if (start_time != NULL) {
+               struct timeval current_time = timeval_current();
+               uint64_t duration =  usec_time_diff(&current_time,
+                                                   start_time);
+               json_add_int(&authentication,
+                            "duration",
+                            duration);
+       }
+
        log_json(msg_ctx,
                 lp_ctx,
                 &wrapper,
@@ -296,6 +313,7 @@ static void log_no_json(struct imessaging_context *msg_ctx,
 static void log_authentication_event_json(
        struct imessaging_context *msg_ctx,
        struct loadparm_context *lp_ctx,
+       const struct timeval *start_time,
        const struct auth_usersupplied_info *ui,
        NTSTATUS status,
        const char *domain_name,
@@ -470,6 +488,7 @@ static void log_authentication_event_human_readable(
 void log_authentication_event(
        struct imessaging_context *msg_ctx,
        struct loadparm_context *lp_ctx,
+       const struct timeval *start_time,
        const struct auth_usersupplied_info *ui,
        NTSTATUS status,
        const char *domain_name,
@@ -498,7 +517,9 @@ void log_authentication_event(
        }
        if (CHECK_DEBUGLVLC(DBGC_AUTH_AUDIT_JSON, debug_level) ||
            (msg_ctx && lp_ctx && lpcfg_auth_event_notification(lp_ctx))) {
-               log_authentication_event_json(msg_ctx, lp_ctx,
+               log_authentication_event_json(msg_ctx,
+                                             lp_ctx,
+                                             start_time,
                                              ui,
                                              status,
                                              domain_name,
index 3de227e..d8377eb 100644 (file)
@@ -122,6 +122,9 @@ struct auth4_context {
        /* SAM database for this local machine - to fill in local groups, or to authenticate local NTLM users */
        struct ldb_context *sam_ctx;
 
+       /* The time this authentication started */
+       struct timeval start_time;
+
        /* Private data for the callbacks on this auth context */
        void *private_data;
 
@@ -178,6 +181,7 @@ struct auth4_context {
  */
 void log_authentication_event(struct imessaging_context *msg_ctx,
                              struct loadparm_context *lp_ctx,
+                             const struct timeval *start_time,
                              const struct auth_usersupplied_info *ui,
                              NTSTATUS status,
                              const char *account_name,
index 6cec63a..cb524d0 100644 (file)
@@ -430,6 +430,7 @@ class AuthLogTests(samba.tests.auth_log_base.AuthLogTestBase):
                           msg["Authentication"]["serviceDescription"])
         self.assertEquals("ENC-TS Pre-authentication",
                           msg["Authentication"]["authDescription"])
+        self.assertTrue(msg["Authentication"]["duration"] > 0)
 
         # Check the second message it should be an Authentication
         msg = messages[1]
@@ -439,6 +440,7 @@ class AuthLogTests(samba.tests.auth_log_base.AuthLogTestBase):
                           msg["Authentication"]["serviceDescription"])
         self.assertEquals("ENC-TS Pre-authentication",
                           msg["Authentication"]["authDescription"])
+        self.assertTrue(msg["Authentication"]["duration"] > 0)
 
     def test_ldap_ntlm(self):
 
@@ -463,6 +465,7 @@ class AuthLogTests(samba.tests.auth_log_base.AuthLogTestBase):
         self.assertEquals("LDAP",
                           msg["Authentication"]["serviceDescription"])
         self.assertEquals("NTLMSSP", msg["Authentication"]["authDescription"])
+        self.assertTrue(msg["Authentication"]["duration"] > 0)
 
     def test_ldap_simple_bind(self):
         def isLastExpectedMessage(msg):
index e0011a4..d13d0fe 100644 (file)
@@ -300,7 +300,9 @@ NTSTATUS auth_check_ntlm_password(TALLOC_CTX *mem_ctx,
        }
 
        log_authentication_event(NULL, NULL,
-                                user_info, nt_status,
+                                &auth_context->start_time,
+                                user_info,
+                                nt_status,
                                 server_info->info3->base.logon_domain.string,
                                 server_info->info3->base.account_name.string,
                                 unix_username, &sid);
@@ -331,7 +333,15 @@ fail:
                  user_info->client.account_name, user_info->mapped.account_name,
                  nt_errstr(nt_status), *pauthoritative));
 
-       log_authentication_event(NULL, NULL, user_info, nt_status, NULL, NULL, NULL, NULL);
+       log_authentication_event(NULL,
+                                NULL,
+                                &auth_context->start_time,
+                                user_info,
+                                nt_status,
+                                NULL,
+                                NULL,
+                                NULL,
+                                NULL);
 
        ZERO_STRUCTP(pserver_info);
 
@@ -373,6 +383,8 @@ static NTSTATUS make_auth_context(TALLOC_CTX *mem_ctx,
                return NT_STATUS_NO_MEMORY;
        }
 
+       ctx->start_time = timeval_current();
+
        talloc_set_destructor((TALLOC_CTX *)ctx, auth_context_destructor);
 
        *auth_context = ctx;
index 31a1f20..0facb86 100644 (file)
@@ -84,6 +84,9 @@ typedef NTSTATUS (*make_auth4_context_fn)(const struct auth_context *auth_contex
 struct auth_context {
        DATA_BLOB challenge; 
 
+       /* What time did this start */
+       struct timeval start_time;
+
        /* Who set this up in the first place? */ 
        const char *challenge_set_by; 
 
index e560116..3a3fa7e 100644 (file)
@@ -479,6 +479,7 @@ _PUBLIC_ NTSTATUS auth_check_password_recv(struct tevent_req *req,
 
                log_authentication_event(state->auth_ctx->msg_ctx,
                                         state->auth_ctx->lp_ctx,
+                                        &state->auth_ctx->start_time,
                                         state->user_info, status,
                                         NULL, NULL, NULL, NULL);
                tevent_req_received(req);
@@ -493,6 +494,7 @@ _PUBLIC_ NTSTATUS auth_check_password_recv(struct tevent_req *req,
 
        log_authentication_event(state->auth_ctx->msg_ctx,
                                 state->auth_ctx->lp_ctx,
+                                &state->auth_ctx->start_time,
                                 state->user_info, status,
                                 state->user_info_dc->info->domain_name,
                                 state->user_info_dc->info->account_name,
@@ -712,6 +714,7 @@ _PUBLIC_ NTSTATUS auth_context_create_methods(TALLOC_CTX *mem_ctx, const char *
        ctx->event_ctx                  = ev;
        ctx->msg_ctx                    = msg;
        ctx->lp_ctx                     = lp_ctx;
+       ctx->start_time                 = timeval_current();
 
        if (sam_ctx) {
                ctx->sam_ctx = sam_ctx;
index 273e488..fcd9050 100644 (file)
@@ -112,6 +112,7 @@ _PUBLIC_ struct tevent_req *authenticate_ldap_simple_bind_send(TALLOC_CTX *mem_c
                                             dn, &nt4_domain, &nt4_username);
        if (!NT_STATUS_IS_OK(status)) {
                log_authentication_event(msg, lp_ctx,
+                                        &state->auth_context->start_time,
                                         user_info, status,
                                         NULL, NULL, NULL, NULL);
        }
index 56ecdaf..58ae645 100644 (file)
@@ -2900,6 +2900,7 @@ static int check_password_restrictions_and_log(struct setup_password_fields_io *
                }
                log_authentication_event(msg_ctx,
                                         lp_ctx,
+                                        NULL,
                                         &ui,
                                         status,
                                         domain_name,
index 4baf90e..12187dd 100644 (file)
@@ -1094,6 +1094,7 @@ _kdc_as_rep(krb5_context context,
        if (config->db[0] && config->db[0]->hdb_auth_status)
                (config->db[0]->hdb_auth_status)(context, config->db[0], NULL,
                                                 from_addr,
+                                                &_kdc_now,
                                                 client_name,
                                                 NULL,
                                                 HDB_AUTH_CLIENT_UNKNOWN);
@@ -1204,6 +1205,7 @@ _kdc_as_rep(krb5_context context,
            if (clientdb->hdb_auth_status)
                    (clientdb->hdb_auth_status)(context, clientdb, client,
                                                from_addr,
+                                               &_kdc_now,
                                                client_name,
                                                "PKINIT",
                                                HDB_AUTH_PKINIT_SUCCESS);
@@ -1323,6 +1325,7 @@ _kdc_as_rep(krb5_context context,
                if (clientdb->hdb_auth_status)
                    (clientdb->hdb_auth_status)(context, clientdb, client,
                                                from_addr,
+                                               &_kdc_now,
                                                client_name,
                                                str ? str : "unknown enctype",
                                                HDB_AUTH_WRONG_PASSWORD);
@@ -1386,6 +1389,7 @@ _kdc_as_rep(krb5_context context,
            if (clientdb->hdb_auth_status)
                    (clientdb->hdb_auth_status)(context, clientdb, client,
                                                from_addr,
+                                               &_kdc_now,
                                                client_name,
                                                str ? str : "unknown enctype",
                                                HDB_AUTH_CORRECT_PASSWORD);
@@ -1443,6 +1447,7 @@ _kdc_as_rep(krb5_context context,
     if (clientdb->hdb_auth_status)
        (clientdb->hdb_auth_status)(context, clientdb, client,
                                    from_addr,
+                                   &_kdc_now,
                                    client_name,
                                    NULL,
                                    HDB_AUTHZ_SUCCESS);
index 1af798d..6a09ecb 100644 (file)
@@ -249,6 +249,7 @@ typedef struct HDB{
      */
     krb5_error_code (*hdb_auth_status)(krb5_context, struct HDB *,
                                       hdb_entry_ex *, struct sockaddr *from_addr,
+                                      struct timeval *start_time,
                                       const char *original_client_name,
                                       const char *auth_type,
                                       int);
index 50eed44..cff4725 100644 (file)
@@ -388,6 +388,7 @@ static void send_bad_password_netlogon(TALLOC_CTX *mem_ctx,
 static krb5_error_code hdb_samba4_auth_status(krb5_context context, HDB *db,
                                              hdb_entry_ex *entry,
                                              struct sockaddr *from_addr,
+                                             struct timeval *start_time,
                                              const char *original_client_name,
                                              const char *auth_type,
                                              int hdb_auth_status)
@@ -494,6 +495,7 @@ static krb5_error_code hdb_samba4_auth_status(krb5_context context, HDB *db,
 
                log_authentication_event(kdc_db_ctx->msg_ctx,
                                         kdc_db_ctx->lp_ctx,
+                                        start_time,
                                         &ui,
                                         status,
                                         domain_name,
@@ -519,6 +521,7 @@ static krb5_error_code hdb_samba4_auth_status(krb5_context context, HDB *db,
 
                log_authentication_event(kdc_db_ctx->msg_ctx,
                                         kdc_db_ctx->lp_ctx,
+                                        start_time,
                                         &ui,
                                         NT_STATUS_NO_SUCH_USER,
                                         NULL, NULL,
index c19d33c..b4046bd 100644 (file)
@@ -557,6 +557,7 @@ static NTSTATUS dcesrv_netr_ServerAuthenticate3(
        log_authentication_event(
                dce_call->conn->msg_ctx,
                dce_call->conn->dce_ctx->lp_ctx,
+               NULL,
                &ui,
                status,
                lpcfg_workgroup(dce_call->conn->dce_ctx->lp_ctx),
index db202cc..4c65698 100644 (file)
@@ -68,6 +68,7 @@ static void log_password_change_event(struct imessaging_context *msg_ctx,
 
        log_authentication_event(msg_ctx,
                                 lp_ctx,
+                                NULL,
                                 &ui,
                                 status,
                                 ui.mapped.domain_name,