dtprobed: logging improvements

So it turns out that fuse_log() isn't marked with any of GCC's printf
attributes. It's not so marked upstream, which is bad enough, but its
replacment isn't marked in our tree either, so all the fuse_log()s aren't
getting properly format-string checked.

Fix that, fix a bunch of them, and fix up the logging output so it usually
has timestamps in DTrace debug log format in it so testsuite output gets
properly split up and so that you can correlate debug output from dtprobed
with debug output from DTrace itself.

Tie it into the daemon logging machinery (which sends error messages up the
synchronization pipe after dtprobed has forked a daemonized child but before
it has finished initializing and its parent has died off, for printing by
the parent), so that fuse_log() can now be used everywhere without concern
for whether this code is being run before dtprobed has daemonized or not.
In the process, delete daemon_err(), a print-error-and-die function with
no remaining uses.

(Some format string errors remain after this commit, in code that is
outright removed or rewritten in the following commits.)

Signed-off-by: Nick Alcock <nick.alcock@oracle.com>
Reviewed-by: Kris Van Hees <kris.van.hees@oracle.com>

dtprobed/dtprobed.c

@@ -1,6 +1,6 @@
 /*
  * Oracle Linux DTrace; DOF-consumption and USDT-probe-creation daemon.
- * Copyright (c) 2022, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024, Oracle and/or its affiliates. All rights reserved.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * http://oss.oracle.com/licenses/upl.
  */
@@ -17,6 +17,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <syslog.h>
+#include <time.h>
 #include <unistd.h>
 #include <config.h>
 
@@ -54,6 +55,7 @@
 #include <dt_list.h>
 #include "dof_parser.h"
 #include "uprobes.h"
+#include "libproc.h"
 
 #include "seccomp-assistance.h"
 
@@ -71,6 +73,7 @@ void dt_debug_dump(int unused) {} 		/* For libproc.  */
 static pid_t parser_pid;
 static int parser_in_pipe[2];
 static int parser_out_pipe[2];
+static int sync_fd = -1;
 static int timeout = 5000; 			/* In seconds.  */
 static int rq_count = 0;
 
@@ -91,9 +94,13 @@ log_msg(enum fuse_log_level level, const char *fmt, va_list ap)
 	if (!_dtrace_debug && level > FUSE_LOG_INFO)
 		return;
 
-	if (foreground)
+	if (foreground) {
+		fprintf(stderr, "dtprobed DEBUG %li: ", time(NULL));
 		vfprintf(stderr, fmt, ap);
-	else
+	} else if (sync_fd >= 0) {
+		daemon_log(sync_fd, "dtprobed DEBUG %li: ", time(NULL));
+		daemon_vlog(sync_fd, fmt, ap);
+	} else
 		vsyslog(level, fmt, ap);
 }
 
@@ -105,12 +112,13 @@ dt_debug_printf(const char *subsys, const char *fmt, va_list ap)
 		return;
 
 	if (foreground) {
-		fprintf(stderr, "%s DEBUG: ", subsys);
+		fprintf(stderr, "%s DEBUG %li: ", subsys, time(NULL));
 		vfprintf(stderr, fmt, ap);
-	} else {
+	} else if (sync_fd >= 0)
+		daemon_vlog(sync_fd, fmt, ap);
+	else
 		/* Subsystem discarded (it's always 'libproc' anyway).  */
 		vsyslog(LOG_DEBUG, fmt, ap);
-	}
 }
 
 #if HAVE_LIBFUSE3
@@ -310,15 +318,18 @@ parse_dof(int in, int out)
  * and sends a stream of dof_parsed_t back to this process.
  */
 static void
