s4-ldb: don't show timestamps on every line of ldb traces

This adds ldb_debug_add() and ldb_debug_end() to format multiline
messages

5 files changed, 100 insertions, 64 deletions

diff --git a/source4/lib/ldb/common/ldb.c b/source4/lib/ldb/common/ldb.c
index 02298c1dff..e93560e559 100644
--- a/source4/lib/ldb/common/ldb.c
+++ b/source4/lib/ldb/common/ldb.c
@@ -633,78 +633,82 @@ static void ldb_trace_request(struct ldb_context *ldb, struct ldb_request *req)
 
 	switch (req->operation) {
 	case LDB_SEARCH:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: SEARCH");
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " dn: %s",
+		ldb_debug_add(ldb, "ldb_trace_request: SEARCH\n");
+		ldb_debug_add(ldb, " dn: %s\n",
 			  ldb_dn_get_linearized(req->op.search.base));
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " scope: %s", 
+		ldb_debug_add(ldb, " scope: %s\n", 
 			  req->op.search.scope==LDB_SCOPE_BASE?"base":
 			  req->op.search.scope==LDB_SCOPE_ONELEVEL?"one":
 			  req->op.search.scope==LDB_SCOPE_SUBTREE?"sub":"UNKNOWN");
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " expr: %s", 
+		ldb_debug_add(ldb, " expr: %s\n", 
 			  ldb_filter_from_tree(tmp_ctx, req->op.search.tree));
 		if (req->op.search.attrs == NULL) {
-			ldb_debug(ldb, LDB_DEBUG_TRACE, " attr: <ALL>");
+			ldb_debug_add(ldb, " attr: <ALL>\n");
 		} else {
 			for (i=0; req->op.search.attrs[i]; i++) {
-				ldb_debug(ldb, LDB_DEBUG_TRACE, " attr: %s", req->op.search.attrs[i]);
+				ldb_debug_add(ldb, " attr: %s\n", req->op.search.attrs[i]);
 			}
 		}
 		break;
 	case LDB_DELETE:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: DELETE");
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " dn: %s", 
-			  ldb_dn_get_linearized(req->op.del.dn));
+		ldb_debug_add(ldb, "ldb_trace_request: DELETE\n");
+		ldb_debug_add(ldb, " dn: %s\n", 
+			      ldb_dn_get_linearized(req->op.del.dn));
 		break;
 	case LDB_RENAME:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: RENAME");
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " olddn: %s", 
-			  ldb_dn_get_linearized(req->op.rename.olddn));
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " newdn: %s", 
-			  ldb_dn_get_linearized(req->op.rename.newdn));
+		ldb_debug_add(ldb, "ldb_trace_request: RENAME\n");
+		ldb_debug_add(ldb, " olddn: %s\n", 
+			      ldb_dn_get_linearized(req->op.rename.olddn));
+		ldb_debug_add(ldb, " newdn: %s\n", 
+			      ldb_dn_get_linearized(req->op.rename.newdn));
 		break;
 	case LDB_EXTENDED:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: EXTENDED");
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " oid: %s", req->op.extended.oid);
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " data: %s", req->op.extended.data?"yes":"no");
+		ldb_debug_add(ldb, "ldb_trace_request: EXTENDED\n");
+		ldb_debug_add(ldb, " oid: %s\n", req->op.extended.oid);
+		ldb_debug_add(ldb, " data: %s\n", req->op.extended.data?"yes":"no");
 		break;
 	case LDB_ADD:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: ADD");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "%s", 
-			  ldb_ldif_message_string(req->handle->ldb, tmp_ctx, 
-						  LDB_CHANGETYPE_ADD, req->op.add.message));
+		ldb_debug_add(ldb, "ldb_trace_request: ADD\n");
+		ldb_debug_add(req->handle->ldb, "%s\n", 
+			      ldb_ldif_message_string(req->handle->ldb, tmp_ctx, 
+						      LDB_CHANGETYPE_ADD, 
+						      req->op.add.message));
 		break;
 	case LDB_MODIFY:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: MODIFY");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "%s", 
-			  ldb_ldif_message_string(req->handle->ldb, tmp_ctx, 
-						  LDB_CHANGETYPE_ADD, req->op.mod.message));
+		ldb_debug_add(ldb, "ldb_trace_request: MODIFY\n");
+		ldb_debug_add(req->handle->ldb, "%s\n", 
+			      ldb_ldif_message_string(req->handle->ldb, tmp_ctx, 
+						      LDB_CHANGETYPE_ADD, 
+						      req->op.mod.message));
 		break;
 	case LDB_REQ_REGISTER_CONTROL:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: REGISTER_CONTROL");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "%s", 
