[PATCH] Log transaction and authentication durations.
Gary Lockyer
gary at catalyst.net.nz
Mon Jun 25 01:59:47 UTC 2018
Updated patch set to fix a flapping test.
Gary
On 20/06/18 12:17, Gary Lockyer via samba-technical wrote:
> Log the transaction duration and duration of NTLM and KDC
> authentication. The DSDB audit logging tests should also be less flappy
> due to the changes made.
>
> Review and Push appreciated.
>
> Thanks
> Gary.
>
-------------- next part --------------
From 599f2f6d389d9ac063c9d34de93f4a30b2cc1898 Mon Sep 17 00:00:00 2001
From: Andrew Bartlett <abartlet at samba.org>
Date: Sun, 10 Jun 2018 13:00:34 +0200
Subject: [PATCH 1/2] 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 at samba.org>
---
auth/auth_log.c | 24 +++++++++++++++++++++++-
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 | 5 ++++-
source4/auth/ntlm/auth_simple.c | 1 +
source4/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, 64 insertions(+), 4 deletions(-)
diff --git a/auth/auth_log.c b/auth/auth_log.c
index 369a5c9..4a41979 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,
@@ -311,6 +329,7 @@ static void log_authentication_event_json(
static void log_successful_authz_event_json(
struct imessaging_context *msg_ctx,
struct loadparm_context *lp_ctx,
+ const struct timeval *start_time,
const struct tsocket_address *remote,
const struct tsocket_address *local,
const char *service_description,
@@ -470,6 +489,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 +518,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 3de227e..3a97aff 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 6cec63a..cb524d0 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 e0011a4..78c72af 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 31a1f20..5b9bc54 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 e560116..b6b3be2 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,7 +714,8 @@ _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;
} else {
diff --git a/source4/auth/ntlm/auth_simple.c b/source4/auth/ntlm/auth_simple.c
index 273e488..fcd9050 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 56ecdaf..58ae645 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 4baf90e..12187dd 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 1af798d..6a09ecb 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 50eed44..cff4725 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 c19d33c..b4046bd 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 db202cc..4c65698 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,
--
2.7.4
From 7b12afa3f3a991a0815742950bdc47152a5b2bdf Mon Sep 17 00:00:00 2001
From: Gary Lockyer <gary at catalyst.net.nz>
Date: Wed, 6 Jun 2018 15:30:44 +0200
Subject: [PATCH 2/2] dsdb: Log the transaction duraton.
This is not a general purpose profiling solution, but these JSON
logs are already being generated and stored, so this is worth adding.
This will allow administrators to identify long running
transactions, and identify potential performance bottlenecks.
This complements a similar patch set to log authentication duration.
Signed-off-by: Gary Lockyer <gary at catalyst.net.nz>
---
python/samba/tests/audit_log_base.py | 13 +--
python/samba/tests/audit_log_dsdb.py | 83 +++++++++++--------
source4/dsdb/samdb/ldb_modules/audit_log.c | 95 ++++++++++++++--------
.../dsdb/samdb/ldb_modules/tests/test_audit_log.c | 25 ++++--
4 files changed, 141 insertions(+), 75 deletions(-)
diff --git a/python/samba/tests/audit_log_base.py b/python/samba/tests/audit_log_base.py
index fa51911..e91c414 100644
--- a/python/samba/tests/audit_log_base.py
+++ b/python/samba/tests/audit_log_base.py
@@ -27,6 +27,7 @@ import json
import os
import re
+
def getAudit(message):
if "type" not in message:
return None
@@ -35,8 +36,8 @@ def getAudit(message):
audit = message[type]
return audit
-class AuditLogTestBase(samba.tests.TestCase):
+class AuditLogTestBase(samba.tests.TestCase):
def setUp(self):
super(AuditLogTestBase, self).setUp()
@@ -51,7 +52,7 @@ class AuditLogTestBase(samba.tests.TestCase):
def isRemote(message):
audit = getAudit(message)
if audit is None:
- return false
+ return False
remote = audit["remoteAddress"]
if remote is None:
@@ -76,7 +77,7 @@ class AuditLogTestBase(samba.tests.TestCase):
elif jsonMsg["type"] == "dsdbTransaction":
context["txnMessage"] = jsonMsg
- self.context = {"messages": [], "txnMessage": ""}
+ self.context = {"messages": [], "txnMessage": None}
self.msg_handler_and_context = (messageHandler, self.context)
self.msg_ctx.register(self.msg_handler_and_context,
msg_type=self.message_type)
@@ -127,7 +128,6 @@ class AuditLogTestBase(samba.tests.TestCase):
return True
return False
-
def waitForMessages(self, number, connection=None, dn=None):
"""Wait for all the expected messages to arrive
The connection is passed through to keep the connection alive
@@ -158,8 +158,11 @@ class AuditLogTestBase(samba.tests.TestCase):
# Discard any previously queued messages.
def discardMessages(self):
self.msg_ctx.loop_once(0.001)
- while len(self.context["messages"]):
+ while (len(self.context["messages"]) or
+ self.context["txnMessage"] is not None):
+
self.context["messages"] = []
+ self.context["txnMessage"] = None
self.msg_ctx.loop_once(0.001)
GUID_RE = "[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}"
diff --git a/python/samba/tests/audit_log_dsdb.py b/python/samba/tests/audit_log_dsdb.py
index 5329af4..53d4573 100644
--- a/python/samba/tests/audit_log_dsdb.py
+++ b/python/samba/tests/audit_log_dsdb.py
@@ -21,6 +21,7 @@ from __future__ import print_function
import samba.tests
from samba.dcerpc.messaging import MSG_DSDB_LOG, DSDB_EVENT_NAME
+from ldb import ERR_NO_SUCH_OBJECT
from samba.samdb import SamDB
from samba.auth import system_session
import os
@@ -33,8 +34,6 @@ from samba.dcerpc import security, lsa
USER_NAME = "auditlogtestuser"
USER_PASS = samba.generate_random_password(32, 32)
-SECOND_USER_NAME = "auditlogtestuser02"
-SECOND_USER_PASS = samba.generate_random_password(32, 32)
class AuditLogDsdbTests(AuditLogTestBase):
@@ -79,9 +78,6 @@ class AuditLogDsdbTests(AuditLogTestBase):
# (Re)adds the test user USER_NAME with password USER_PASS
delete_force(self.ldb, "cn=" + USER_NAME + ",cn=users," + self.base_dn)
- delete_force(
- self.ldb,
- "cn=" + SECOND_USER_NAME + ",cn=users," + self.base_dn)
self.ldb.add({
"dn": "cn=" + USER_NAME + ",cn=users," + self.base_dn,
"objectclass": "user",
@@ -93,15 +89,21 @@ class AuditLogDsdbTests(AuditLogTestBase):
# Discard the messages from the setup code
#
def discardSetupMessages(self, dn):
- messages = self.waitForMessages(2, dn=dn)
+ self.waitForMessages(2, dn=dn)
self.discardMessages()
-
def tearDown(self):
self.discardMessages()
super(AuditLogDsdbTests, self).tearDown()
- def waitForTransaction(self, connection=None):
+ def haveExpectedTxn(self, expected):
+ if self.context["txnMessage"] is not None:
+ txn = self.context["txnMessage"]["dsdbTransaction"]
+ if txn["transactionId"] == expected:
+ return True
+ return False
+
+ def waitForTransaction(self, expected, connection=None):
"""Wait for a transaction message to arrive
The connection is passed through to keep the connection alive
until all the logging messages have been received.
@@ -110,7 +112,7 @@ class AuditLogDsdbTests(AuditLogTestBase):
self.connection = connection
start_time = time.time()
- while self.context["txnMessage"] == "":
+ while not self.haveExpectedTxn(expected):
self.msg_ctx.loop_once(0.1)
if time.time() - start_time > 1:
self.connection = None
@@ -329,55 +331,72 @@ class AuditLogDsdbTests(AuditLogTestBase):
self.ldb.deleteuser(USER_NAME)
- messages = self.waitForMessages(2, dn=dn)
+ messages = self.waitForMessages(1, dn=dn)
print("Received %d messages" % len(messages))
- self.assertEquals(2,
+ self.assertEquals(1,
len(messages),
"Did not receive the expected number of messages")
- audit = messages[1]["dsdbChange"]
+ audit = messages[0]["dsdbChange"]
self.assertEquals("Delete", audit["operation"])
self.assertFalse(audit["performedAsSystem"])
self.assertTrue(dn.lower(), audit["dn"].lower())
self.assertRegexpMatches(audit["remoteAddress"],
self.remoteAddress)
self.assertTrue(self.is_guid(audit["sessionId"]))
+ self.assertEquals(0, audit["statusCode"])
+ self.assertEquals("Success", audit["status"])
session_id = self.get_session()
self.assertEquals(session_id, audit["sessionId"])
service_description = self.get_service_description()
self.assertEquals(service_description, "LDAP")
- def test_net_set_password_user_without_permission(self):
-
- self.ldb.newuser(SECOND_USER_NAME, SECOND_USER_PASS)
+ transactionId = audit["transactionId"]
+ message = self.waitForTransaction(transactionId)
+ audit = message["dsdbTransaction"]
+ self.assertEquals("commit", audit["action"])
+ self.assertTrue(self.is_guid(audit["transactionId"]))
+ self.assertTrue(audit["duration"] > 0)
- creds = self.insta_creds(
- template=self.get_credentials(),
- username=SECOND_USER_NAME,
- userpass=SECOND_USER_PASS,
- kerberos_state=None)
+ def test_samdb_delete_non_existent_dn(self):
- lp = self.get_loadparm()
- net = Net(creds, lp, server=self.server)
- password = "newPassword!!42"
- domain = lp.get("workgroup")
+ DOES_NOT_EXIST = "doesNotExist"
+ dn = "cn=" + USER_NAME + ",cn=users," + self.base_dn
+ self.discardSetupMessages(dn)
- #
- # This operation should fail and trigger a transaction roll back.
- #
+ dn = "cn=" + DOES_NOT_EXIST + ",cn=users," + self.base_dn
try:
- net.set_password(newpassword=password.encode('utf-8'),
- account_name=USER_NAME,
- domain_name=domain)
- self.fail("Expected exception not thrown")
+ self.ldb.delete(dn)
+ self.fail("Exception not thrown")
except Exception:
pass
- message = self.waitForTransaction(net)
+ messages = self.waitForMessages(1)
+ print("Received %d messages" % len(messages))
+ self.assertEquals(1,
+ len(messages),
+ "Did not receive the expected number of messages")
+
+ audit = messages[0]["dsdbChange"]
+ self.assertEquals("Delete", audit["operation"])
+ self.assertFalse(audit["performedAsSystem"])
+ self.assertTrue(dn.lower(), audit["dn"].lower())
+ self.assertRegexpMatches(audit["remoteAddress"],
+ self.remoteAddress)
+ self.assertEquals(ERR_NO_SUCH_OBJECT, audit["statusCode"])
+ self.assertEquals("No such object", audit["status"])
+ self.assertTrue(self.is_guid(audit["sessionId"]))
+ session_id = self.get_session()
+ self.assertEquals(session_id, audit["sessionId"])
+ service_description = self.get_service_description()
+ self.assertEquals(service_description, "LDAP")
+ transactionId = audit["transactionId"]
+ message = self.waitForTransaction(transactionId)
audit = message["dsdbTransaction"]
self.assertEquals("rollback", audit["action"])
self.assertTrue(self.is_guid(audit["transactionId"]))
+ self.assertTrue(audit["duration"] > 0)
def test_create_and_delete_secret_over_lsa(self):
diff --git a/source4/dsdb/samdb/ldb_modules/audit_log.c b/source4/dsdb/samdb/ldb_modules/audit_log.c
index 23b4651..80914cb 100644
--- a/source4/dsdb/samdb/ldb_modules/audit_log.c
+++ b/source4/dsdb/samdb/ldb_modules/audit_log.c
@@ -49,10 +49,8 @@
#define TRANSACTION_HR_TAG "DSDB Transaction"
#define TRANSACTION_MAJOR 1
#define TRANSACTION_MINOR 0
-/*
- * Currently we only log roll backs and prepare commit failures
- */
-#define TRANSACTION_LOG_LVL 5
+#define TRANSACTION_LOG_FAILURE_LVL 5
+#define TRANSACTION_LOG_COMPLETION_LVL 10
#define REPLICATION_JSON_TYPE "replicatedUpdate"
#define REPLICATION_HR_TAG "Replicated Update"
@@ -91,6 +89,11 @@ struct audit_context {
* Unique transaction id for the current transaction
*/
struct GUID transaction_guid;
+ /*
+ * Transaction start time, used to calculate the transaction
+ * duration.
+ */
+ struct timeval transaction_start;
};
/*
@@ -360,12 +363,15 @@ static struct json_object password_change_json(
*
* @param action a one word description of the event/action
* @param transaction_id the GUID identifying the current transaction.
+ * @param status the status code returned by the operation
+ * @param duration the duration of the operation.
*
* @return a JSON object detailing the event
*/
static struct json_object transaction_json(
const char *action,
- struct GUID *transaction_id)
+ struct GUID *transaction_id,
+ const int64_t duration)
{
struct json_object wrapper;
struct json_object audit;
@@ -374,6 +380,8 @@ static struct json_object transaction_json(
json_add_version(&audit, TRANSACTION_MAJOR, TRANSACTION_MINOR);
json_add_string(&audit, "action", action);
json_add_guid(&audit, "transactionId", transaction_id);
+ json_add_int(&audit, "duration", duration);
+
wrapper = json_new_object();
json_add_timestamp(&wrapper);
@@ -396,6 +404,7 @@ static struct json_object transaction_json(
*/
static struct json_object commit_failure_json(
const char *action,
+ const int64_t duration,
int status,
const char *reason,
struct GUID *transaction_id)
@@ -407,6 +416,7 @@ static struct json_object commit_failure_json(
json_add_version(&audit, TRANSACTION_MAJOR, TRANSACTION_MINOR);
json_add_string(&audit, "action", action);
json_add_guid(&audit, "transactionId", transaction_id);
+ json_add_int(&audit, "duration", duration);
json_add_int(&audit, "statusCode", status);
json_add_string(&audit, "status", ldb_strerror(status));
json_add_string(&audit, "reason", reason);
@@ -719,13 +729,14 @@ static char *replicated_update_human_readable(
*
* @param mem_ctx The talloc context owning the returned string.
* @param action a one word description of the event/action
- * @param transaction_id the GUID identifying the current transaction.
+ * @param duration the duration of the transaction.
*
* @return the log entry
*/
static char *transaction_human_readable(
TALLOC_CTX *mem_ctx,
- const char* action)
+ const char* action,
+ const int64_t duration)
{
const char *timestamp = NULL;
char *log_entry = NULL;
@@ -736,9 +747,10 @@ static char *transaction_human_readable(
log_entry = talloc_asprintf(
mem_ctx,
- "[%s] at [%s]",
+ "[%s] at [%s] duration [%ld]",
action,
- timestamp);
+ timestamp,
+ duration);
TALLOC_FREE(ctx);
return log_entry;
@@ -759,6 +771,7 @@ static char *transaction_human_readable(
static char *commit_failure_human_readable(
TALLOC_CTX *mem_ctx,
const char *action,
+ const int64_t duration,
int status,
const char *reason)
{
@@ -771,9 +784,10 @@ static char *commit_failure_human_readable(
log_entry = talloc_asprintf(
mem_ctx,
- "[%s] at [%s] status [%d] reason [%s]",
+ "[%s] at [%s] duration [%ld] status [%d] reason [%s]",
action,
timestamp,
+ duration,
status,
reason);
@@ -976,40 +990,47 @@ static void log_operation(
* and send over the message bus.
*
* @param module the ldb_module
- * @param action the transaction event i.e. begin, commit, roll back.
+ * @param action the transaction event i.e. begin, commit, roll back.
+ * @param log_level the logging level
*
*/
static void log_transaction(
struct ldb_module *module,
- const char *action)
+ const char *action,
+ int log_level)
{
struct audit_context *ac =
talloc_get_type(ldb_module_get_private(module),
struct audit_context);
+ const struct timeval now = timeval_current();
+ const int64_t duration = usec_time_diff(&now, &ac->transaction_start);
TALLOC_CTX *ctx = talloc_new(NULL);
- if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT, TRANSACTION_LOG_LVL)) {
+ if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT, log_level)) {
char* entry = NULL;
- entry = transaction_human_readable(ctx, action);
+ entry = transaction_human_readable(ctx, action, duration);
audit_log_human_text(
TRANSACTION_HR_TAG,
entry,
DBGC_DSDB_TXN_AUDIT,
- TRANSACTION_LOG_LVL);
+ log_level);
TALLOC_FREE(entry);
}
#ifdef HAVE_JANSSON
- if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT_JSON, TRANSACTION_LOG_LVL) ||
+ if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT_JSON, log_level) ||
(ac->msg_ctx && ac->send_samdb_events)) {
struct json_object json;
- json = transaction_json(action, &ac->transaction_guid);
+ json = transaction_json(
+ action,
+ &ac->transaction_guid,
+ duration);
audit_log_json(
TRANSACTION_JSON_TYPE,
&json,
DBGC_DSDB_TXN_AUDIT_JSON,
- TRANSACTION_LOG_LVL);
+ log_level);
if (ac->send_samdb_events) {
audit_message_send(
ac->msg_ctx,
@@ -1044,29 +1065,35 @@ static void log_commit_failure(
talloc_get_type(ldb_module_get_private(module),
struct audit_context);
const char* reason = dsdb_audit_get_ldb_error_string(module, status);
+ const int log_level = TRANSACTION_LOG_FAILURE_LVL;
+ const struct timeval now = timeval_current();
+ const int64_t duration = usec_time_diff(&now, &ac->transaction_start);
TALLOC_CTX *ctx = talloc_new(NULL);
- if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT, TRANSACTION_LOG_LVL)) {
+ if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT, log_level)) {
+
char* entry = NULL;
entry = commit_failure_human_readable(
ctx,
action,
+ duration,
status,
reason);
audit_log_human_text(
TRANSACTION_HR_TAG,
entry,
DBGC_DSDB_TXN_AUDIT,
- TRANSACTION_LOG_LVL);
+ TRANSACTION_LOG_FAILURE_LVL);
TALLOC_FREE(entry);
}
#ifdef HAVE_JANSSON
- if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT_JSON, TRANSACTION_LOG_LVL) ||
+ if (CHECK_DEBUGLVLC(DBGC_DSDB_TXN_AUDIT_JSON, log_level) ||
(ac->msg_ctx && ac->send_samdb_events)) {
struct json_object json;
json = commit_failure_json(
action,
+ duration,
status,
reason,
&ac->transaction_guid);
@@ -1074,7 +1101,7 @@ static void log_commit_failure(
TRANSACTION_JSON_TYPE,
&json,
DBGC_DSDB_TXN_AUDIT_JSON,
- TRANSACTION_LOG_LVL);
+ log_level);
if (ac->send_samdb_events) {
audit_message_send(ac->msg_ctx,
DSDB_EVENT_NAME,
@@ -1361,10 +1388,12 @@ static int log_start_transaction(struct ldb_module *module)
/*
* We do not log transaction begins
- * however we do generate a new transaction_id
+ * however we do generate a new transaction_id and record the start
+ * time so that we can log the transaction duration.
*
*/
ac->transaction_guid = GUID_random();
+ ac->transaction_start = timeval_current();
return ldb_next_start_trans(module);
}
@@ -1410,18 +1439,20 @@ static int log_end_transaction(struct ldb_module *module)
struct audit_context);
int ret = 0;
- /*
- * Clear the transaction id inserted by log_start_transaction
- */
- memset(&ac->transaction_guid, 0, sizeof(struct GUID));
ret = ldb_next_end_trans(module);
- if (ret != LDB_SUCCESS) {
- /*
- * We currently only log commit failures
- */
+ if (ret == LDB_SUCCESS) {
+ log_transaction(
+ module,
+ "commit",
+ TRANSACTION_LOG_COMPLETION_LVL);
+ } else {
log_commit_failure(module, "commit", ret);
}
+ /*
+ * Clear the transaction id inserted by log_start_transaction
+ */
+ memset(&ac->transaction_guid, 0, sizeof(struct GUID));
return ret;
}
@@ -1441,7 +1472,7 @@ static int log_del_transaction(struct ldb_module *module)
talloc_get_type(ldb_module_get_private(module),
struct audit_context);
- log_transaction(module, "rollback");
+ log_transaction(module, "rollback", TRANSACTION_LOG_FAILURE_LVL);
memset(&ac->transaction_guid, 0, sizeof(struct GUID));
return ldb_next_del_trans(module);
}
diff --git a/source4/dsdb/samdb/ldb_modules/tests/test_audit_log.c b/source4/dsdb/samdb/ldb_modules/tests/test_audit_log.c
index 567c5b3..6ceea80 100644
--- a/source4/dsdb/samdb/ldb_modules/tests/test_audit_log.c
+++ b/source4/dsdb/samdb/ldb_modules/tests/test_audit_log.c
@@ -1016,7 +1016,7 @@ static void test_transaction_json(void **state)
GUID_from_string(GUID, &guid);
before = time(NULL);
- json = transaction_json("delete", &guid);
+ json = transaction_json("delete", &guid, 10000099);
assert_int_equal(3, json_object_size(json.root));
@@ -1033,7 +1033,7 @@ static void test_transaction_json(void **state)
audit = json_object_get(json.root, "dsdbTransaction");
assert_non_null(audit);
assert_true(json_is_object(audit));
- assert_int_equal(3, json_object_size(audit));
+ assert_int_equal(4, json_object_size(audit));
o = json_object_get(audit, "version");
assert_non_null(o);
@@ -1049,6 +1049,11 @@ static void test_transaction_json(void **state)
assert_true(json_is_string(v));
assert_string_equal("delete", json_string_value(v));
+ v = json_object_get(audit, "duration");
+ assert_non_null(v);
+ assert_true(json_is_integer(v));
+ assert_int_equal(10000099, json_integer_value(v));
+
json_free(&json);
}
@@ -1074,6 +1079,7 @@ static void test_commit_failure_json(void **state)
before = time(NULL);
json = commit_failure_json(
"prepare",
+ 987876,
LDB_ERR_OPERATIONS_ERROR,
"because",
&guid);
@@ -1093,7 +1099,7 @@ static void test_commit_failure_json(void **state)
audit = json_object_get(json.root, "dsdbTransaction");
assert_non_null(audit);
assert_true(json_is_object(audit));
- assert_int_equal(6, json_object_size(audit));
+ assert_int_equal(7, json_object_size(audit));
o = json_object_get(audit, "version");
assert_non_null(o);
@@ -1126,6 +1132,11 @@ static void test_commit_failure_json(void **state)
assert_true(json_is_string(v));
assert_string_equal("because", json_string_value(v));
+ v = json_object_get(audit, "duration");
+ assert_non_null(v);
+ assert_true(json_is_integer(v));
+ assert_int_equal(987876, json_integer_value(v));
+
json_free(&json);
}
@@ -1829,14 +1840,14 @@ static void test_transaction_hr(void **state)
GUID_from_string(GUID, &guid);
- line = transaction_human_readable(ctx, "delete");
+ line = transaction_human_readable(ctx, "delete", 23);
assert_non_null(line);
/*
* We ignore the timestamp to make this test a little easier
* to write.
*/
- rs = "\\[delete] at \\[[^[]*\\]";
+ rs = "\\[delete] at \\[[^[]*\\] duration \\[23\\]";
ret = regcomp(®ex, rs, 0);
assert_int_equal(0, ret);
@@ -1871,6 +1882,7 @@ static void test_commit_failure_hr(void **state)
line = commit_failure_human_readable(
ctx,
"commit",
+ 789345,
LDB_ERR_OPERATIONS_ERROR,
"because");
@@ -1880,7 +1892,8 @@ static void test_commit_failure_hr(void **state)
* We ignore the timestamp to make this test a little easier
* to write.
*/
- rs = "\\[commit\\] at \\[[^[]*\\] status \\[1\\] reason \\[because\\]";
+ rs = "\\[commit\\] at \\[[^[]*\\] duration \\[789345\\] "
+ "status \\[1\\] reason \\[because\\]";
ret = regcomp(®ex, rs, 0);
assert_int_equal(0, ret);
--
2.7.4
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 473 bytes
Desc: OpenPGP digital signature
URL: <http://lists.samba.org/pipermail/samba-technical/attachments/20180625/3e1e5b7f/signature.sig>
More information about the samba-technical
mailing list