[Tarantool-patches] [PATCH 06/13] popen: decouple logger fd from stderr

[Alexander Turenko]

The default logger configuration writes logs to stderr.

Popen implementation holds a logger fd until execve() to be able to
write debug entries or information about a failure from a child. However
when popen flags requires to close stderr in the child, the logger fd
becomes closed: logging will fail.

Another problem appears when a user want to capture stderr and
tarantool's log level is set to debug (7). Since the logger uses stderr
and it is fed to the parent using a pipe, the logger output will not
shown on the 'real' stderr, but will be captured together with child's
program debugging output.

This commit duplicates a logger file descriptor that allows to close or
redirect child's stderr without described side effects.

See also 86ec3a5c4792ea1bba9f644da1e8f301314c8d29 ('popen: add logging
in child process').

Areas for improvements:

* Copy logger fd at module initialization time instead of copying of
  each popen call.

Alternatives:

* Extend logger to allow to accumulate log entries in a buffer. Flush
  the buffer from the parent process. (It is possible since vfork does
  not split a virtual memory space).

Part of #4031
---
 src/lib/core/popen.c | 124 +++++++++++++++++++++++++++++++++++++++----
 1 file changed, 115 insertions(+), 9 deletions(-)

diff --git a/src/lib/core/popen.c b/src/lib/core/popen.c
index 9d4e6ef3a..62920e0c8 100644
--- a/src/lib/core/popen.c
+++ b/src/lib/core/popen.c
@@ -74,6 +74,59 @@ popen_unregister(struct popen_handle *handle)
 	mh_i32ptr_remove(popen_pids_map, &node, NULL);
 }
 
+/**
+ * Duplicate a file descriptor, but not to std{in,out,err}.
+ *
+ * Return a new fd at success, otherwise return -1 and set a diag.
+ */
+static int
+dup_not_std_streams(int fd)
+{
+	int res = -1;
+	int save_errno = 0;
+
+	/*
+	 * We will call dup() in a loop until it will return
+	 * fd > STDERR_FILENO. The array `discarded_fds` stores
+	 * intermediate fds to close them after all dup() calls.
+	 */
+	static_assert(STDERR_FILENO + 1 == 3,
+		      "Unexpected STDERR_FILENO constant");
+	int discarded_fds[STDERR_FILENO + 1] = {-1, -1, -1};
+
+	for (size_t i = 0; i < lengthof(discarded_fds) + 1; ++i) {
+		int new_fd = dup(fd);
+		if (new_fd < 0) {
+			save_errno = errno;
+			break;
+		}
+
+		/* Found wanted fd. */
+		if (new_fd > STDERR_FILENO) {
+			res = new_fd;
+			break;
+		}
+
+		/* Save to close then. */
+		assert(i < lengthof(discarded_fds));
+		discarded_fds[i] = new_fd;
+	}
+
+	/* Close all intermediate fds (if any). */
+	for (size_t i = 0; i < lengthof(discarded_fds); ++i)
+		if (discarded_fds[i] >= 0)
+			close(discarded_fds[i]);
+
+	/* Report an error if it occurs. */
+	if (res < 0) {
+		errno = save_errno;
+		diag_set(SystemError, "Unable to duplicate an fd %d", fd);
+		return -1;
+	}
+
+	return res;
+}
+
 /**
  * Allocate new popen hanldle with flags specified.
  */
@@ -746,9 +799,34 @@ popen_new(struct popen_opts *opts)
 	 * plus dev/null variants and logfd
 	 */
 	int skip_fds[POPEN_FLAG_FD_STDEND_BIT * 2 + 2 + 1];
-	int log_fd = log_get_fd();
 	size_t nr_skip_fds = 0;
 
+	/*
+	 * We must decouple log file descriptor from stderr in order to
+	 * close or redirect stderr, but keep logging as is until
+	 * execve() call.
+	 *
+	 * The new file descriptor should not have the same number as
+	 * stdin, stdout or stderr.
+	 *
+	 * NB: It is better to acquire it from the parent to catch
+	 * possible error sooner and don't ever call vfork() if we
+	 * reached a file descriptor limit.
+	 */
+	int old_log_fd = log_get_fd();
+	int log_fd = -1;
+	if (old_log_fd >= 0) {
+		log_fd = dup_not_std_streams(old_log_fd);
+		if (log_fd < 0)
+			return NULL;
+		if (fcntl(log_fd, F_SETFL, O_CLOEXEC) != 0) {
+			diag_set(SystemError,
+				 "Unable to set O_CLOEXEC on temporary logfd");
+			close(log_fd);
+			return NULL;
+		}
+	}
+
 	/*
 	 * A caller must preserve space for this.
 	 */
@@ -771,8 +849,11 @@ popen_new(struct popen_opts *opts)
 		      "Popen flags do not match stdX");
 
 	handle = handle_new(opts);
-	if (!handle)
+	if (!handle) {
+		if (log_fd >= 0)
+			close(log_fd);
 		return NULL;
+	}
 
 	if (log_fd >= 0)
 		skip_fds[nr_skip_fds++] = log_fd;
@@ -839,6 +920,20 @@ popen_new(struct popen_opts *opts)
 		 * do anything special.
 		 */
 
+		/*
+		 * Replace the logger fd to its duplicate. It
+		 * should be done before we'll close inherited
+		 * fds: old logger fd may be stderr and stderr may
+		 * be subject to close.
+		 *
+		 * We should also do it before a first call to a
+		 * say_*() function, because otherwise a user may
+		 * capture our debug logs as stderr of the child
+		 * process.
+		 */
+		if (log_fd >= 0)
+			log_set_fd(log_fd);
+
 		/*
 		 * Also don't forget to drop signal handlers
 		 * to default inside a child process since we're
@@ -944,19 +1039,21 @@ popen_new(struct popen_opts *opts)
 			goto exit_child;
 		}
 
-		if (log_fd >= 0) {
-			if (close(log_fd)) {
-				say_error("child: can't close logfd %d",
-					  log_fd);
-				goto exit_child;
-			}
-		}
+		/*
+		 * Return the logger back, because we're in the
+		 * same virtual memory address space as the
+		 * parent.
+		 */
+		if (log_fd >= 0)
+			log_set_fd(old_log_fd);
 
 		if (opts->flags & POPEN_FLAG_SHELL)
 			execve(_PATH_BSHELL, opts->argv, envp);
 		else
 			execve(opts->argv[0], opts->argv, envp);
 exit_child:
+		if (log_fd >= 0)
+			log_set_fd(old_log_fd);
 		_exit(errno);
 		unreachable();
 	}
@@ -987,6 +1084,13 @@ exit_child:
 		}
 	}
 
+	/* Close the temporary logger fd. */
+	if (log_fd >= 0 && close(log_fd) != 0) {
+		diag_set(SystemError, "Can't close temporary logfd %d", log_fd);
+		log_fd = -1;
+		goto out_err;
+	}
+
 	/*
 	 * Link it into global list for force
 	 * cleanup on exit. Note we use this
@@ -1018,6 +1122,8 @@ out_err:
 		if (pfd[i][1] != -1)
 			close(pfd[i][1]);
 	}
+	if (log_fd >= 0)
+		close(log_fd);
 	errno = saved_errno;
 	return NULL;
 }
-- 
2.25.0