-			  req->op.reg_control.oid);
+		ldb_debug_add(ldb, "ldb_trace_request: REGISTER_CONTROL\n");
+		ldb_debug_add(req->handle->ldb, "%s\n", 
+			      req->op.reg_control.oid);
 		break;
 	case LDB_REQ_REGISTER_PARTITION:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: REGISTER_PARTITION");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "%s", 
-			  ldb_dn_get_linearized(req->op.reg_partition.dn));
+		ldb_debug_add(ldb, "ldb_trace_request: REGISTER_PARTITION\n");
+		ldb_debug_add(req->handle->ldb, "%s\n", 
+			      ldb_dn_get_linearized(req->op.reg_partition.dn));
 		break;
 	default:
-		ldb_debug(ldb, LDB_DEBUG_TRACE, "ldb_trace_request: UNKNOWN(%u)", 
-			  req->operation);
+		ldb_debug_add(ldb, "ldb_trace_request: UNKNOWN(%u)\n", 
+			      req->operation);
 		break;
 	}
 
 	if (req->controls == NULL) {
-		ldb_debug(ldb, LDB_DEBUG_TRACE, " control: <NONE>");
+		ldb_debug_add(ldb, " control: <NONE>\n");
 	} else {
 		for (i=0; req->controls && req->controls[i]; i++) {
-			ldb_debug(ldb, LDB_DEBUG_TRACE, " control: %s  crit:%u  data:%s", 
-				  req->controls[i]->oid, 
-				  req->controls[i]->critical, 
-				  req->controls[i]->data?"yes":"no");
+			ldb_debug_add(ldb, " control: %s  crit:%u  data:%s\n", 
+				      req->controls[i]->oid, 
+				      req->controls[i]->critical, 
+				      req->controls[i]->data?"yes":"no");
 		}
 	}
+	
+	ldb_debug_end(ldb, LDB_DEBUG_TRACE);
 
 	talloc_free(tmp_ctx);
 }
diff --git a/source4/lib/ldb/common/ldb_debug.c b/source4/lib/ldb/common/ldb_debug.c
index 4612b016f6..6aa58ccf71 100644
--- a/source4/lib/ldb/common/ldb_debug.c
+++ b/source4/lib/ldb/common/ldb_debug.c
@@ -96,6 +96,31 @@ void ldb_debug(struct ldb_context *ldb, enum ldb_debug_level level, const char *
 	va_end(ap);
 }
 
