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 fe8c51aed5300af37018a171487d1dbc0ef27101..296b4ab590e1b2543c1324616c26492182669b11 100644 (file)
--- 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 54796079941bbe9f818aac15021d00e975f5158e..c1379e8677bcfd08ba334a5bcd8d470722988728 100755 (executable)
--- 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 2932b16c4ad5d31e1bff7d7641301dd75516b28a..c00cb2e79e08d29ecd93c4fd5d6b64f5b0493724 100755 (executable)
--- 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 9b8ebf18074c254785d9231245722cc7080c9202..04cce63b9e428983d61b1757a2c1a9141abeaa21 100644 (file)
--- 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 7a633950a8be9f370b00e68fd13c0fe82404646a..626cc192876975c0bc591f82a1417c4cd5f833bf 100755 (executable)
--- 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
 
 }