eventscript: ctdb_fork_with_logging()

A new helper functions which sets up an event attached to the child's
stdout/stderr which gets routed to the logging callback after being
placed in the normal logs.

This is a generalization of the previous code which was hardcoded to
call ctdb_log_event_script_output.

The only subtlety is that we hang the child fds off the output buffer;
the destructor for that will flush, which means it has to be destroyed
before the output buffer is.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>


(This used to be ctdb commit 32cfdc3aec34272612f43a3588e4cabed9c85b68)

3 files changed, 113 insertions, 34 deletions

diff --git a/ctdb/include/ctdb_private.h b/ctdb/include/ctdb_private.h
index f03ac20957..2bf4f48e51 100644
--- a/ctdb/include/ctdb_private.h
+++ b/ctdb/include/ctdb_private.h
@@ -1536,6 +1536,10 @@ struct ctdb_get_log_addr {
 
 int32_t ctdb_control_get_log(struct ctdb_context *ctdb, TDB_DATA addr);
 int32_t ctdb_control_clear_log(struct ctdb_context *ctdb);
+struct ctdb_log_state *ctdb_fork_with_logging(TALLOC_CTX *mem_ctx,
+					      struct ctdb_context *ctdb,
+					      void (*logfn)(const char *, uint16_t, void *),
+					      void *logfn_private, pid_t *pid);
 
 int32_t ctdb_control_process_exists(struct ctdb_context *ctdb, pid_t pid);
 struct ctdb_client *ctdb_find_client_by_pid(struct ctdb_context *ctdb, pid_t pid);
diff --git a/ctdb/server/ctdb_logging.c b/ctdb/server/ctdb_logging.c
index 37d1b60bf0..7dadbfd776 100644
--- a/ctdb/server/ctdb_logging.c
+++ b/ctdb/server/ctdb_logging.c
@@ -159,6 +159,8 @@ struct ctdb_log_state {
 	char buf[1024];
 	uint16_t buf_used;
 	bool use_syslog;
+	void (*logfn)(const char *, uint16_t, void *);
+	void *logfn_private;
 };
 
 /* we need this global to keep the DEBUG() syntax */
@@ -349,7 +351,17 @@ int ctdb_set_logfile(struct ctdb_context *ctdb, const char *logfile, bool use_sy
 	return 0;
 }
 
-
+/* Note that do_debug always uses the global log state. */
+static void write_to_log(struct ctdb_log_state *log,
+			 const char *buf, unsigned int len)
+{
+	if (script_log_level <= LogLevel) {
+		do_debug("%*.*s\n", len, len, buf);
+		/* log it in the eventsystem as well */
+		if (log->logfn)
+			log->logfn(log->buf, len, log->logfn_private);
+	}
+}
 
 /*
   called when log data comes in from a child process
@@ -381,11 +393,7 @@ static void ctdb_log_handler(struct event_context *ev, struct fd_event *fde,
 		if (n2 > 0 && log->buf[n2-1] == '\r') {
 			n2--;
 		}
-		if (script_log_level <= LogLevel) {
-			do_debug("%*.*s\n", n2, n2, log->buf);
-			/* log it in the eventsystem as well */
-			ctdb_log_event_script_output(log->ctdb, log->buf, n2);
-		}
+		write_to_log(log, log->buf, n2);
 		memmove(log->buf, p+1, sizeof(log->buf) - n1);
 		log->buf_used -= n1;
 	}
@@ -393,17 +401,91 @@ static void ctdb_log_handler(struct event_context *ev, struct fd_event *fde,
 	/* the buffer could have completely filled - unfortunately we have
 	   no choice but to dump it out straight away */
 	if (log->buf_used == sizeof(log->buf)) {
-		if (script_log_level <= LogLevel) {
-			do_debug("%*.*s\n", 
-				(int)log->buf_used, (int)log->buf_used, log->buf);
-			/* log it in the eventsystem as well */
-			ctdb_log_event_script_output(log->ctdb, log->buf, log->buf_used);
-		}
+		write_to_log(log, log->buf, log->buf_used);
 		log->buf_used = 0;
 	}
 }
 
