auth: For NTLM and KDC authentication, log the authentication duration

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>

diff --git a/auth/auth_log.c b/auth/auth_log.c
index 369a5c96162f593d5406edc6d458e19fa39125ff..67d23c12a1b852cc7670c326f9386c48a23be9af 100644 (file)
--- a/auth/auth_log.c
+++ b/auth/auth_log.c
@@ -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,

diff --git a/auth/common_auth.h b/auth/common_auth.h
index 3de227ee35499b8b6546be658962c02efb55ab69..d8377eb5347ce5f17b8607935b3465879a3dbc35 100644 (file)
--- a/auth/common_auth.h
+++ b/auth/common_auth.h
@@ -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,

diff --git a/python/samba/tests/auth_log.py b/python/samba/tests/auth_log.py
index 6cec63a81713fda9bf13fdf4cfb2912a64b99b69..cb524d0ed81cd6e44ec471175edd2463a356d480 100644 (file)
--- a/python/samba/tests/auth_log.py
+++ b/python/samba/tests/auth_log.py
@@ -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):

diff --git a/source3/auth/auth.c b/source3/auth/auth.c
index e0011a47eb333a499a4b478d55dce8c035a92b87..d13d0fe471c967d1f692c36b89dbff4d2fb7c231 100644 (file)
--- a/source3/auth/auth.c
+++ b/source3/auth/auth.c
@@ -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;

diff --git a/source3/include/auth.h b/source3/include/auth.h
index 31a1f2018359bc39196ba04b1f5e626a3f7ae4ad..0facb8668cd37f5167689acd55230292985ac73d 100644 (file)
--- a/source3/include/auth.h
+++ b/source3/include/auth.h
@@ -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; 
 

diff --git a/source4/auth/ntlm/auth.c b/source4/auth/ntlm/auth.c
index e560116b9419ee3e526c3b1984337b5fb39b29a5..3a3fa7eaa59b9a4d0d7cb5fb86baf727aa92fb7b 100644 (file)
--- a/source4/auth/ntlm/auth.c
+++ b/source4/auth/ntlm/auth.c
@@ -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;

diff --git a/source4/auth/ntlm/auth_simple.c b/source4/auth/ntlm/auth_simple.c
index 273e48861250adc96c7d583f73bdb4bf35fd936a..fcd9050979d0c015b7226b797e427db35266cb3d 100644 (file)
--- a/source4/auth/ntlm/auth_simple.c
+++ b/source4/auth/ntlm/auth_simple.c
@@ -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);
        }

diff --git a/source4/dsdb/samdb/ldb_modules/password_hash.c b/source4/dsdb/samdb/ldb_modules/password_hash.c
index 56ecdaf81c0f5a3be210874971e834e98083624e..58ae64537eb601447e743584149bc2f29a23454b 100644 (file)
--- a/source4/dsdb/samdb/ldb_modules/password_hash.c
+++ b/source4/dsdb/samdb/ldb_modules/password_hash.c
@@ -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,

diff --git a/source4/heimdal/kdc/kerberos5.c b/source4/heimdal/kdc/kerberos5.c
index 4baf90e41d8728d6701fc1919bb924417075d440..12187dde4299de7c8ce5b7f3bafae39ee557354d 100644 (file)
--- a/source4/heimdal/kdc/kerberos5.c
+++ b/source4/heimdal/kdc/kerberos5.c
@@ -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);

diff --git a/source4/heimdal/lib/hdb/hdb.h b/source4/heimdal/lib/hdb/hdb.h
index 1af798d3512fa1c4c499dfe9df1bff9cbbdd3181..6a09ecb6fe180ffd27f180cf2bf650be008e21ce 100644 (file)
--- a/source4/heimdal/lib/hdb/hdb.h
+++ b/source4/heimdal/lib/hdb/hdb.h
@@ -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);

diff --git a/source4/kdc/hdb-samba4.c b/source4/kdc/hdb-samba4.c
index 50eed445cd55da1b59e5579c87b216d9b48cce76..cff472574d414b776b26cffc0721e00bc654b4c5 100644 (file)
--- a/source4/kdc/hdb-samba4.c
+++ b/source4/kdc/hdb-samba4.c
@@ -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,

diff --git a/source4/rpc_server/netlogon/dcerpc_netlogon.c b/source4/rpc_server/netlogon/dcerpc_netlogon.c
index c19d33c88921884fa9e7ba385a1c2626fbcccdca..b4046bdd203773f7a63f281e32647239cf099c82 100644 (file)
--- a/source4/rpc_server/netlogon/dcerpc_netlogon.c
+++ b/source4/rpc_server/netlogon/dcerpc_netlogon.c
@@ -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),

diff --git a/source4/rpc_server/samr/samr_password.c b/source4/rpc_server/samr/samr_password.c
index db202cce986b343c021d74ad11e60c2ce80a1c05..4c6569888796546e91048f72624182afff6d24f2 100644 (file)
--- a/source4/rpc_server/samr/samr_password.c
+++ b/source4/rpc_server/samr/samr_password.c
@@ -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,