s4:dsdb Rework partitions module for better tracing

This means we need to create a fake 'module' which only has a 'next'
pointer, so that we can now ldb_next_request() (which incorporates
tracing).  The remainaing stub of partition_request() is retained so
that we can indicate which partition an operation is destined for.

Similar tracing is added to the transaction handlers.

Andrew Bartlett

3 files changed, 76 insertions, 97 deletions

diff --git a/source4/dsdb/samdb/ldb_modules/partition.c b/source4/dsdb/samdb/ldb_modules/partition.c
index c6f6f6a5f3..a36ab3a7d9 100644
--- a/source4/dsdb/samdb/ldb_modules/partition.c
+++ b/source4/dsdb/samdb/ldb_modules/partition.c
@@ -68,48 +68,23 @@ static struct partition_context *partition_init_ctx(struct ldb_module *module, s
 
 int partition_request(struct ldb_module *module, struct ldb_request *request)
 {
-	int ret;
-	switch (request->operation) {
-	case LDB_SEARCH:
-		PARTITION_FIND_OP(module, search);
-		ret = module->ops->search(module, request);
-		break;
-	case LDB_ADD:
-		PARTITION_FIND_OP(module, add);
-		ret = module->ops->add(module, request);
-		break;
-	case LDB_MODIFY:
-		PARTITION_FIND_OP(module, modify);
-		ret = module->ops->modify(module, request);
-		break;
-	case LDB_DELETE:
-		PARTITION_FIND_OP(module, del);
-		ret = module->ops->del(module, request);
-		break;
-	case LDB_RENAME:
-		PARTITION_FIND_OP(module, rename);
-		ret = module->ops->rename(module, request);
-		break;
-	case LDB_EXTENDED:
-		PARTITION_FIND_OP(module, extended);
-		ret = module->ops->extended(module, request);
-		break;
-	default:
-		PARTITION_FIND_OP(module, request);
-		ret = module->ops->request(module, request);
-		break;
-	}
-	if (ret == LDB_SUCCESS) {
-		return ret;
-	}
-	if (!ldb_errstring(ldb_module_get_ctx(module))) {
-		/* Set a default error string, to place the blame somewhere */
-		ldb_asprintf_errstring(ldb_module_get_ctx(module),
-					"error in module %s: %s (%d)",
-					module->ops->name,
-					ldb_strerror(ret), ret);
+	if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) { \
+		const struct dsdb_control_current_partition *partition = NULL;
+		struct ldb_control *partition_ctrl = ldb_request_get_control(request, DSDB_CONTROL_CURRENT_PARTITION_OID);
+		if (partition_ctrl) {
+			partition = talloc_get_type(partition_ctrl->data,
+						    struct dsdb_control_current_partition);
+		}
+
+		if (partition != NULL) {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_request() -> %s", 
+				  ldb_dn_get_linearized(partition->dn));			
+		} else {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_request() -> (metadata partition)");			
+		}
 	}
-	return ret;
+
+	return ldb_next_request(module, request);
 }
 
 static struct dsdb_partition *find_partition(struct partition_private_data *data,
@@ -358,9 +333,9 @@ static int partition_prep_request(struct partition_context *ac,
 		}
 
 	} else {
-		/* make sure you put the NEXT module here, or
-		 * partition_request() will simply loop forever on itself */
-		ac->part_req[ac->num_requests].module = ac->module->next;
+		/* make sure you put the module here, or
+		 * or ldb_next_request() will skip a module */
+		ac->part_req[ac->num_requests].module = ac->module;
 	}
 
 	ac->num_requests++;
@@ -414,7 +389,7 @@ static int partition_replicate(struct ldb_module *module, struct ldb_request *re
 		return ldb_next_request(module, req);
 	}
 