+/*
+  add to an accumulated log message
+ */
+void ldb_debug_add(struct ldb_context *ldb, const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	if (ldb->partial_debug == NULL) {
+		ldb->partial_debug = talloc_vasprintf(ldb, fmt, ap);
+	} else {
+		ldb->partial_debug = talloc_vasprintf_append(ldb->partial_debug, 
+							     fmt, ap);
+	}
+	va_end(ap);
+}
+
+/*
+  send the accumulated log message, and free it
+ */
+void ldb_debug_end(struct ldb_context *ldb, enum ldb_debug_level level)
+{
+	ldb_debug(ldb, level, "%s", ldb->partial_debug);
+	talloc_free(ldb->partial_debug);
+	ldb->partial_debug = NULL;
+}
 
 /*
   log a message, and set the ldb error string to the same message
diff --git a/source4/lib/ldb/common/ldb_modules.c b/source4/lib/ldb/common/ldb_modules.c
index c57d0e407d..997d373653 100644
--- a/source4/lib/ldb/common/ldb_modules.c
+++ b/source4/lib/ldb/common/ldb_modules.c
@@ -1,4 +1,4 @@
-/* 
+/*
    ldb database library
 
    Copyright (C) Simo Sorce  2004-2008
@@ -6,7 +6,7 @@
      ** NOTE! The following LGPL license applies to the ldb
      ** library. This does NOT imply that all of Samba is released
      ** under the LGPL
-   
+
    This library is free software; you can redistribute it and/or
    modify it under the terms of the GNU Lesser General Public
    License as published by the Free Software Foundation; either
@@ -127,7 +127,7 @@ static struct backends_list_entry {
 
 static struct ops_list_entry {
 	const struct ldb_module_ops *ops;
-	struct ops_list_entry *next;	
+	struct ops_list_entry *next;
 } *registered_modules = NULL;
 
 static const struct ldb_builtins {
@@ -264,9 +264,9 @@ static const struct ldb_module_ops *ldb_find_module_ops(const char *name)
 		if (strcmp(builtins[i].module_ops->name, name) == 0)
 			return builtins[i].module_ops;
 	}
- 
+
 	for (e = registered_modules; e; e = e->next) {
- 		if (strcmp(e->ops->name, name) == 0) 
+ 		if (strcmp(e->ops->name, name) == 0)
 			return e->ops;
 	}
 
@@ -301,7 +301,7 @@ static void *ldb_dso_load_symbol(struct ldb_context *ldb, const char *name,
 	if (ldb->modules_dir == NULL)
 		return NULL;
 
-	path = talloc_asprintf(ldb, "%s/%s.%s", ldb->modules_dir, name, 
+	path = talloc_asprintf(ldb, "%s/%s.%s", ldb->modules_dir, name,
 			       SHLIBEXT);
 
 	ldb_debug(ldb, LDB_DEBUG_TRACE, "trying to load %s from %s", name, path);
@@ -328,7 +328,7 @@ int ldb_load_modules_list(struct ldb_context *ldb, const char **module_list, str
 {
 	struct ldb_module *module;
 	int i;
-	
+
 	module = backend;
 
 	for (i = 0; module_list[i] != NULL; i++) {
@@ -338,10 +338,10 @@ int ldb_load_modules_list(struct ldb_context *ldb, const char **module_list, str
 		if (strcmp(module_list[i], "") == 0) {
 			continue;
 		}
-		
+
 		ops = ldb_find_module_ops(module_list[i]);
 		if (ops == NULL) {
-			char *symbol_name = talloc_asprintf(ldb, "ldb_%s_module_ops", 
+			char *symbol_name = talloc_asprintf(ldb, "ldb_%s_module_ops",
 												module_list[i]);
 			if (symbol_name == NULL) {
 				return LDB_ERR_OPERATIONS_ERROR;
@@ -349,31 +349,31 @@ int ldb_load_modules_list(struct ldb_context *ldb, const char **module_list, str
 			ops = ldb_dso_load_symbol(ldb, module_list[i], symbol_name);
 			talloc_free(symbol_name);
 		}
-		
+
 		if (ops == NULL) {
 			ldb_debug(ldb, LDB_DEBUG_WARNING, "WARNING: Module [%s] not found",
 				  module_list[i]);
 			continue;
 		}
-		
+
 		current = talloc_zero(ldb, struct ldb_module);
 		if (current == NULL) {
 			return LDB_ERR_OPERATIONS_ERROR;
 		}
 		talloc_set_name(current, "ldb_module: %s", module_list[i]);
-		
+
 		current->ldb = ldb;
 		current->ops = ops;
-		
+
 		DLIST_ADD(module, current);
 	}
 	*out = module;
 	return LDB_SUCCESS;
 }
 
-int ldb_init_module_chain(struct ldb_context *ldb, struct ldb_module *module) 
+int ldb_init_module_chain(struct ldb_context *ldb, struct ldb_module *module)
 {
-	while (module && module->ops->init_context == NULL) 
+	while (module && module->ops->init_context == NULL)
 		module = module->next;
 
 	/* init is different in that it is not an error if modules
@@ -412,7 +412,7 @@ int ldb_load_modules(struct ldb_context *ldb, const char *options[])
 	}
 
 	/* if not overloaded by options and the backend is not ldap try to load the modules list from ldb */
