From: Martin Schwenke <martin@meltin.net>
Date: Thu, 23 Sep 2021 08:37:57 +0000 (+1000)
Subject: ctdb-common: Use Samba's DEBUG_FILE logging
X-Git-Tag: tdb-1.4.6~154
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=10d15c9e5dfe4e8595d0b322c96f474fc7078f46;p=thirdparty%2Fsamba.git

ctdb-common: Use Samba's DEBUG_FILE logging

This has support for log rotation (or re-opening).

The log format is updated to use an RFC5424 timestamp and to include a
hostname.  The addition of the hostname allows trivial merging of log
files from multiple cluster nodes.

The hostname is faked from the CTDB_BASE environment variable during
testing, as per the comment in the code.  It is currently faked in a
similar manner in local_daemons.sh when printing logs, so drop this.

Unit tests need updating because stderr logging no longer produces a
"PROGNAME[PID]: " header.

Signed-off-by: Martin Schwenke <martin@meltin.net>
Reviewed-by: Amitay Isaacs <amitay@gmail.com>
---

diff --git a/ctdb/common/logging.c b/ctdb/common/logging.c
index fe8c51aed53..296b4ab590e 100644
--- a/ctdb/common/logging.c
+++ b/ctdb/common/logging.c
@@ -111,50 +111,6 @@ int debug_level_from_string(const char *log_string)
  * file logging backend
  */
 
-struct file_log_state {
-	const char *app_name;
-	int fd;
-	char buffer[1024];
-};
-
-static void file_log(void *private_data, int level, const char *msg)
-{
-	struct file_log_state *state = talloc_get_type_abort(
-		private_data, struct file_log_state);
-	struct timeval tv;
-	struct timeval_buf tvbuf;
-	int ret;
-
-	if (state->fd == STDERR_FILENO) {
-		ret = snprintf(state->buffer, sizeof(state->buffer),
-			       "%s[%u]: %s\n",
-			       state->app_name, (unsigned)getpid(), msg);
-	} else {
-		GetTimeOfDay(&tv);
-		timeval_str_buf(&tv, false, true, &tvbuf);
-
-		ret = snprintf(state->buffer, sizeof(state->buffer),
-			       "%s %s[%u]: %s\n", tvbuf.buf,
-			       state->app_name, (unsigned)getpid(), msg);
-	}
-	if (ret < 0) {
-		return;
-	}
-
-	state->buffer[sizeof(state->buffer)-1] = '\0';
-
-	sys_write_v(state->fd, state->buffer, strlen(state->buffer));
-}
-
-static int file_log_state_destructor(struct file_log_state *state)
-{
-	if (state->fd != -1 && state->fd != STDERR_FILENO) {
-		close(state->fd);
-		state->fd = -1;
-	}
-	return 0;
-}
-
 static bool file_log_validate(const char *option)
 {
 	char *t, *dir;
@@ -185,46 +141,49 @@ static bool file_log_validate(const char *option)
 	return true;
 }
 
