From 1bb2a1c6b3eaccf114ac3f3b5b51f57828a04996 Mon Sep 17 00:00:00 2001 From: Andrew Bartlett Date: Sun, 10 Jun 2018 13:00:34 +0200 Subject: [PATCH] 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 Reviewed-by: Gary Lockyer --- auth/auth_log.c | 23 ++++++++++++++++++- auth/common_auth.h | 4 ++++ python/samba/tests/auth_log.py | 3 +++ source3/auth/auth.c | 16 +++++++++++-- source3/include/auth.h | 3 +++ source4/auth/ntlm/auth.c | 3 +++ source4/auth/ntlm/auth_simple.c | 1 + .../dsdb/samdb/ldb_modules/password_hash.c | 1 + source4/heimdal/kdc/kerberos5.c | 5 ++++ source4/heimdal/lib/hdb/hdb.h | 1 + source4/kdc/hdb-samba4.c | 3 +++ source4/rpc_server/netlogon/dcerpc_netlogon.c | 1 + source4/rpc_server/samr/samr_password.c | 1 + 13 files changed, 62 insertions(+), 3 deletions(-) diff --git a/auth/auth_log.c b/auth/auth_log.c index 369a5c96162..67d23c12a1b 100644 --- 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(¤t_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 3de227ee354..d8377eb5347 100644 --- 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 6cec63a8171..cb524d0ed81 100644 --- 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 e0011a47eb3..d13d0fe471c 100644 --- 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 31a1f201835..0facb8668cd 100644 --- 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 e560116b941..3a3fa7eaa59 100644 --- 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 273e4886125..fcd9050979d 100644 --- 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 56ecdaf81c0..58ae64537eb 100644 --- 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 4baf90e41d8..12187dde429 100644 --- 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 1af798d3512..6a09ecb6fe1 100644 --- 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 50eed445cd5..cff472574d4 100644 --- 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 c19d33c8892..b4046bdd203 100644 --- 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 db202cce986..4c656988879 100644 --- 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,