From d2e40bb8d98763e33c3eeac4f5f1b7c53465009f Mon Sep 17 00:00:00 2001 From: Stefano Brivio Date: Tue, 15 Mar 2022 00:59:09 +0100 Subject: [PATCH] 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 --- conf.c | 15 +++++++++++++++ passt.1 | 5 +++++ passt.c | 3 ++- passt.h | 2 ++ tap.c | 4 ++-- test/README.md | 6 +++++- test/lib/setup | 10 ++++++++++ util.c | 6 ++++++ util.h | 8 ++++++++ 9 files changed, 55 insertions(+), 4 deletions(-) diff --git a/conf.c b/conf.c index 08f24be..5170163 100644 --- a/conf.c +++ b/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"); diff --git a/passt.1 b/passt.1 index 57cf745..0252fbb 100644 --- a/passt.1 +++ b/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. diff --git a/passt.c b/passt.c index 40d3e57..5cd8f3b 100644 --- a/passt.c +++ b/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); diff --git a/passt.h b/passt.h index 042f760..8344fca 100644 --- a/passt.h +++ b/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; diff --git a/tap.c b/tap.c index 29fcd51..e1854fb 100644 --- a/tap.c +++ b/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"); } diff --git a/test/README.md b/test/README.md index 88270e8..cdf233b 100644 --- a/test/README.md +++ b/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 diff --git a/test/lib/setup b/test/lib/setup index f04949e..a39eb80 100755 --- a/test/lib/setup +++ b/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' diff --git a/util.c b/util.c index 90b5ab8..50b83db 100644 --- a/util.c +++ b/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) diff --git a/util.h b/util.h index b7852e9..bfab221 100644 --- a/util.h +++ b/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