[SCM] Samba Shared Repository - branch master updated
Andrew Bartlett
abartlet at samba.org
Mon Jun 25 09:17:02 UTC 2018
The branch, master has been updated
via b282bcb dsdb: Log the transaction duraton.
via 1bb2a1c auth: For NTLM and KDC authentication, log the authentication duration
from 05b54cc talloc_stack: Call talloc destructors while frame is still around
https://git.samba.org/?p=samba.git;a=shortlog;h=master
- Log -----------------------------------------------------------------
commit b282bcbb759bbb12797922e066aeb12c0df5b2f1
Author: Gary Lockyer <gary at catalyst.net.nz>
Date: Wed Jun 6 15:30:44 2018 +0200
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>
Reviewed-by: Andrew Bartlett <abartlet at samba.org>
Autobuild-User(master): Andrew Bartlett <abartlet at samba.org>
Autobuild-Date(master): Mon Jun 25 11:16:18 CEST 2018 on sn-devel-144
commit 1bb2a1c6b3eaccf114ac3f3b5b51f57828a04996
Author: Andrew Bartlett <abartlet at samba.org>
Date: Sun Jun 10 13:00:34 2018 +0200
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>
Reviewed-by: Gary Lockyer <gary at catalyst.net.nz>
-----------------------------------------------------------------------
Summary of changes:
auth/auth_log.c | 23 +++++-
auth/common_auth.h | 4 +
python/samba/tests/audit_log_base.py | 13 +--
python/samba/tests/audit_log_dsdb.py | 83 +++++++++++--------
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 +
source4/dsdb/samdb/ldb_modules/audit_log.c | 95 ++++++++++++++--------
source4/dsdb/samdb/ldb_modules/password_hash.c | 1 +
.../dsdb/samdb/ldb_modules/tests/test_audit_log.c | 25 ++++--
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 +
17 files changed, 203 insertions(+), 78 deletions(-)
Changeset truncated at 500 lines:
diff --git a/auth/auth_log.c b/auth/auth_log.c
index 369a5c9..67d23c1 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 3de227e..d8377eb 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/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/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..d13d0fe 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..0facb86 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..3a3fa7e 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 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/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);
--
Samba Shared Repository
More information about the samba-cvs
mailing list