ctdb-logging: Update to use Samba style debug.h/debug.c

Samba's debug subsystem has changed a lot, so CTDB's logging needs
to be rewritten to be compatible.

The new debug.h/debug.c can't just be pulled in because it has some
extra dependencies into Samba's lib/util.  For now, to support the
smallest possible patch, implement a minimal subset of Samba's
debug.[ch] that just supports the DEBUG_CALLBACK logtype.

Define a callback for each logging method.

Check later to see if debug_extra (or similar) can somehow be
implemented using debug classes.

The timestamp on CTDB CLI tool and test program DEBUG() output goes
away, so update the unit test code to cope.

Signed-off-by: Martin Schwenke <martin@meltin.net>
Reviewed-by: Volker Lendecke <vl@samba.org>

6 files changed, 92 insertions, 146 deletions

diff --git a/ctdb/common/ctdb_logging.c b/ctdb/common/ctdb_logging.c
index bf67f096b54..9b5103a20dd 100644
--- a/ctdb/common/ctdb_logging.c
+++ b/ctdb/common/ctdb_logging.c
@@ -23,8 +23,6 @@
 #include "../include/ctdb_private.h"
 #include "../include/ctdb_client.h"
 
-int DEBUGLEVEL = DEBUG_NOTICE;
-int this_log_level = 0;
 const char *debug_extra = "";
 
 struct debug_levels debug_levels[] = {
diff --git a/ctdb/include/ctdb_logging.h b/ctdb/include/ctdb_logging.h
index f6f904aeade..c0c02660051 100644
--- a/ctdb/include/ctdb_logging.h
+++ b/ctdb/include/ctdb_logging.h
@@ -20,8 +20,6 @@
 #ifndef _CTDB_LOGGING_H_
 #define _CTDB_LOGGING_H_
 
-extern int DEBUGLEVEL;
-extern int this_log_level;
 extern const char *debug_extra;
 
 enum debug_level {
@@ -35,8 +33,4 @@ enum debug_level {
 	DEBUG_DEBUG   =  4,
 };
 
-#define DEBUGLVL(lvl) ((lvl) <= DEBUGLEVEL)
-#define DEBUG(lvl, x) do { this_log_level = (lvl); if ((lvl) <= DEBUGLEVEL) { do_debug x; }} while (0)
-#define DEBUGADD(lvl, x) do { if ((lvl) <= DEBUGLEVEL) { this_log_level = (lvl); do_debug_add x; }} while (0)
-
 #endif /* _CTDB_LOGGING_H_ */
diff --git a/ctdb/lib/tdb_wrap/tdb_wrap.c b/ctdb/lib/tdb_wrap/tdb_wrap.c
index f39ac7a0911..57f8efc4e9f 100644
--- a/ctdb/lib/tdb_wrap/tdb_wrap.c
+++ b/ctdb/lib/tdb_wrap/tdb_wrap.c
@@ -50,12 +50,19 @@ static void log_fn(struct tdb_context *tdb, enum tdb_debug_level level, const ch
 {
 	if (level <= TDB_DEBUG_ERROR) {
 		va_list ap;
-		char newfmt[strlen(tdb_name(tdb)) + 1 + strlen(fmt) + 1];
-		this_log_level = level;
-		sprintf(newfmt, "%s:%s", tdb_name(tdb), fmt);
+		char *ptr = NULL;
+		int ret;
+
 		va_start(ap, fmt);
-		do_debug_v(newfmt, ap);
+		ret = vasprintf(&ptr, fmt, ap);
 		va_end(ap);
+
+		if (ret != -1) {
+			const char *name = tdb_name(tdb);
+			DEBUG(level,
+			      ("%s:%s", name ? name : "unnamed tdb", ptr));
+			free(ptr);
+		}
 	}
 }
 
diff --git a/ctdb/lib/util/debug.c b/ctdb/lib/util/debug.c
index 40dda1a70a5..e15944403da 100644
--- a/ctdb/lib/util/debug.c
+++ b/ctdb/lib/util/debug.c
@@ -17,78 +17,13 @@
    along with this program; if not, see <http://www.gnu.org/licenses/>.
 */
 
-#include "includes.h"
-#include "system/time.h"
-#include <unistd.h>
+#include "replace.h"
+#include "system/filesys.h"
 #include <ctype.h>
+#include <assert.h>
+#include "debug.h"
 
-static void _do_debug_v(const char *format, va_list ap)
-{
-	struct timeval t;
-	char *s = NULL;
-	struct tm *tm;
-	char tbuf[100];
-	int ret;
-
-	ret = vasprintf(&s, format, ap);
-	if (ret == -1) {
-		fprintf(stderr, "vasprintf failed in _do_debug_v, cannot print debug message.\n");
-		fflush(stderr);
-		return;
-	}
-
-	t = timeval_current();
-	tm = localtime(&t.tv_sec);
-
-	strftime(tbuf,sizeof(tbuf)-1,"%Y/%m/%d %H:%M:%S", tm);
-
-	fprintf(stderr, "%s.%06u [%s%5u]: %s", tbuf, (unsigned)t.tv_usec,
-		debug_extra, (unsigned)getpid(), s);
-	fflush(stderr);
-	free(s);
-}
-
-/* default logging function */
-void (*do_debug_v)(const char *, va_list ap) = _do_debug_v;
-
-void do_debug(const char *format, ...)
-{
-	va_list ap;
-
-	va_start(ap, format);
-	do_debug_v(format, ap);
-	va_end(ap);
-}
-
-
-static void _do_debug_add_v(const char *format, va_list ap)
-{
-	char *s = NULL;
-	int ret;
-
-	ret = vasprintf(&s, format, ap);
-	if (ret == -1) {
-		fprintf(stderr, "vasprintf failed in _do_debug_add_v, cannot print debug message.\n");
-		fflush(stderr);
-		return;
-	}
-
-	fprintf(stderr, "%s", s);
-	fflush(stderr);
-	free(s);
-}
-
-/* default logging function */
-void (*do_debug_add_v)(const char *, va_list ap) = _do_debug_add_v;
-
-void do_debug_add(const char *format, ...)
-{
-	va_list ap;
-
-	va_start(ap, format);
-	do_debug_add_v(format, ap);
-	va_end(ap);
-}
+int DEBUGLEVEL;
 
 static void print_asc(int level, const uint8_t *buf, size_t len)
 {
@@ -133,3 +68,48 @@ void dump_data(int level, const uint8_t *buf, size_t len)
 	DEBUG(level, (__location__ " dump data of size %i finished\n", (int)len));
 }
 
+/* state variables for the debug system */
+static struct {
+	debug_callback_fn callback;
+	void *callback_private;
+} state;
+
+static int current_msg_level = 0;
+
+void debug_set_callback(void *private_ptr, debug_callback_fn fn)
+{
+	assert(fn != NULL);
+
+	state.callback_private = private_ptr;
+	state.callback = fn;
+}
+
+bool dbghdr(int level, const char *location, const char *func)
+{
+	current_msg_level = level;
+	return true;
+}
+
+bool dbgtext( const char *format_str, ... )
+{
+	va_list ap;
+	char *msgbuf = NULL;
+	int res;
+
+	va_start(ap, format_str);
+	res = vasprintf(&msgbuf, format_str, ap);
+	va_end(ap);
+	if (res == -1) {
+		return false;
+	}
+
+	if (state.callback != NULL) {
+		state.callback(state.callback_private,
+			       current_msg_level, msgbuf);
+	} else {
+		write(2, msgbuf, strlen(msgbuf));
+	}
+
+	free(msgbuf);
+	return true;
+}
diff --git a/ctdb/lib/util/debug.h b/ctdb/lib/util/debug.h
index a590bc0f843..ac5e2c77cfa 100644
--- a/ctdb/lib/util/debug.h
+++ b/ctdb/lib/util/debug.h
@@ -20,10 +20,20 @@
 #ifndef UTIL_DEBUG_H
 #define UTIL_DEBUG_H
 
-extern void (*do_debug_v)(const char *, va_list ap);
-extern void (*do_debug_add_v)(const char *, va_list ap);
-void do_debug(const char *format, ...) PRINTF_ATTRIBUTE(1, 2);
-void do_debug_add(const char *format, ...) PRINTF_ATTRIBUTE(1, 2);
+bool dbgtext( const char *, ... ) PRINTF_ATTRIBUTE(1,2);
+bool dbghdr( int level, const char *location, const char *func);
 void dump_data(int level, const uint8_t *buf1, size_t len);
 
+extern int DEBUGLEVEL;
+
+#define DEBUGLVL(lvl) ((lvl) <= DEBUGLEVEL)
+#define DEBUG( lvl, body ) \
+  (void)( ((lvl) <= DEBUGLEVEL) \
+       && (dbghdr( lvl, __location__, __FUNCTION__ )) \
+       && (dbgtext body) )
+#define DEBUGADD(lvl, body) DEBUG(lvl, body)
+
+typedef void (*debug_callback_fn)(void *private_ptr, int level, const char *msg);
+void debug_set_callback(void *private_ptr, debug_callback_fn fn);
+
 #endif /* UTIL_DEBUG_H */
diff --git a/ctdb/server/ctdb_logging.c b/ctdb/server/ctdb_logging.c
index 97cc3beda6f..3aba37b81d5 100644
--- a/ctdb/server/ctdb_logging.c
+++ b/ctdb/server/ctdb_logging.c
@@ -23,6 +23,7 @@
 #include "system/syslog.h"
 #include "system/time.h"
 #include "system/filesys.h"
+#include "lib/util/debug.h"
 
 struct syslog_message {
 	uint32_t level;
@@ -208,21 +209,15 @@ static struct ctdb_log_state *log_state;
 /*
   syslog logging function
  */
-static void ctdb_syslog_log(const char *format, va_list ap)
+static void ctdb_syslog_log(void *private_ptr, int dbglevel, const char *s)
 {
 	struct syslog_message *msg;
 	int level = LOG_DEBUG;
-	char *s = NULL;
-	int len, ret;
+	int len;
 	int syslog_fd;
 	struct sockaddr_in syslog_sin;
 
-	ret = vasprintf(&s, format, ap);
-	if (ret == -1) {
-		return;
-	}
-
-	switch (this_log_level) {
+	switch (dbglevel) {
 	case DEBUG_EMERG: 
 		level = LOG_EMERG; 
 		break;
@@ -252,7 +247,6 @@ static void ctdb_syslog_log(const char *format, va_list ap)
 	len = offsetof(struct syslog_message, message) + strlen(debug_extra) + strlen(s) + 1;
 	msg = malloc(len);
 	if (msg == NULL) {
-		free(s);
 		return;
 	}
 	msg->level = level;
@@ -266,7 +260,6 @@ static void ctdb_syslog_log(const char *format, va_list ap)
 		syslog_fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);
 		if (syslog_fd == -1) {
 			printf("Failed to create syslog socket\n");
-			free(s);
 			free(msg);
 			return;
 		}
@@ -275,15 +268,14 @@ static void ctdb_syslog_log(const char *format, va_list ap)
 		syslog_sin.sin_port   = htons(CTDB_PORT);
 		syslog_sin.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
 
-		ret = sendto(syslog_fd, msg, len, 0,
-			     (struct sockaddr *)&syslog_sin,
-			     sizeof(syslog_sin));
+		(void) sendto(syslog_fd, msg, len, 0,
+			      (struct sockaddr *)&syslog_sin,
+			      sizeof(syslog_sin));
 		/* no point in checking here since we cant log an error */
 
 		close(syslog_fd);
 	}
 
-	free(s);
 	free(msg);
 }
 
@@ -291,23 +283,14 @@ static void ctdb_syslog_log(const char *format, va_list ap)
 /*
   log file logging function
  */
-static void ctdb_logfile_log(const char *format, va_list ap)
+static void ctdb_logfile_log(void *private_ptr, int dbglevel, const char *s)
 {
 	struct timeval t;
-	char *s = NULL;
 	struct tm *tm;
 	char tbuf[100];
 	char *s2 = NULL;
 	int ret;
 
-	ret = vasprintf(&s, format, ap);
-	if (ret == -1) {
-		const char *errstr = "vasprintf failed\n";
-
-		sys_write(log_state->fd, errstr, strlen(errstr));
-		return;
-	}
-
 	t = timeval_current();
 	tm = localtime(&t.tv_sec);
 
@@ -316,7 +299,6 @@ static void ctdb_logfile_log(const char *format, va_list ap)
 	ret = asprintf(&s2, "%s.%06u [%s%5u]: %s",
 		       tbuf, (unsigned)t.tv_usec,
 		       debug_extra, (unsigned)getpid(), s);
-	free(s);
 	if (ret == -1) {
 		const char *errstr = "asprintf failed\n";
 		sys_write(log_state->fd, errstr, strlen(errstr));
@@ -328,32 +310,12 @@ static void ctdb_logfile_log(const char *format, va_list ap)
 	}
 }
 
-static void ctdb_logfile_log_add(const char *format, va_list ap)
-{
-	char *s = NULL;
-	int ret;
-
-	ret = vasprintf(&s, format, ap);
-	if (ret == -1) {
-		const char *errstr = "vasprintf failed\n";
-
-		sys_write(log_state->fd, errstr, strlen(errstr));
-		return;
-	}
-
-	if (s) {
-		sys_write(log_state->fd, s, strlen(s));
-		free(s);
-	}
-}
-
-
-
 /*
   choose the logfile location
 */
 int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_syslog)
 {
+	debug_callback_fn callback;
 	int ret;
 
 	ctdb->log = talloc_zero(ctdb, struct ctdb_log_state);
@@ -366,12 +328,10 @@ int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_sy
 	log_state = ctdb->log;
 
 	if (use_syslog) {
-		do_debug_v = ctdb_syslog_log;
-		do_debug_add_v = ctdb_syslog_log;
+		callback = ctdb_syslog_log;
 		ctdb->log->use_syslog = true;
 	} else if (logfile == NULL || strcmp(logfile, "-") == 0) {
-		do_debug_v = ctdb_logfile_log;
-		do_debug_add_v = ctdb_logfile_log_add;
+		callback = ctdb_logfile_log;
 		ctdb->log->fd = 1;
 		/* also catch stderr of subcommands to stdout */
 		ret = dup2(1, 2);
@@ -380,8 +340,7 @@ int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_sy
 			abort();
 		}
 	} else {
-		do_debug_v = ctdb_logfile_log;
-		do_debug_add_v = ctdb_logfile_log_add;
+		callback = ctdb_logfile_log;
 
 		ctdb->log->fd = open(logfile, O_WRONLY|O_APPEND|O_CREAT, 0666);
 		if (ctdb->log->fd == -1) {
@@ -390,6 +349,8 @@ int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_sy
 		}
 	}
 
+	debug_set_callback(NULL, callback);
+
 	return 0;
 }
 
@@ -399,9 +360,9 @@ static void write_to_log(struct ctdb_log_state *log,
 {
 	if (script_log_level <= DEBUGLEVEL) {
 		if (log != NULL && log->prefix != NULL) {
-			do_debug("%s: %*.*s\n", log->prefix, len, len, buf);
+			dbgtext("%s: %*.*s\n", log->prefix, len, len, buf);
 		} else {
-			do_debug("%*.*s\n", len, len, buf);
+			dbgtext("%*.*s\n", len, len, buf);
 		}
 		/* log it in the eventsystem as well */
 		if (log && log->logfn) {
@@ -435,8 +396,6 @@ static void ctdb_log_handler(struct event_context *ev, struct fd_event *fde,
 		return;
 	}
 
-	this_log_level = script_log_level;
-
 	while (log->buf_used > 0 &&
 	       (p = memchr(log->buf, '\n', log->buf_used)) != NULL) {
 		int n1 = (p - log->buf)+1;
@@ -462,7 +421,6 @@ static int log_context_destructor(struct ctdb_log_state *log)
 {
 	/* Flush buffer in case it wasn't \n-terminated. */
 	if (log->buf_used > 0) {
-		this_log_level = script_log_level;
 		write_to_log(log, log->buf, log->buf_used);
 	}
 	return 0;
@@ -629,8 +587,7 @@ static void ctdb_tevent_logging(void *private_data,
 	}
 
 	if (lvl <= DEBUGLEVEL) {
-		this_log_level = lvl;
-		do_debug_v(fmt, ap);
+		dbgtext(fmt, ap);
 	}
 }