-	if (req->operation != LDB_SEARCH) {
+	if (req->operation != LDB_SEARCH && ldb_dn_is_special(dn)) {
 		/* Is this a special DN, we need to replicate to every backend? */
 		for (i=0; data->replicate && data->replicate[i]; i++) {
 			if (ldb_dn_compare(data->replicate[i], 
@@ -663,6 +638,9 @@ static int partition_start_trans(struct ldb_module *module)
 	/* Look at base DN */
 	/* Figure out which partition it is under */
 	/* Skip the lot if 'data' isn't here yet (initialization) */
+	if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+		ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_start_trans() -> (metadata partition)");
+	}
 	ret = ldb_next_start_trans(module);
 	if (ret != LDB_SUCCESS) {
 		return ret;
@@ -674,17 +652,15 @@ static int partition_start_trans(struct ldb_module *module)
 	}
 
 	for (i=0; data && data->partitions && data->partitions[i]; i++) {
-		struct ldb_module *next = data->partitions[i]->module;
-		PARTITION_FIND_OP(next, start_transaction);
-
-		ret = next->ops->start_transaction(next);
+		if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_start_trans() -> %s", 
+				  ldb_dn_get_linearized(data->partitions[i]->ctrl->dn));
+		}
+		ret = ldb_next_start_trans(data->partitions[i]->module);
 		if (ret != LDB_SUCCESS) {
 			/* Back it out, if it fails on one */
 			for (i--; i >= 0; i--) {
-				next = data->partitions[i]->module;
-				PARTITION_FIND_OP(next, del_transaction);
-
-				next->ops->del_transaction(next);
+				ldb_next_del_trans(data->partitions[i]->module);
 			}
 			ldb_next_del_trans(module);
 			return ret;
@@ -704,20 +680,22 @@ static int partition_prepare_commit(struct ldb_module *module)
 							      struct partition_private_data);
 
 	for (i=0; data && data->partitions && data->partitions[i]; i++) {
-		struct ldb_module *next_prepare = data->partitions[i]->module;
 		int ret;
 
-		PARTITION_FIND_OP_NOERROR(next_prepare, prepare_commit);
-		if (next_prepare == NULL) {
-			continue;
+		if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_prepare_commit() -> %s", 
+				  ldb_dn_get_linearized(data->partitions[i]->ctrl->dn));
 		}
-
-		ret = next_prepare->ops->prepare_commit(next_prepare);
+		ret = ldb_next_prepare_commit(data->partitions[i]->module);
 		if (ret != LDB_SUCCESS) {
+			ldb_asprintf_errstring(module->ldb, "prepare_commit error on %s: %s", ldb_dn_get_linearized(data->partitions[i]->ctrl->dn), ldb_errstring(module->ldb));
 			return ret;
 		}
 	}
 
+	if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+		ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_prepare_commit() -> (metadata partition)");
+	}
 	return ldb_next_prepare_commit(module);
 }
 
@@ -729,13 +707,15 @@ static int partition_end_trans(struct ldb_module *module)
 	struct partition_private_data *data = talloc_get_type(module->private_data, 
 							      struct partition_private_data);
 	for (i=0; data && data->partitions && data->partitions[i]; i++) {
-		struct ldb_module *next_end = data->partitions[i]->module;
 		int ret;
 
-		PARTITION_FIND_OP(next_end, end_transaction);
-
-		ret = next_end->ops->end_transaction(next_end);
+		if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_end_trans() -> %s", 
+				  ldb_dn_get_linearized(data->partitions[i]->ctrl->dn));
+		}
+		ret = ldb_next_end_trans(data->partitions[i]->module);
 		if (ret != LDB_SUCCESS) {
+			ldb_asprintf_errstring(module->ldb, "end_trans error on %s: %s", ldb_dn_get_linearized(data->partitions[i]->ctrl->dn), ldb_errstring(module->ldb));
 			return ret;
 		}
 	}
@@ -746,6 +726,9 @@ static int partition_end_trans(struct ldb_module *module)
 	}
 	data->in_transaction--;
 
+	if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+		ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_end_trans() -> (metadata partition)");
+	}
 	return ldb_next_end_trans(module);
 }
 
