[PATCH 25/25] virtiofsd: print log only when priority is high enough

["Dr. David Alan Gilbert (git)" <dgilbert@redhat.com>]

From: Eryu Guan <eguan@linux.alibaba.com>

Introduce "-o log_level=" command line option to specify current log
level (priority), valid values are "debug info warn err", e.g.

    ./virtiofsd -o log_level=debug ...

So only log priority higher than "debug" will be printed to
stderr/syslog. And the default level is info.

The "-o debug"/"-d" options are kept, and imply debug log level.

Signed-off-by: Eryu Guan <eguan@linux.alibaba.com>
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
dgilbert: Reworked for libfuse's log_func
Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
---
 contrib/virtiofsd/fuse_log.c       |   4 ++
 contrib/virtiofsd/fuse_lowlevel.c  |  79 ++++++++++-------------
 contrib/virtiofsd/fuse_lowlevel.h  |   1 +
 contrib/virtiofsd/helper.c         |   9 ++-
 contrib/virtiofsd/passthrough_ll.c | 100 +++++++++++++----------------
 5 files changed, 91 insertions(+), 102 deletions(-)

diff --git a/contrib/virtiofsd/fuse_log.c b/contrib/virtiofsd/fuse_log.c
index 0d268ab014..b11f6d0c08 100644
--- a/contrib/virtiofsd/fuse_log.c
+++ b/contrib/virtiofsd/fuse_log.c
@@ -8,6 +8,10 @@
   See the file COPYING.LIB
 */
 
+#include <stdbool.h>
+#include <stdio.h>
+#include <stdarg.h>
+#include <syslog.h>
 #include "fuse_log.h"
 
 #include <stdarg.h>
