conf, util, tap: Implement --trace option for extra verbose logging

--debug can be a bit too noisy, especially as single packets or
socket messages are logged: implement a new option, --trace,
implying --debug, that enables all debug messages.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

conf.c

@@ -558,6 +558,7 @@ static void usage(const char *name)
 	info("");
 
 	info(   "  -d, --debug		Be verbose, don't run in background");
+	info(   "      --trace		Be extra verbose, implies --debug");
 	info(   "  -q, --quiet		Don't print informational messages");
 	info(   "  -f, --foreground	Don't run in background");
 	info(   "    default: run in background if started from a TTY");
@@ -829,6 +830,7 @@ void conf(struct ctx *c, int argc, char **argv)
 		{"no-dhcp-search", no_argument,		NULL,		8 },
 		{"dns-forward",	required_argument,	NULL,		9 },
 		{"no-netns-quit", no_argument,		NULL,		10 },
+		{"trace",	no_argument,		NULL,		11 },
 		{ 0 },
 	};
 	struct get_bound_ports_ns_arg ns_ports_arg = { .c = c };
@@ -960,6 +962,19 @@ void conf(struct ctx *c, int argc, char **argv)
 			}
 			c->no_netns_quit = 1;
 			break;
+		case 11:
+			if (c->trace) {
+				err("Multiple --trace options given");
+				usage(argv[0]);
+			}
+
+			if (c->quiet) {
+				err("Either --trace or --quiet");
+				usage(argv[0]);
+			}
+
+			c->trace = c->debug = c->foreground = 1;
+			break;
 		case 'd':
 			if (c->debug) {
 				err("Multiple --debug options given");

passt.1

@@ -74,6 +74,11 @@ for performance reasons.
 .BR \-d ", " \-\-debug
 Be verbose, don't run in background.
 
+.TP
+.BR \-\-trace
+Be extra verbose, show single packets, don't run in background. Implies
+\fB--debug\fR.
+
 .TP
 .BR \-q ", " \-\-quiet
 Don't print informational messages.

passt.c

@@ -96,7 +96,7 @@ char *ip_proto_str[IPPROTO_SCTP + 1] = {
 static void sock_handler(struct ctx *c, union epoll_ref ref, uint32_t events,
 			 struct timespec *now)
 {
-	debug("%s: %s packet from socket %i (events: 0x%08x)",
+	trace("%s: %s packet from socket %i (events: 0x%08x)",
 	      c->mode == MODE_PASST ? "passt" : "pasta",
 	      IP_PROTO_STR(ref.r.proto), ref.r.s, events);
 
@@ -351,6 +351,7 @@ int main(int argc, char **argv)
 	__setlogmask(LOG_MASK(LOG_EMERG));
 
 	conf(&c, argc, argv);
+	trace_init(c.trace);
 
 	if (!c.debug && (c.stderr || isatty(fileno(stdout))))
 		__openlog(log_name, LOG_PERROR, LOG_DAEMON);

passt.h

@@ -92,6 +92,7 @@ enum passt_modes {
  * struct ctx - Execution context
  * @mode:		Operation mode, qemu/UNIX domain socket or namespace/tap
  * @debug:		Enable debug mode
+ * @trace:		Enable tracing (extra debug) mode
  * @quiet:		Don't print informational messages
  * @foreground:		Run in foreground, don't log to stderr by default
  * @stderr:		Force logging to stderr
@@ -153,6 +154,7 @@ enum passt_modes {
 struct ctx {
 	enum passt_modes mode;
 	int debug;
+	int trace;
 	int quiet;
 	int foreground;
 	int stderr;

tap.c

@@ -283,14 +283,14 @@ static void tap_packet_debug(struct iphdr *iph, struct ipv6hdr *ip6h,
 	}
 
 	if (proto == IPPROTO_TCP || proto == IPPROTO_UDP) {
-		debug("protocol %i from tap: %s:%i -> %s:%i (%i packet%s)",
+		trace("protocol %i from tap: %s:%i -> %s:%i (%i packet%s)",
 		      proto, seq4 ? buf4s : buf6s,
 		      ntohs(seq4 ? seq4->source : seq6->source),
 		      seq4 ? buf4d : buf6d,
 		      ntohs(seq4 ? seq4->dest : seq6->dest),
 		      count, count == 1 ? "" : "s");
 	} else {
-		debug("protocol %i from tap: %s -> %s (%i packet%s)",
+		trace("protocol %i from tap: %s -> %s (%i packet%s)",
 		      proto, iph ? buf4s : buf6s, iph ? buf4d : buf6d,
 		      count, count == 1 ? "" : "s");
 	}

test/README.md

@@ -63,7 +63,11 @@ Just issue:
 
     ./run
 
-from the `test` directory. Elevated privileges are not needed.
+from the `test` directory. Elevated privileges are not needed. Environment
+variable settings: DEBUG=1 enables debugging messages, TRACE=1 enables tracing
+(further debugging messages), PCAP=1 enables packet captures. Example:
+
+    PCAP=1 TRACE=1 ./run
 
 ## Continuous integration
 

test/lib/setup

@@ -49,6 +49,8 @@ setup_passt() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/passt.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
+
 	pane_run PASST "./passt ${__opts} -f -t 10001 -u 10001"
 	sleep 1
 
@@ -90,6 +92,7 @@ setup_pasta() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/pasta.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 
 	pane_run PASST "./pasta ${__opts} -f -t 10002 -T 10003 -u 10002 -U 10003 ${__target_pid}"
 	sleep 1
@@ -118,6 +121,7 @@ setup_passt_in_ns() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/pasta_with_passt.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 
 	__pid_file="$(mktemp)"
 	pane_run PASST "./pasta ${__opts} -t 10001,10002,10011,10012 -T 10003,10013 -u 10001,10002,10011,10012 -U 10003,10013 -P ${__pid_file}"
@@ -145,6 +149,7 @@ setup_passt_in_ns() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/passt_in_pasta.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 
 	#pane_run PASST "valgrind --max-stackframe=3000000 ./passt -f ${__opts} -t 10001,10011,10021,10031 -u 10001,10011,10021,10031"
 	pane_run PASST "./passt -f ${__opts} -t 10001,10011,10021,10031 -u 10001,10011,10021,10031"
@@ -183,11 +188,13 @@ setup_two_guests() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/pasta_1.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 	pane_run PASST_1 "./pasta ${__opts} -P ${__pid1_file} -t 10001,10002 -T 10003,10004 -u 10001,10002 -U 10003,10004"
 
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/pasta_2.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 	pane_run PASST_2 "./pasta ${__opts} -P ${__pid2_file} -t 10004,10005 -T 10003,10001 -u 10004,10005 -U 10003,10001"
 
 	sleep 1
@@ -223,12 +230,15 @@ setup_two_guests() {
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/passt_1.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
+
 	pane_run PASST_1 "./passt -f ${__opts} -t 10001 -u 10001"
 	sleep 1
 
 	__opts=
 	[ ${PCAP} -eq 1 ] && __opts="${__opts} -p /tmp/passt_2.pcap"
 	[ ${DEBUG} -eq 1 ] && __opts="${__opts} -d"
+	[ ${TRACE} -eq 1 ] && __opts="${__opts} --trace"
 	pane_run PASST_2 "./passt -f ${__opts} -t 10004 -u 10004"
 
 	pane_run GUEST_2 'cp mbuto.img mbuto_2.img'

util.c

@@ -45,6 +45,7 @@ static int	log_sock = -1;
 static char	log_ident[BUFSIZ];
 static int	log_opt;
 static time_t	log_debug_start;
+int		log_trace;
 
 #define logfn(name, level)						\
 void name(const char *format, ...) {					\
@@ -77,6 +78,11 @@ logfn(warn,  LOG_WARNING)
 logfn(info,  LOG_INFO)
 logfn(debug, LOG_DEBUG)
 
+void trace_init(int enable)
+{
+	log_trace = enable;
+}
+
 /**
  * __openlog() - Non-optional openlog() wrapper, to allow custom vsyslog()
  * @ident:	openlog() identity (program name)

util.h

@@ -8,6 +8,14 @@ void warn(const char *format, ...);
 void info(const char *format, ...);
 void debug(const char *format, ...);
 
+extern int log_trace;
+void trace_init(int enable);
+#define trace(format, ...)						\
+	do {								\
+		if (log_trace)						\
+			debug(format, ##__VA_ARGS__);			\
+	} while (0)
+
 #ifndef SECCOMP_RET_KILL_PROCESS
 #define SECCOMP_RET_KILL_PROCESS	SECCOMP_RET_KILL
 #endif