@@ -756,11 +739,13 @@ static int partition_del_trans(struct ldb_module *module)
 	struct partition_private_data *data = talloc_get_type(module->private_data, 
 							      struct partition_private_data);
 	for (i=0; data && data->partitions && data->partitions[i]; i++) {
-		struct ldb_module *next = data->partitions[i]->module;
-		PARTITION_FIND_OP(next, del_transaction);
-
-		ret = next->ops->del_transaction(next);
+		if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+			ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_del_trans() -> %s", 
+				  ldb_dn_get_linearized(data->partitions[i]->ctrl->dn));
+		}
+		ret = ldb_next_del_trans(data->partitions[i]->module);
 		if (ret != LDB_SUCCESS) {
+			ldb_asprintf_errstring(module->ldb, "del_trans error on %s: %s", ldb_dn_get_linearized(data->partitions[i]->ctrl->dn), ldb_errstring(module->ldb));
 			final_ret = ret;
 		}
 	}	
@@ -771,6 +756,9 @@ static int partition_del_trans(struct ldb_module *module)
 	}
 	data->in_transaction--;
 
+	if ((module && module->ldb->flags & LDB_FLG_ENABLE_TRACING)) {
+		ldb_debug(module->ldb, LDB_DEBUG_TRACE, "partition_del_trans() -> (metadata partition)");
+	}
 	ret = ldb_next_del_trans(module);
 	if (ret != LDB_SUCCESS) {
 		final_ret = ret;
diff --git a/source4/dsdb/samdb/ldb_modules/partition.h b/source4/dsdb/samdb/ldb_modules/partition.h
index dda0b86515..81c98f4767 100644
--- a/source4/dsdb/samdb/ldb_modules/partition.h
+++ b/source4/dsdb/samdb/ldb_modules/partition.h
@@ -48,17 +48,4 @@ struct partition_private_data {
 	uint32_t in_transaction;
 };
 
-#define PARTITION_FIND_OP_NOERROR(module, op) do { \
-        while (module && module->ops->op == NULL) module = module->next; \
-} while (0)
-
-#define PARTITION_FIND_OP(module, op) do { \
-	PARTITION_FIND_OP_NOERROR(module, op); \
-        if (module == NULL) { \
-                ldb_asprintf_errstring(ldb_module_get_ctx(module), \
-			"Unable to find backend operation for " #op ); \
-                return LDB_ERR_OPERATIONS_ERROR; \
-        } \
-} while (0)
-
 #include "dsdb/samdb/ldb_modules/partition_proto.h"
