[DTrace-devel] [PATCH v2 06/23] dtprobed: logging improvements
Kris Van Hees
kris.van.hees at oracle.com
Wed Dec 6 20:11:29 UTC 2023
On Mon, Nov 27, 2023 at 04:47:12PM +0000, Nick Alcock wrote:
> 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 at oracle.com>
Reviewed-by: Kris Van Hees <kris.van.hees at oracle.com>
.., provided the last remaining coding style issue is resolved (which was
reported in the previous review of this patch). See below...
> ---
> dtprobed/dtprobed.c | 48 ++++++++++++++++++++-----------
> dtprobed/rpl_fuse_log.h | 4 ++-
> include/port.h | 4 ++-
> libport/daemonize.c | 62 +++++++++++++++++++++++++++++------------
> 4 files changed, 82 insertions(+), 36 deletions(-)
>
> diff --git a/dtprobed/dtprobed.c b/dtprobed/dtprobed.c
> index 507a412ad0de..64fb9fa47b19 100644
> --- a/dtprobed/dtprobed.c
> +++ b/dtprobed/dtprobed.c
> @@ -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,14 @@ 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) {
This should be:
} 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 +113,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 +319,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 +339,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 +393,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 +466,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 +478,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 +664,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 +861,6 @@ main(int argc, char *argv[])
> {
> int opt;
> char *devname = "dtrace/helper";
> - int sync_fd = -1;
> int ret;
> struct sigaction sa = {0};
>
> @@ -920,10 +934,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");
> diff --git a/dtprobed/rpl_fuse_log.h b/dtprobed/rpl_fuse_log.h
> index 5baf65a2a1a6..1415bcf7ced6 100644
> --- a/dtprobed/rpl_fuse_log.h
> +++ b/dtprobed/rpl_fuse_log.h
> @@ -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
>
> diff --git a/include/port.h b/include/port.h
> index b74a33a988f7..d24da88c86ad 100644
> --- a/include/port.h
> +++ b/include/port.h
> @@ -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);
>
> diff --git a/libport/daemonize.c b/libport/daemonize.c
> index f8ac0f1b43ca..43a4a9bf09b8 100644
> --- a/libport/daemonize.c
> +++ b/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, 2023, 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.
> *
> --
> 2.42.0.271.g85384428f1
>
>
More information about the DTrace-devel
mailing list