-static int file_log_setup(TALLOC_CTX *mem_ctx, const char *option,
+static int file_log_setup(TALLOC_CTX *mem_ctx,
+			  const char *option,
 			  const char *app_name)
 {
-	struct file_log_state *state;
-
-	state = talloc_zero(mem_ctx, struct file_log_state);
-	if (state == NULL) {
-		return ENOMEM;
-	}
-
-	state->app_name = app_name;
+	struct debug_settings settings = {
+		.debug_syslog_format = true,
+		.debug_hires_timestamp = true,
+	};
+	const char *t = NULL;
 
 	if (option == NULL || strcmp(option, "-") == 0) {
-		int ret;
-
-		state->fd = STDERR_FILENO;
-		ret = dup2(STDERR_FILENO, STDOUT_FILENO);
-		if (ret == -1) {
-			int save_errno = errno;
-			talloc_free(state);
-			return save_errno;
-		}
-
-	} else {
-		state->fd = open(option, O_WRONLY|O_APPEND|O_CREAT, 0644);
-		if (state->fd == -1) {
-			int save_errno = errno;
-			talloc_free(state);
-			return save_errno;
-		}
-
-		if (! set_close_on_exec(state->fd)) {
-			int save_errno = errno;
-			talloc_free(state);
-			return save_errno;
+		/*
+		 * Logging to stderr is the default and has already
+		 * been done in logging init
+		 */
+		return 0;
+	}
+
+	/*
+	 * Support logging of fake hostname in local daemons.  This
+	 * hostname is basename(getenv(CTDB_BASE)).
+	 */
+	t = getenv("CTDB_TEST_MODE");
+	if (t != NULL) {
+		t = getenv("CTDB_BASE");
+		if (t != NULL) {
+			const char *p = strrchr(t, '/');
+			if (p != NULL) {
+				p++;
+				if (p[0] == '\0') {
+					p = "unknown";
+				}
+			} else {
+				p = t;
+			}
+
+			debug_set_hostname(p);
 		}
 	}
 
-	talloc_set_destructor(state, file_log_state_destructor);
-	debug_set_callback(state, file_log);
+	debug_set_settings(&settings, "file", 0, false);
+	debug_set_logfile(option);
+	setup_logging(app_name, DEBUG_FILE);
 
 	return 0;
 }
diff --git a/ctdb/tests/UNIT/cunit/sock_daemon_test_001.sh b/ctdb/tests/UNIT/cunit/sock_daemon_test_001.sh
index 54796079941..c1379e8677b 100755
--- a/ctdb/tests/UNIT/cunit/sock_daemon_test_001.sh
+++ b/ctdb/tests/UNIT/cunit/sock_daemon_test_001.sh
@@ -17,112 +17,111 @@ result_filter ()
 {
 	_pid="[0-9][0-9]*"
 	sed -e "s|pid=${_pid}|pid=PID|" \
-	    -e "s|PID ${_pid}|PID PID|" \
-	    -e "s|\[${_pid}\]|[PID]|"
+	    -e "s|PID ${_pid}|PID PID|"
 }
 
 
 ok <<EOF
-test1[PID]: daemon started, pid=PID
-test1[PID]: startup failed, ret=1
-test1[PID]: daemon started, pid=PID
-test1[PID]: startup failed, ret=2
-test1[PID]: daemon started, pid=PID
-test1[PID]: startup completed successfully
-test1[PID]: listening on $sockpath
-test1[PID]: Shutting down
+daemon started, pid=PID
+startup failed, ret=1
+daemon started, pid=PID
+startup failed, ret=2
+daemon started, pid=PID
+startup completed successfully
+listening on $sockpath
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 1
 
 ok <<EOF
-test2[PID]: daemon started, pid=PID
-test2[PID]: startup completed successfully
-test2[PID]: listening on $sockpath
-test2[PID]: Received signal $(sigcode SIGHUP)
-test2[PID]: reconfigure failed, ret=1
-test2[PID]: Received signal $(sigcode SIGUSR1)
-test2[PID]: reconfigure completed successfully
-test2[PID]: Received signal $(sigcode SIGTERM)
-test2[PID]: Shutting down
-test2[PID]: daemon started, pid=PID
-test2[PID]: startup completed successfully
-test2[PID]: listening on $sockpath
-test2[PID]: Received signal $(sigcode SIGUSR1)
-test2[PID]: reconfigure failed, ret=2
-test2[PID]: Received signal $(sigcode SIGHUP)
-test2[PID]: reconfigure completed successfully
-test2[PID]: Received signal $(sigcode SIGTERM)
-test2[PID]: Shutting down
+daemon started, pid=PID
+startup completed successfully
+listening on $sockpath
+Received signal $(sigcode SIGHUP)
+reconfigure failed, ret=1
+Received signal $(sigcode SIGUSR1)
+reconfigure completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
+daemon started, pid=PID
+startup completed successfully
+listening on $sockpath
+Received signal $(sigcode SIGUSR1)
+reconfigure failed, ret=2
+Received signal $(sigcode SIGHUP)
+reconfigure completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 2
 
 ok <<EOF
-test3[PID]: daemon started, pid=PID
-test3[PID]: listening on $sockpath
-test3[PID]: PID PID gone away, exiting
-test3[PID]: Shutting down
+daemon started, pid=PID
+listening on $sockpath
+PID PID gone away, exiting
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 3
 
 ok <<EOF
-test4[PID]: daemon started, pid=PID
-test4[PID]: Shutting down
+daemon started, pid=PID
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 4
 
 ok <<EOF
-test5[PID]: daemon started, pid=PID
-test5[PID]: listening on $sockpath
-test5[PID]: Received signal $(sigcode SIGTERM)
-test5[PID]: Shutting down
+daemon started, pid=PID
+listening on $sockpath
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 5
 
 ok <<EOF
-test6[PID]: daemon started, pid=PID
-test6[PID]: listening on $sockpath
-test6[PID]: Shutting down
+daemon started, pid=PID
+listening on $sockpath
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 6
 
 ok <<EOF
-test7[PID]: daemon started, pid=PID
-test7[PID]: startup completed successfully
-test7[PID]: Received signal $(sigcode SIGTERM)
-test7[PID]: Shutting down
+daemon started, pid=PID
+startup completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 7
 
 ok <<EOF
-test8[PID]: daemon started, pid=PID
-test8[PID]: startup completed successfully
-test8[PID]: Received signal $(sigcode SIGTERM)
-test8[PID]: Shutting down
-test8[PID]: daemon started, pid=PID
-test8[PID]: startup completed successfully
-test8[PID]: Received signal $(sigcode SIGTERM)
-test8[PID]: Shutting down
+daemon started, pid=PID
+startup completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
+daemon started, pid=PID
+startup completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 8
 
 ok <<EOF
-test9[PID]: daemon started, pid=PID
-test9[PID]: startup completed successfully
-test9[PID]: Received signal $(sigcode SIGTERM)
-test9[PID]: Shutting down
-test9[PID]: daemon started, pid=PID
-test9[PID]: startup completed successfully
-test9[PID]: Received signal $(sigcode SIGTERM)
-test9[PID]: Shutting down
+daemon started, pid=PID
+startup completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
+daemon started, pid=PID
+startup completed successfully
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 9
 
 ok <<EOF
-test10[PID]: daemon started, pid=PID
-test10[PID]: listening on $sockpath
-test10[PID]: daemon started, pid=PID
-test10[PID]: listening on $sockpath
-test10[PID]: Received signal $(sigcode SIGTERM)
-test10[PID]: Shutting down
+daemon started, pid=PID
+listening on $sockpath
+daemon started, pid=PID
+listening on $sockpath
+Received signal $(sigcode SIGTERM)
+Shutting down
 EOF
 unit_test sock_daemon_test "$pidfile" "$sockpath" 10
diff --git a/ctdb/tests/UNIT/eventd/eventd_051.sh b/ctdb/tests/UNIT/eventd/eventd_051.sh
index 2932b16c4ad..c00cb2e79e0 100755
--- a/ctdb/tests/UNIT/eventd/eventd_051.sh
+++ b/ctdb/tests/UNIT/eventd/eventd_051.sh
@@ -10,6 +10,6 @@ ok_null
 simple_test run 10 random verbose
 
 ok <<EOF
-ctdb-eventd[PID]: 02.enabled: Running event verbose
+02.enabled: Running event verbose
 EOF
 unit_test grep "02.enabled:" "$eventd_logfile"
diff --git a/ctdb/tests/UNIT/eventd/scripts/local.sh b/ctdb/tests/UNIT/eventd/scripts/local.sh
index 9b8ebf18074..04cce63b9e4 100644
--- a/ctdb/tests/UNIT/eventd/scripts/local.sh
+++ b/ctdb/tests/UNIT/eventd/scripts/local.sh
@@ -118,6 +118,5 @@ result_filter ()
 	_pid="[0-9][0-9]*"
 	sed -e "s#${_duration}#DURATION#" \
 	    -e "s#${_datetime}#DATETIME#" \
-	    -e "s#,${_pid}#,PID#" \
-	    -e "s#\[${_pid}\]#[PID]#"
+	    -e "s#,${_pid}#,PID#"
 }
diff --git a/ctdb/tests/local_daemons.sh b/ctdb/tests/local_daemons.sh
index 7a633950a8b..626cc192876 100755
--- a/ctdb/tests/local_daemons.sh
+++ b/ctdb/tests/local_daemons.sh
@@ -427,14 +427,7 @@ local_daemons_print_log ()
 
 	# shellcheck disable=SC2016
 	# $CTDB_BASE must only be expanded under onnode, not in top-level shell
-	onnode -q "$_nodes" 'echo ${CTDB_BASE}/log.ctdb' |
-	while IFS='' read -r _l ; do
-		_dir=$(dirname "$_l")
-		_node=$(basename "$_dir")
-		# Add fake hostname after date and time, which are the
-		# first 2 words on each line
-		sed -e "s|^\\([^ ][^ ]* [^ ][^ ]*\\)|\\1 ${_node}|" "$_l"
-	done |
+	onnode -q "$_nodes" 'cat ${CTDB_BASE}/log.ctdb' |
 	sort
 
 }