diff --git a/source4/dsdb/samdb/ldb_modules/partition_init.c b/source4/dsdb/samdb/ldb_modules/partition_init.c
index 5967bc8159..d3400f8e08 100644
--- a/source4/dsdb/samdb/ldb_modules/partition_init.c
+++ b/source4/dsdb/samdb/ldb_modules/partition_init.c
@@ -188,6 +188,7 @@ static int new_partition_from_dn(struct ldb_context *ldb, struct partition_priva
 	const char *backend_url;
 	struct dsdb_control_current_partition *ctrl;
 	struct ldb_module *backend_module;
+	struct ldb_module *module_chain;
 	const char **modules;
 	int ret;
 
@@ -261,7 +262,7 @@ static int new_partition_from_dn(struct ldb_context *ldb, struct partition_priva
 		talloc_free(*partition);
 		return LDB_ERR_CONSTRAINT_VIOLATION;
 	}
-	ret = ldb_load_modules_list(ldb, modules, backend_module, &(*partition)->module);
+	ret = ldb_load_modules_list(ldb, modules, backend_module, &module_chain);
 	if (ret != LDB_SUCCESS) {
 		ldb_asprintf_errstring(ldb, 
 				       "partition_init: "
@@ -270,7 +271,7 @@ static int new_partition_from_dn(struct ldb_context *ldb, struct partition_priva
 		talloc_free(*partition);
 		return ret;
 	}
-	ret = ldb_init_module_chain(ldb, (*partition)->module);
+	ret = ldb_init_module_chain(ldb, module_chain);
 	if (ret != LDB_SUCCESS) {
 		ldb_asprintf_errstring(ldb,
 				       "partition_init: "
@@ -280,16 +281,24 @@ static int new_partition_from_dn(struct ldb_context *ldb, struct partition_priva
 		return ret;
 	}
 
-	talloc_steal((*partition), (*partition)->module);
+	/* This weirdness allows us to use ldb_next_request() in partition.c */
+	(*partition)->module = ldb_module_new(*partition, ldb, "partition_next", NULL);
+	if (!(*partition)->module) {
+		ldb_oom(ldb);
+		talloc_free(*partition);
+		return LDB_ERR_OPERATIONS_ERROR;
+	}
+	(*partition)->module->next = talloc_steal((*partition)->module, module_chain);
 
 	/* if we were in a transaction then we need to start a
 	   transaction on this new partition, otherwise we'll get a
 	   transaction mismatch when we end the transaction */
 	if (data->in_transaction) {
-		struct ldb_module *next = (*partition)->module;
-		PARTITION_FIND_OP(next, start_transaction);
-
-		ret = next->ops->start_transaction(next);
+		if (ldb->flags & LDB_FLG_ENABLE_TRACING) {
+			ldb_debug(ldb, LDB_DEBUG_TRACE, "partition_start_trans() -> %s (new partition)", 
+				  ldb_dn_get_linearized((*partition)->ctrl->dn));
+		}
+		ret = ldb_next_start_trans((*partition)->module);
 	}
 
 	return ret;
@@ -409,7 +418,6 @@ int partition_reload_if_required(struct ldb_module *module,
 		DATA_BLOB dn_blob;
 		struct ldb_dn *dn;
 		struct dsdb_partition *partition;
-		struct ldb_module tmp_module;
 		struct ldb_result *dn_res;
 		const char *no_attrs[] = { NULL };
 
@@ -470,12 +478,8 @@ int partition_reload_if_required(struct ldb_module *module,
 			return ret;
 		}
 
-		/* Hack to be able to re-use dsdb_module_search_dn, which calls ldb_next_request(), which needs ->next filled out */
-		tmp_module = *partition->module;
-		tmp_module.next = partition->module;
-		
 		/* Get the 'correct' case of the partition DNs from the database */
-		ret = dsdb_module_search_dn(&tmp_module, data, &dn_res, 
+		ret = dsdb_module_search_dn(partition->module, data, &dn_res, 
 					    dn, no_attrs);
 		if (ret == LDB_SUCCESS) {
 			talloc_free(partition->ctrl->dn);
@@ -541,7 +545,7 @@ static int new_partition_set_replicated_metadata(struct ldb_context *ldb,
 			return ret;
 		}
 		/* do request */
-		ret = partition_request(partition->module, add_req);
+		ret = ldb_next_request(partition->module, add_req);
 		/* wait */
 		if (ret == LDB_SUCCESS) {
 			ret = ldb_wait(add_req->handle, LDB_WAIT_ALL);
@@ -568,7 +572,7 @@ static int new_partition_set_replicated_metadata(struct ldb_context *ldb,
 				return ret;
 			}
 			/* do request */
-			ret = partition_request(partition->module, del_req);
+			ret = ldb_next_request(partition->module, del_req);
 			
 			/* wait */
 			if (ret == LDB_SUCCESS) {
@@ -595,7 +599,7 @@ static int new_partition_set_replicated_metadata(struct ldb_context *ldb,
 			}
 			
 			/* do the add again */
-			ret = partition_request(partition->module, add_req);
+			ret = ldb_next_request(partition->module, add_req);
 			
 			/* wait */
 			if (ret == LDB_SUCCESS) {
@@ -694,7 +698,7 @@ int partition_create(struct ldb_module *module, struct ldb_request *req)
 		
 		last_req = mod_req;
 
-		ret = partition_request(module, mod_req);
+		ret = ldb_next_request(module, mod_req);
 		if (ret == LDB_SUCCESS) {
 			ret = ldb_wait(mod_req->handle, LDB_WAIT_ALL);
 		}