-dof_parser_start(int sync_fd)
+dof_parser_start(void)
 {
 	if ((pipe(parser_in_pipe) < 0) ||
 	    (pipe(parser_out_pipe) < 0))
 		daemon_perr(sync_fd, "cannot create DOF parser pipes", errno);
 
 	switch (parser_pid = fork()) {
-	case -1:
-		daemon_perr(sync_fd, "cannot fork DOF parser", errno);
+	case -1: {
+		fuse_log(FUSE_LOG_ERR, "cannot fork DOF parser: %s",
+			 strerror(errno));
+		exit(1);
+	}
 	case 0: {
 		/*
 		 * Sandboxed parser child.  Close unwanted fds and nail into
@@ -327,8 +338,10 @@ dof_parser_start(int sync_fd)
 		close(session_fd(cuse_session));
 		close(parser_in_pipe[1]);
 		close(parser_out_pipe[0]);
-		if (!foreground)
+		if (!foreground) {
 			close(sync_fd);
+			sync_fd = -1;
+		}
 
 		/*
 		 * Reporting errors at this point is difficult: we have already
@@ -379,7 +392,7 @@ dof_parser_tidy(int restart)
 	close(parser_out_pipe[0]);
 
 	if (restart)
-		dof_parser_start(-1);
+		dof_parser_start();
 }
 
 static dof_parsed_t *
@@ -452,7 +465,7 @@ helper_ioctl(fuse_req_t req, int cmd, void *arg,
 		fuse_reply_ioctl(req, 0, NULL, 0);
 		return;
 	default: errmsg = "invalid ioctl";;
-		fuse_log(FUSE_LOG_WARNING, "%i: dtprobed: %s %lx\n",
+		fuse_log(FUSE_LOG_WARNING, "%i: dtprobed: %s %x\n",
 			 pid, errmsg, cmd);
 		goto fuse_err;
 	}
@@ -464,6 +477,8 @@ helper_ioctl(fuse_req_t req, int cmd, void *arg,
 		in.iov_base = arg;
 		in.iov_len = sizeof(dof_helper_t);
 
+		fuse_log(FUSE_LOG_DEBUG, "DTRACEHIOC_ADDDOF from PID %i\n", pid);
+
 		errmsg = "error reading ioctl size";
 		if (fuse_reply_ioctl_retry(req, &in, 1, NULL, 0) < 0)
 			goto fuse_errmsg;
@@ -648,8 +663,7 @@ helper_ioctl(fuse_req_t req, int cmd, void *arg,
   fuse_err:
 	if (fuse_reply_err(req, EINVAL) < 0)
 		fuse_log(FUSE_LOG_ERR, "%i: dtprobed: %s\n", pid,
-			 "cannot send error to ioctl caller: %s",
-			errmsg);
+			 "cannot send error to ioctl caller\n");
 	free(userdata->buf);
 	userdata->buf = NULL;
 	userdata->state = DTP_IOCTL_START;
@@ -846,7 +860,6 @@ main(int argc, char *argv[])
 {
 	int opt;
 	char *devname = "dtrace/helper";
-	int sync_fd = -1;
 	int ret;
 	struct sigaction sa = {0};
 
@@ -920,10 +933,12 @@ main(int argc, char *argv[])
 	sa.sa_handler = SIG_IGN;
 	(void) sigaction(SIGPIPE, &sa, NULL);
 
-	dof_parser_start(sync_fd);
+	dof_parser_start();
 
-	if (!foreground)
+	if (!foreground) {
 		close(sync_fd);
+		sync_fd = -1;
+	}
 
 #ifdef HAVE_LIBSYSTEMD
 	sd_notify(1, "READY=1");

dtprobed/rpl_fuse_log.h

@@ -1,6 +1,6 @@
 /*
  * Oracle Linux DTrace; FUSE logging reimplementation.
- * Copyright (c) 2022, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024, Oracle and/or its affiliates. All rights reserved.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * http://oss.oracle.com/licenses/upl.
  */
@@ -9,6 +9,7 @@
 #define	_RPL_FUSE_LOG_H
 
 #include <stdarg.h>
+#include <sys/compiler.h>
 
 /*
  * Reimplementation of fuse_log API in FUSE 3.7.0+.  Not used when FUSE is
@@ -37,7 +38,8 @@ typedef void (*rpl_log_func_t)(enum fuse_log_level level, const char *fmt,
 
 void fuse_set_log_func(rpl_log_func_t func);
 
-void fuse_log(enum fuse_log_level level, const char *fmt, ...);
+void fuse_log(enum fuse_log_level level, const char *fmt, ...)
+	_dt_printflike_(2,3);
 
 #endif
 

include/port.h

@@ -1,6 +1,6 @@
 /*
  * Oracle Linux DTrace.
- * Copyright (c) 2011, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2011, 2024, Oracle and/or its affiliates. All rights reserved.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * http://oss.oracle.com/licenses/upl.
  */
@@ -9,6 +9,7 @@
 #define _PORT_H
 
 #include <pthread.h>
+#include <stdarg.h>
 #include <unistd.h>
 #include <sys/compiler.h>
 #include <sys/types.h>
@@ -29,8 +30,9 @@ int p_online(int cpun);
 
 int daemonize(int close_fds);
 
-_dt_noreturn_ void daemon_err(int fd, const char *err);
 _dt_noreturn_ void daemon_perr(int fd, const char *err, int err_no);
+_dt_printflike_(2, 3) void daemon_log(int fd, const char *fmt, ...);
+void daemon_vlog(int fd, const char *fmt, va_list ap);
 
 unsigned long linux_version_code(void);
 

libport/daemonize.c

@@ -1,6 +1,6 @@
 /*
  * Oracle Linux DTrace; become a daemon.
- * Copyright (c) 2022, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024, Oracle and/or its affiliates. All rights reserved.
  * Licensed under the Universal Permissive License v 1.0 as shown at
  * http://oss.oracle.com/licenses/upl.
  */
@@ -11,6 +11,8 @@
 #include <dirent.h>
 #include <errno.h>
 #include <fcntl.h>
+#include <stdarg.h>
+#include <stdlib.h>
 #include <signal.h>
 #include <stdio.h>
 #include <string.h>
@@ -19,23 +21,8 @@
 #include <port.h>
 
 /*
- * Write an error return down the synchronization pipe.
- */
-_dt_noreturn_
-void
-daemon_err(int fd, const char *err)
-{
-	/*
-	 * Not a paranoid write, no EINTR protection: all our errors are quite
-	 * short and are unlikely to hit EINTR.  The read side, which might
-	 * block for some time,  can make no such assumptions.
-	 */
-	write(fd, err, strlen(err));
-	_exit(1);
-}
-
-/*
- * Write an error return featuring errno down the synchronization pipe.
+ * Write an error return featuring errno down the synchronization pipe, and
+ * terminate.
  *
  * If fd is < 0, write to stderr instead.
  */
@@ -61,6 +48,45 @@ daemon_perr(int fd, const char *err, int err_no)
 	_exit(1);
 }
 
+/*
+ * Log a message down the synchronization pipe, using a va_list.
+ *
+ * If fd is < 0, write to stderr instead.
+ */
+void
+daemon_vlog(int fd, const char *fmt, va_list ap)
+{
+	char *errstr;
+
+	if (vasprintf(&errstr, fmt, ap) < 0)
+		daemon_perr(fd, "cannot format log string", errno);
+
+	/*
+	 * Not a paranoid write: see above.
+	 */
+	if (fd >= 0)
+		write(fd, errstr, strlen(errstr));
+	else
+		fprintf(stderr, "%s", errstr);
+	free(errstr);
+}
+
+/*
+ * Log a message down the synchronization pipe.
+ *
+ * If fd is < 0, write to stderr instead.
+ */
+_dt_printflike_(2, 3)
+void
+daemon_log(int fd, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	daemon_vlog(fd, fmt, ap);
+	va_end(ap);
+}
+
 /*
  * On failure, returns -1 in the parent.
  *