diff --git a/contrib/virtiofsd/fuse_lowlevel.c b/contrib/virtiofsd/fuse_lowlevel.c
index 8f9a59a34c..20f2190194 100644
--- a/contrib/virtiofsd/fuse_lowlevel.c
+++ b/contrib/virtiofsd/fuse_lowlevel.c
@@ -155,20 +155,17 @@ static int fuse_send_msg(struct fuse_session *se, struct fuse_chan *ch,
 	struct fuse_out_header *out = iov[0].iov_base;
 
 	out->len = iov_length(iov, count);
-	if (se->debug) {
-		if (out->unique == 0) {
-			fuse_log(FUSE_LOG_DEBUG, "NOTIFY: code=%d length=%u\n",
-				out->error, out->len);
-		} else if (out->error) {
-			fuse_log(FUSE_LOG_DEBUG,
-				"   unique: %llu, error: %i (%s), outsize: %i\n",
-				(unsigned long long) out->unique, out->error,
-				strerror(-out->error), out->len);
-		} else {
-			fuse_log(FUSE_LOG_DEBUG,
-				"   unique: %llu, success, outsize: %i\n",
-				(unsigned long long) out->unique, out->len);
-		}
+	if (out->unique == 0) {
+		fuse_log(FUSE_LOG_DEBUG, "NOTIFY: code=%d length=%u\n",
+			   out->error, out->len);
+	} else if (out->error) {
+		fuse_log(FUSE_LOG_DEBUG, "   unique: %llu, error: %i (%s), outsize: %i\n",
+			   (unsigned long long) out->unique,
+			   out->error, strerror(-out->error),
+			   out->len);
+	} else {
+		fuse_log(FUSE_LOG_DEBUG, "   unique: %llu, success, outsize: %i\n",
+			   (unsigned long long) out->unique, out->len);
 	}
 
 	if (fuse_lowlevel_is_virtio(se)) {
@@ -1663,9 +1660,8 @@ static void do_interrupt(fuse_req_t req, fuse_ino_t nodeid,
 		return;
 	}
 
-	if (se->debug)
-		fuse_log(FUSE_LOG_DEBUG, "INTERRUPT: %llu\n",
-			(unsigned long long) arg->unique);
+	fuse_log(FUSE_LOG_DEBUG, "INTERRUPT: %llu\n",
+		 (unsigned long long) arg->unique);
 
 	req->u.i.unique = arg->unique;
 
@@ -1878,13 +1874,11 @@ static void do_init(fuse_req_t req, fuse_ino_t nodeid,
 		}
 	}
 
-	if (se->debug) {
-		fuse_log(FUSE_LOG_DEBUG, "INIT: %u.%u\n", arg->major, arg->minor);
-		if (arg->major == 7 && arg->minor >= 6) {
-			fuse_log(FUSE_LOG_DEBUG, "flags=0x%08x\n", arg->flags);
-			fuse_log(FUSE_LOG_DEBUG, "max_readahead=0x%08x\n",
-				arg->max_readahead);
-		}
+	fuse_log(FUSE_LOG_DEBUG, "INIT: %u.%u\n", arg->major, arg->minor);
+	if (arg->major == 7 && arg->minor >= 6) {
+		fuse_log(FUSE_LOG_DEBUG, "flags=0x%08x\n", arg->flags);
+		fuse_log(FUSE_LOG_DEBUG, "max_readahead=0x%08x\n",
+			   arg->max_readahead);
 	}
 	se->conn.proto_major = arg->major;
 	se->conn.proto_minor = arg->minor;
@@ -2070,19 +2064,17 @@ static void do_init(fuse_req_t req, fuse_ino_t nodeid,
 	if (se->conn.proto_minor >= 23)
 		outarg.time_gran = se->conn.time_gran;
 
-	if (se->debug) {
-		fuse_log(FUSE_LOG_DEBUG, "   INIT: %u.%u\n", outarg.major, outarg.minor);
-		fuse_log(FUSE_LOG_DEBUG, "   flags=0x%08x\n", outarg.flags);
-		fuse_log(FUSE_LOG_DEBUG, "   max_readahead=0x%08x\n",
-			outarg.max_readahead);
-		fuse_log(FUSE_LOG_DEBUG, "   max_write=0x%08x\n", outarg.max_write);
-		fuse_log(FUSE_LOG_DEBUG, "   max_background=%i\n",
-			outarg.max_background);
-		fuse_log(FUSE_LOG_DEBUG, "   congestion_threshold=%i\n",
-			outarg.congestion_threshold);
-		fuse_log(FUSE_LOG_DEBUG, "   time_gran=%u\n",
-			outarg.time_gran);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "   INIT: %u.%u\n", outarg.major, outarg.minor);
+	fuse_log(FUSE_LOG_DEBUG, "   flags=0x%08x\n", outarg.flags);
+	fuse_log(FUSE_LOG_DEBUG, "   max_readahead=0x%08x\n",
+		   outarg.max_readahead);
+	fuse_log(FUSE_LOG_DEBUG, "   max_write=0x%08x\n", outarg.max_write);
+	fuse_log(FUSE_LOG_DEBUG, "   max_background=%i\n",
+		   outarg.max_background);
+	fuse_log(FUSE_LOG_DEBUG, "   congestion_threshold=%i\n",
+		   outarg.congestion_threshold);
+	fuse_log(FUSE_LOG_DEBUG, "   time_gran=%u\n",
+		   outarg.time_gran);
 	if (arg->minor < 5)
 		outargsize = FUSE_COMPAT_INIT_OUT_SIZE;
 	else if (arg->minor < 23)
@@ -2370,13 +2362,12 @@ void fuse_session_process_buf_int(struct fuse_session *se,
 	in = fuse_mbuf_iter_advance(&iter, sizeof(*in));
 	assert(in); /* caller guarantees the input buffer is large enough */
 
-	if (se->debug) {
-		fuse_log(FUSE_LOG_DEBUG,
-			"unique: %llu, opcode: %s (%i), nodeid: %llu, insize: %zu, pid: %u\n",
-			(unsigned long long) in->unique,
-			opname((enum fuse_opcode) in->opcode), in->opcode,
-			(unsigned long long) in->nodeid, buf->size, in->pid);
-	}
+	fuse_log(FUSE_LOG_DEBUG,
+		 "unique: %llu, opcode: %s (%i), nodeid: %llu, insize: %zu, pid: %u\n",
+		 (unsigned long long) in->unique,
+		 opname((enum fuse_opcode) in->opcode), in->opcode,
+		 (unsigned long long) in->nodeid, buf->size,
+		 in->pid);
 
 	req = fuse_ll_alloc_req(se);
 	if (req == NULL) {
diff --git a/contrib/virtiofsd/fuse_lowlevel.h b/contrib/virtiofsd/fuse_lowlevel.h
index 112596caaf..49cf5b22ff 100644
--- a/contrib/virtiofsd/fuse_lowlevel.h
+++ b/contrib/virtiofsd/fuse_lowlevel.h
@@ -1799,6 +1799,7 @@ struct fuse_cmdline_opts {
 	int print_capabilities;
 	int clone_fd;
 	int syslog;
+	int log_level;
 	unsigned int max_idle_threads;
 };
 
diff --git a/contrib/virtiofsd/helper.c b/contrib/virtiofsd/helper.c
index b1e45aee05..d9eb9ff62c 100644
--- a/contrib/virtiofsd/helper.c
+++ b/contrib/virtiofsd/helper.c
@@ -29,7 +29,6 @@
 #define FUSE_HELPER_OPT_VALUE(t, p, v) \
 	{ t, offsetof(struct fuse_cmdline_opts, p), v }
 
-
 static const struct fuse_opt fuse_helper_opts[] = {
 	FUSE_HELPER_OPT("-h",		show_help),
 	FUSE_HELPER_OPT("--help",	show_help),
@@ -54,6 +53,10 @@ static const struct fuse_opt fuse_helper_opts[] = {
 	FUSE_HELPER_OPT("clone_fd",	clone_fd),
 	FUSE_HELPER_OPT("max_idle_threads=%u", max_idle_threads),
 	FUSE_HELPER_OPT("--syslog",	syslog),
+	FUSE_HELPER_OPT_VALUE("log_level=debug", log_level, FUSE_LOG_DEBUG),
+	FUSE_HELPER_OPT_VALUE("log_level=info", log_level, FUSE_LOG_INFO),
+	FUSE_HELPER_OPT_VALUE("log_level=warn", log_level, FUSE_LOG_WARNING),
+	FUSE_HELPER_OPT_VALUE("log_level=err", log_level, FUSE_LOG_ERR),
 	FUSE_OPT_END
 };
 
@@ -143,7 +146,9 @@ void fuse_cmdline_help(void)
 	       "    -o clone_fd                use separate fuse device fd for each thread\n"
 	       "                               (may improve performance)\n"
 	       "    -o max_idle_threads        the maximum number of idle worker threads\n"
-	       "                               allowed (default: 10)\n");
+	       "                               allowed (default: 10)\n"
+	       "    -o log_level=<level>       log level, default to \"info\"\n"
+	       "                               level could be one of \"debug, info, warn, err\"\n");
 }
 
 static int fuse_helper_opt_proc(void *data, const char *arg, int key,
diff --git a/contrib/virtiofsd/passthrough_ll.c b/contrib/virtiofsd/passthrough_ll.c
index b413687720..8ad41b1072 100644
--- a/contrib/virtiofsd/passthrough_ll.c
+++ b/contrib/virtiofsd/passthrough_ll.c
@@ -36,6 +36,7 @@
 
 #include "fuse_virtio.h"
 #include "fuse_lowlevel.h"
+#include "fuse_log.h"
 #include <unistd.h>
 #include <stdlib.h>
 #include <stdio.h>
@@ -153,6 +154,7 @@ static const struct fuse_opt lo_opts[] = {
 	FUSE_OPT_END
 };
 static bool use_syslog = false;
+static int current_log_level;
 
 static void unref_inode(struct lo_data *lo, struct lo_inode *inode, uint64_t n);
 
@@ -446,11 +448,6 @@ static int lo_fd(fuse_req_t req, fuse_ino_t ino)
 	return inode ? inode->fd : -1;
 }
 
-static bool lo_debug(fuse_req_t req)
-{
-	return lo_data(req)->debug != 0;
-}
-
 static void lo_init(void *userdata,
 		    struct fuse_conn_info *conn)
 {
@@ -461,13 +458,11 @@ static void lo_init(void *userdata,
 
 	if (lo->writeback &&
 	    conn->capable & FUSE_CAP_WRITEBACK_CACHE) {
-		if (lo->debug)
-			fuse_log(FUSE_LOG_DEBUG, "lo_init: activating writeback\n");
+		fuse_log(FUSE_LOG_DEBUG, "lo_init: activating writeback\n");
 		conn->want |= FUSE_CAP_WRITEBACK_CACHE;
 	}
 	if (lo->flock && conn->capable & FUSE_CAP_FLOCK_LOCKS) {
-		if (lo->debug)
-			fuse_log(FUSE_LOG_DEBUG, "lo_init: activating flock locks\n");
+		fuse_log(FUSE_LOG_DEBUG, "lo_init: activating flock locks\n");
 		conn->want |= FUSE_CAP_FLOCK_LOCKS;
 	}
 }
@@ -789,9 +784,9 @@ static int lo_do_lookup(fuse_req_t req, fuse_ino_t parent, const char *name,
 	}
 	e->ino = inode->fuse_ino;
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
-			(unsigned long long) parent, name, (unsigned long long) e->ino);
+	fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
+		 (unsigned long long) parent, name,
+		 (unsigned long long) e->ino);
 
 	return 0;
 
@@ -807,9 +802,7 @@ static void lo_lookup(fuse_req_t req, fuse_ino_t parent, const char *name)
 	struct fuse_entry_param e;
 	int err;
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "lo_lookup(parent=%" PRIu64 ", name=%s)\n",
-			parent, name);
+	fuse_log(FUSE_LOG_DEBUG, "lo_lookup(parent=%" PRIu64 ", name=%s)\n", parent, name);
 
 	/* Don't use is_safe_path_component(), allow "." and ".." for NFS export
 	 * support.
@@ -911,9 +904,9 @@ static void lo_mknod_symlink(fuse_req_t req, fuse_ino_t parent,
 	if (saverr)
 		goto out;
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
-			(unsigned long long) parent, name, (unsigned long long) e.ino);
+	fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
+		   (unsigned long long) parent, name,
+		   (unsigned long long) e.ino);
 
 	fuse_reply_entry(req, &e);
 	return;
@@ -1010,10 +1003,9 @@ static void lo_link(fuse_req_t req, fuse_ino_t ino, fuse_ino_t parent,
 	pthread_mutex_unlock(&lo->mutex);
 	e.ino = inode->fuse_ino;
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
-			(unsigned long long) parent, name,
-			(unsigned long long) e.ino);
+	fuse_log(FUSE_LOG_DEBUG, "  %lli/%s -> %lli\n",
+		   (unsigned long long) parent, name,
+		   (unsigned long long) e.ino);
 
 	fuse_reply_entry(req, &e);
 	return;
@@ -1107,12 +1099,10 @@ static void lo_forget_one(fuse_req_t req, fuse_ino_t ino, uint64_t nlookup)
 	if (!inode)
 		return;
 
-	if (lo_debug(req)) {
-		fuse_log(FUSE_LOG_DEBUG, "  forget %lli %lli -%lli\n",
-			(unsigned long long) ino,
-			(unsigned long long) inode->refcount,
-			(unsigned long long) nlookup);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "  forget %lli %lli -%lli\n",
+		(unsigned long long) ino,
+		(unsigned long long) inode->refcount,
+		(unsigned long long) nlookup);
 
 	unref_inode(lo, inode, nlookup);
 }
@@ -1364,9 +1354,7 @@ static void lo_create(fuse_req_t req, fuse_ino_t parent, const char *name,
 	int err;
 	struct lo_cred old = {};
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "lo_create(parent=%" PRIu64 ", name=%s)\n",
-			parent, name);
+	fuse_log(FUSE_LOG_DEBUG, "lo_create(parent=%" PRIu64 ", name=%s)\n", parent, name);
 
 	if (!is_safe_path_component(name)) {
 		fuse_reply_err(req, EINVAL);
@@ -1439,9 +1427,7 @@ static void lo_open(fuse_req_t req, fuse_ino_t ino, struct fuse_file_info *fi)
 	char buf[64];
 	struct lo_data *lo = lo_data(req);
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "lo_open(ino=%" PRIu64 ", flags=%d)\n",
-			ino, fi->flags);
+	fuse_log(FUSE_LOG_DEBUG, "lo_open(ino=%" PRIu64 ", flags=%d)\n", ino, fi->flags);
 
 	/* With writeback cache, kernel may send read requests even
 	   when userspace opened write-only */
@@ -1543,9 +1529,8 @@ static void lo_read(fuse_req_t req, fuse_ino_t ino, size_t size,
 {
 	struct fuse_bufvec buf = FUSE_BUFVEC_INIT(size);
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "lo_read(ino=%" PRIu64 ", size=%zd, "
-			"off=%lu)\n", ino, size, (unsigned long) offset);
+	fuse_log(FUSE_LOG_DEBUG, "lo_read(ino=%" PRIu64 ", size=%zd, "
+		   "off=%lu)\n", ino, size, (unsigned long) offset);
 
 	buf.buf[0].flags = FUSE_BUF_IS_FD | FUSE_BUF_FD_SEEK;
 	buf.buf[0].fd = lo_fi_fd(req, fi);
@@ -1567,9 +1552,8 @@ static void lo_write_buf(fuse_req_t req, fuse_ino_t ino,
 	out_buf.buf[0].fd = lo_fi_fd(req, fi);
 	out_buf.buf[0].pos = off;
 
-	if (lo_debug(req))
-		fuse_log(FUSE_LOG_DEBUG, "lo_write(ino=%" PRIu64 ", size=%zd, off=%lu)\n",
-			ino, out_buf.buf[0].size, (unsigned long) off);
+	fuse_log(FUSE_LOG_DEBUG, "lo_write_buf(ino=%" PRIu64 ", size=%zd, off=%lu)\n",
+		   ino, out_buf.buf[0].size, (unsigned long) off);
 
 	/*
 	 * If kill_priv is set, drop CAP_FSETID which should lead to kernel
@@ -1662,10 +1646,8 @@ static void lo_getxattr(fuse_req_t req, fuse_ino_t ino, const char *name,
 	if (!lo_data(req)->xattr)
 		goto out;
 
-	if (lo_debug(req)) {
-		fuse_log(FUSE_LOG_DEBUG, "lo_getxattr(ino=%" PRIu64 ", name=%s size=%zd)\n",
-			ino, name, size);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "lo_getxattr(ino=%" PRIu64 ", name=%s size=%zd)\n",
+		   ino, name, size);
 
 	if (inode->is_symlink) {
 		/* Sorry, no race free way to getxattr on symlink. */
@@ -1734,10 +1716,7 @@ static void lo_listxattr(fuse_req_t req, fuse_ino_t ino, size_t size)
 	if (!lo_data(req)->xattr)
 		goto out;
 
-	if (lo_debug(req)) {
-		fuse_log(FUSE_LOG_DEBUG, "lo_listxattr(ino=%" PRIu64 ", size=%zd)\n",
-			ino, size);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "lo_listxattr(ino=%" PRIu64 ", size=%zd)\n", ino, size);
 
 	if (inode->is_symlink) {
 		/* Sorry, no race free way to listxattr on symlink. */
@@ -1806,10 +1785,9 @@ static void lo_setxattr(fuse_req_t req, fuse_ino_t ino, const char *name,
 	if (!lo_data(req)->xattr)
 		goto out;
 
-	if (lo_debug(req)) {
-		fuse_log(FUSE_LOG_DEBUG, "lo_setxattr(ino=%" PRIu64 ", name=%s value=%s size=%zd)\n",
-			ino, name, value, size);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "lo_setxattr(ino=%" PRIu64,
+		 ", name=%s value=%s size=%zd)\n",
+		 ino, name, value, size);
 
 	if (inode->is_symlink) {
 		/* Sorry, no race free way to removexattr on symlink. */
@@ -1853,10 +1831,8 @@ static void lo_removexattr(fuse_req_t req, fuse_ino_t ino, const char *name)
 	if (!lo_data(req)->xattr)
 		goto out;
 
-	if (lo_debug(req)) {
-		fuse_log(FUSE_LOG_DEBUG, "lo_removexattr(ino=%" PRIu64 ", name=%s)\n",
-			ino, name);
-	}
+	fuse_log(FUSE_LOG_DEBUG, "lo_removexattr(ino=%" PRIu64 ", name=%s)\n",
+		 ino, name);
 
 	if (inode->is_symlink) {
 		/* Sorry, no race free way to setxattr on symlink. */
@@ -2147,6 +2123,9 @@ static void setup_nofile_rlimit(void)
 static void log_func(enum fuse_log_level level,
 		     const char *fmt, va_list ap)
 {
+	if (current_log_level < level)
+		return;
+
 	if (use_syslog) {
 		int priority = LOG_ERR;
 		switch (level) {
@@ -2227,8 +2206,17 @@ int main(int argc, char *argv[])
 	if (fuse_opt_parse(&args, &lo, lo_opts, NULL)== -1)
 		return 1;
 
+	/*
+	 * log_level is 0 if not configured via cmd options (0 is LOG_EMERG,
+	 * and we don't use this log level).
+	 */
+	if (opts.log_level != 0)
+		current_log_level = opts.log_level;
 	lo.debug = opts.debug;
+	if (lo.debug)
+		current_log_level = FUSE_LOG_DEBUG;
 	lo.root.refcount = 2;
+
 	if (lo.source) {
 		struct stat stat;
 		int res;
-- 
2.23.0