-	if ((modules == NULL) && (strcmp("ldap", ldb->modules->ops->name) != 0)) { 
+	if ((modules == NULL) && (strcmp("ldap", ldb->modules->ops->name) != 0)) {
 		const char * const attrs[] = { "@LIST" , NULL};
 		struct ldb_result *res = NULL;
 		struct ldb_dn *mods_dn;
@@ -424,7 +424,7 @@ int ldb_load_modules(struct ldb_context *ldb, const char *options[])
 		}
 
 		ret = ldb_search(ldb, mods_dn, &res, mods_dn, LDB_SCOPE_BASE, attrs, "@LIST=*");
-		
+
 		if (ret == LDB_ERR_NO_SUCH_OBJECT) {
 			ldb_debug(ldb, LDB_DEBUG_TRACE, "no modules required by the db");
 		} else if (ret != LDB_SUCCESS) {
@@ -584,7 +584,7 @@ int ldb_next_request(struct ldb_module *module, struct ldb_request *request)
 		 * guarantees we will end up hanging in
 		 * ldb_wait(). This fixes it without having to rewrite
 		 * all our modules, and leaves us one less sharp
-		 * corner for module developers to cut themselves on 
+		 * corner for module developers to cut themselves on
 		 */
 		ldb_module_done(request, NULL, NULL, ret);
 	}
@@ -674,10 +674,11 @@ int ldb_module_send_entry(struct ldb_request *req,
 
 	if (req->handle->ldb->flags & LDB_FLG_ENABLE_TRACING) {
 		char *s;
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "ldb_trace_response: ENTRY");
+		ldb_debug_add(req->handle->ldb, "ldb_trace_response: ENTRY\n");
 		s = ldb_ldif_message_string(req->handle->ldb, msg, LDB_CHANGETYPE_NONE, msg);
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "%s", s);
-		talloc_free(s);			  
+		ldb_debug_add(req->handle->ldb, "%s\n", s);
+		talloc_free(s);
+		ldb_debug_end(req->handle->ldb, LDB_DEBUG_TRACE);
 	}
 
 	return req->callback(req, ares);
@@ -706,8 +707,9 @@ int ldb_module_send_referral(struct ldb_request *req,
 	ares->error = LDB_SUCCESS;
 
 	if (req->handle->ldb->flags & LDB_FLG_ENABLE_TRACING) {
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "ldb_trace_response: REFERRAL");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "ref: %s", ref);
+		ldb_debug_add(req->handle->ldb, "ldb_trace_response: REFERRAL\n");
+		ldb_debug_add(req->handle->ldb, "ref: %s\n", ref);
+		ldb_debug_end(req->handle->ldb, LDB_DEBUG_TRACE);
 	}
 
 	return req->callback(req, ares);
@@ -743,12 +745,13 @@ int ldb_module_done(struct ldb_request *req,
 	req->handle->flags |= LDB_HANDLE_FLAG_DONE_CALLED;
 
 	if (req->handle->ldb->flags & LDB_FLG_ENABLE_TRACING) {
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "ldb_trace_response: DONE");
-		ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "error: %u", error);
+		ldb_debug_add(req->handle->ldb, "ldb_trace_response: DONE\n");
+		ldb_debug_add(req->handle->ldb, "error: %u\n", error);
 		if (ldb_errstring(req->handle->ldb)) {
-			ldb_debug(req->handle->ldb, LDB_DEBUG_TRACE, "msg: %s", 
+			ldb_debug_add(req->handle->ldb, "msg: %s\n",
 				  ldb_errstring(req->handle->ldb));
 		}
+		ldb_debug_end(req->handle->ldb, LDB_DEBUG_TRACE);
 	}
 
 	req->callback(req, ares);
diff --git a/source4/lib/ldb/include/ldb_module.h b/source4/lib/ldb/include/ldb_module.h
index 199c0bb40d..ae8c4d50df 100644
--- a/source4/lib/ldb/include/ldb_module.h
+++ b/source4/lib/ldb/include/ldb_module.h
@@ -64,6 +64,8 @@ struct ldb_module_ops {
 void ldb_debug(struct ldb_context *ldb, enum ldb_debug_level level, const char *fmt, ...) PRINTF_ATTRIBUTE(3, 4);
 void ldb_debug_set(struct ldb_context *ldb, enum ldb_debug_level level, 
 		   const char *fmt, ...) PRINTF_ATTRIBUTE(3, 4);
+void ldb_debug_add(struct ldb_context *ldb, const char *fmt, ...) PRINTF_ATTRIBUTE(2, 3);
+void ldb_debug_end(struct ldb_context *ldb, enum ldb_debug_level level);
 
 #define ldb_oom(ldb) ldb_debug_set(ldb, LDB_DEBUG_FATAL, "ldb out of memory at %s:%d\n", __FILE__, __LINE__)
 
diff --git a/source4/lib/ldb/include/ldb_private.h b/source4/lib/ldb/include/ldb_private.h
index 1fb3109b1b..b78cef969a 100644
--- a/source4/lib/ldb/include/ldb_private.h
+++ b/source4/lib/ldb/include/ldb_private.h
@@ -116,6 +116,8 @@ struct ldb_context {
 	struct tevent_context *ev_ctx;
 
 	bool prepare_commit_done;
+
+	char *partial_debug;
 };
 
 /* The following definitions come from lib/ldb/common/ldb.c  */