+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;
+}
+
+/*
+   fork(), redirecting child output to logging and specified callback.
+*/
+struct ctdb_log_state *ctdb_fork_with_logging(TALLOC_CTX *mem_ctx,
+					      struct ctdb_context *ctdb,
+					      void (*logfn)(const char *, uint16_t, void *),
+					      void *logfn_private, pid_t *pid)
+{
+	int p[2];
+	int old_stdout, old_stderr;
+	int saved_errno;
+	struct ctdb_log_state *log;
+
+	log = talloc_zero(mem_ctx, struct ctdb_log_state);
+	CTDB_NO_MEMORY_NULL(ctdb, log);
+	log->ctdb = ctdb;
+	log->logfn = logfn;
+	log->logfn_private = (void *)logfn_private;
+
+	if (pipe(p) != 0) {
+		DEBUG(DEBUG_ERR,(__location__ " Failed to setup for child logging pipe\n"));
+		goto free_log;
+	}
+
+	/* We'll fail if stderr/stdout not already open; it's simpler. */
+	old_stdout = dup(STDOUT_FILENO);
+	old_stderr = dup(STDERR_FILENO);
+	if (dup2(p[1], STDOUT_FILENO) < 0 || dup2(p[1], STDERR_FILENO) < 0) {
+		DEBUG(DEBUG_ERR,(__location__ " Failed to setup output for child\n"));
+		goto close_pipe;
+	}
+	close(p[1]);
+
+	*pid = fork();
+
+	/* Child? */
+	if (*pid == 0) {
+		close(old_stdout);
+		close(old_stderr);
+		close(p[0]);
+		return log;
+	}
 
+	saved_errno = errno;
+	dup2(STDOUT_FILENO, old_stdout);
+	dup2(STDERR_FILENO, old_stderr);
+	close(old_stdout);
+	close(old_stderr);
+
+	/* We failed? */
+	if (*pid < 0) {
+		DEBUG(DEBUG_ERR, (__location__ " fork failed for child process\n"));
+		close(p[0]);
+		errno = saved_errno;
+		goto free_log;
+	}
+
+	log->pfd = p[0];
+	talloc_set_destructor(log, log_context_destructor);
+	event_add_fd(ctdb->ev, log, log->pfd, EVENT_FD_READ,
+		     ctdb_log_handler, log);
+	return log;
+
+close_pipe:
+	close(p[0]);
+	close(p[1]);
+free_log:
+	talloc_free(log);
+	return NULL;
+}
 
 /*
   setup for logging of child process stdout
diff --git a/ctdb/server/eventscript.c b/ctdb/server/eventscript.c
index 6e54c65495..34c6056b78 100644
--- a/ctdb/server/eventscript.c
+++ b/ctdb/server/eventscript.c
@@ -101,26 +101,12 @@ struct ctdb_monitor_script_status {
 /* called from ctdb_logging when we have received output on STDERR from
  * one of the eventscripts
  */
-int ctdb_log_event_script_output(struct ctdb_context *ctdb, char *str, uint16_t len)
+static void log_event_script_output(const char *str, uint16_t len, void *p)
 {
-	struct ctdb_monitor_script_status *script;
-
-	if (ctdb->current_monitor == NULL) {
-		return -1;
-	}
+	struct ctdb_monitor_script_status *script =
+		talloc_get_type(p, struct ctdb_monitor_script_status);
 
-	script = ctdb->current_monitor->scripts;
-	if (script == NULL) {
-		return -1;
-	}
-
-	if (script->output == NULL) {
-		script->output = talloc_asprintf(script, "%*.*s", len, len, str);
-	} else {
-		script->output = talloc_asprintf_append(script->output, "%*.*s", len, len, str);
-	}
-
-	return 0;
+	script->output = talloc_asprintf_append(script->output, "%*.*s", len, len, str);
 }
 
 /* starting a new monitor event */
@@ -158,6 +144,8 @@ static int32_t ctdb_control_event_script_start(struct ctdb_context *ctdb, const
 	script->next  = ctdb->current_monitor->scripts;
 	script->name  = talloc_strdup(script, name);
 	CTDB_NO_MEMORY(ctdb, script->name);
+	script->output = talloc_strdup(script, "");
+	CTDB_NO_MEMORY(ctdb, script->output);
 	script->start = timeval_current();
 	ctdb->current_monitor->scripts = script;
 
@@ -536,9 +524,15 @@ static int fork_child_for_script(struct ctdb_context *ctdb,
 				 struct ctdb_event_script_state *state)
 {
 	int r;
+	void *mem_ctx = state;
+	void (*logfn)(const char *, uint16_t, void *) = NULL;
 
 	if (!state->from_user && state->call == CTDB_EVENT_MONITOR) {
 		ctdb_control_event_script_start(ctdb, state->script_list->name);
+		/* We need the logging destroyed after scripts, since it
+		 * refers to them. */
+		mem_ctx = state->scripts->output;
+		logfn = log_event_script_output;
 	}
 
 	r = pipe(state->fd);
@@ -547,16 +541,15 @@ static int fork_child_for_script(struct ctdb_context *ctdb,
 		return -errno;
 	}
 
-	state->child = fork();
-
-	if (state->child == (pid_t)-1) {
+	if (!ctdb_fork_with_logging(mem_ctx, ctdb, logfn,
+				    state->scripts, &state->child)) {
 		r = -errno;
-		DEBUG(DEBUG_ERR, (__location__ " fork failed for child eventscript process\n"));
 		close(state->fd[0]);
 		close(state->fd[1]);
 		return r;
 	}
 
+	/* If we are the child, do the work. */
 	if (state->child == 0) {
 		int rt;