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>
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,
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,
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,
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,
}
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,
/* 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;
*/
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,
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]
msg["Authentication"]["serviceDescription"])
self.assertEquals("ENC-TS Pre-authentication",
msg["Authentication"]["authDescription"])
+ self.assertTrue(msg["Authentication"]["duration"] > 0)
def test_ldap_ntlm(self):
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):
}
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);
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);
return NT_STATUS_NO_MEMORY;
}
+ ctx->start_time = timeval_current();
+
talloc_set_destructor((TALLOC_CTX *)ctx, auth_context_destructor);
*auth_context = ctx;
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;
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);
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,
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;
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);
}
}
log_authentication_event(msg_ctx,
lp_ctx,
+ NULL,
&ui,
status,
domain_name,
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);
if (clientdb->hdb_auth_status)
(clientdb->hdb_auth_status)(context, clientdb, client,
from_addr,
+ &_kdc_now,
client_name,
"PKINIT",
HDB_AUTH_PKINIT_SUCCESS);
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);
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);
if (clientdb->hdb_auth_status)
(clientdb->hdb_auth_status)(context, clientdb, client,
from_addr,
+ &_kdc_now,
client_name,
NULL,
HDB_AUTHZ_SUCCESS);
*/
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);
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)
log_authentication_event(kdc_db_ctx->msg_ctx,
kdc_db_ctx->lp_ctx,
+ start_time,
&ui,
status,
domain_name,
log_authentication_event(kdc_db_ctx->msg_ctx,
kdc_db_ctx->lp_ctx,
+ start_time,
&ui,
NT_STATUS_NO_SUCH_USER,
NULL, NULL,
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),
log_authentication_event(msg_ctx,
lp_ctx,
+ NULL,
&ui,
status,
ui.mapped.domain_name,