On Fri, Oct 07, 2022 at 02:47:35AM +0200, Stefano Brivio wrote:

Logging to file is going to add some further complexity that we don't want to squeeze into util.c.

Signed-off-by: Stefano Brivio

Reviewed-by: David Gibson

--- Makefile | 4 +- conf.c | 1 + dhcp.c | 1 + dhcpv6.c | 1 + icmp.c | 1 + isolation.c | 1 + log.c | 143 +++++++++++++++++++++++++++++++++++++++++++++++++++ log.h | 26 ++++++++++ ndp.c | 1 + netlink.c | 1 + packet.c | 1 + passt.c | 1 + pasta.c | 1 + pcap.c | 1 + tap.c | 1 + tcp.c | 1 + tcp_splice.c | 1 + udp.c | 1 + util.c | 121 +------------------------------------------ util.h | 16 ------ 20 files changed, 187 insertions(+), 138 deletions(-) create mode 100644 log.c create mode 100644 log.h

diff --git a/Makefile b/Makefile index d4b623f..74bbfeb 100644 --- a/Makefile +++ b/Makefile @@ -33,8 +33,8 @@ FLAGS += -DRLIMIT_STACK_VAL=$(RLIMIT_STACK_VAL) FLAGS += -DARCH=\"$(TARGET_ARCH)\"

PASST_SRCS = arch.c arp.c checksum.c conf.c dhcp.c dhcpv6.c icmp.c igmp.c \ - isolation.c lineread.c mld.c ndp.c netlink.c packet.c passt.c pasta.c \ - pcap.c siphash.c tap.c tcp.c tcp_splice.c udp.c util.c + isolation.c lineread.c log.c mld.c ndp.c netlink.c packet.c passt.c \ + pasta.c pcap.c siphash.c tap.c tcp.c tcp_splice.c udp.c util.c QRAP_SRCS = qrap.c SRCS = $(PASST_SRCS) $(QRAP_SRCS)

diff --git a/conf.c b/conf.c index 1537dbf..ba1d8de 100644 --- a/conf.c +++ b/conf.c @@ -40,6 +40,7 @@ #include "pasta.h" #include "lineread.h" #include "isolation.h" +#include "log.h"

/** * get_bound_ports() - Get maps of ports with bound sockets diff --git a/dhcp.c b/dhcp.c index 7ad1319..7f0cc0b 100644 --- a/dhcp.c +++ b/dhcp.c @@ -29,6 +29,7 @@ #include "packet.h" #include "passt.h" #include "tap.h" +#include "log.h" #include "dhcp.h"

/** diff --git a/dhcpv6.c b/dhcpv6.c index 8a1d4a6..e7640ce 100644 --- a/dhcpv6.c +++ b/dhcpv6.c @@ -30,6 +30,7 @@ #include "util.h" #include "passt.h" #include "tap.h" +#include "log.h"

/** * struct opt_hdr - DHCPv6 option header diff --git a/icmp.c b/icmp.c index 29170aa..f02f89f 100644 --- a/icmp.c +++ b/icmp.c @@ -35,6 +35,7 @@ #include "util.h" #include "passt.h" #include "tap.h" +#include "log.h" #include "icmp.h"

#define ICMP_ECHO_TIMEOUT 60 /* s, timeout for ICMP socket activity */ diff --git a/isolation.c b/isolation.c index 124dea4..b54c325 100644 --- a/isolation.c +++ b/isolation.c @@ -42,6 +42,7 @@ #include "util.h" #include "seccomp.h" #include "passt.h" +#include "log.h" #include "isolation.h"

/** diff --git a/log.c b/log.c new file mode 100644 index 0000000..54a7cbb --- /dev/null +++ b/log.c @@ -0,0 +1,143 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +/* PASST - Plug A Simple Socket Transport + * for qemu/UNIX domain socket mode + * + * PASTA - Pack A Subtle Tap Abstraction + * for network namespace/tap device mode + * + * log.c - Logging functions + * + * Copyright (c) 2020-2022 Red Hat GmbH + * Author: Stefano Brivio + */ + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "log.h" + +/* For __openlog() and __setlogmask() wrappers, and passt_vsyslog() */ +static int log_mask; +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, ...) { \ + struct timespec tp; \ + va_list args; \ + \ + if (setlogmask(0) & LOG_MASK(LOG_DEBUG)) { \ + clock_gettime(CLOCK_REALTIME, &tp); \ + fprintf(stderr, "%li.%04li: ", \ + tp.tv_sec - log_debug_start, \ + tp.tv_nsec / (100L * 1000)); \ + } else { \ + va_start(args, format); \ + passt_vsyslog(level, format, args); \ + va_end(args); \ + } \ + \ + if (setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ + setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ + va_start(args, format); \ + (void)vfprintf(stderr, format, args); \ + va_end(args); \ + if (format[strlen(format)] != '\n') \ + fprintf(stderr, "\n"); \ + } \ +} + +logfn(err, LOG_ERR) +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) + * @option: openlog() options + * @facility: openlog() facility (LOG_DAEMON) + */ +void __openlog(const char *ident, int option, int facility) +{ + struct timespec tp; + + clock_gettime(CLOCK_REALTIME, &tp); + log_debug_start = tp.tv_sec; + + if (log_sock < 0) { + struct sockaddr_un a = { .sun_family = AF_UNIX, }; + + log_sock = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0); + if (log_sock < 0) + return; + + strncpy(a.sun_path, _PATH_LOG, sizeof(a.sun_path)); + if (connect(log_sock, (const struct sockaddr *)&a, sizeof(a))) { + close(log_sock); + log_sock = -1; + return; + } + } + + log_mask |= facility; + strncpy(log_ident, ident, sizeof(log_ident) - 1); + log_opt = option; + + openlog(ident, option, facility); +} + +/** + * __setlogmask() - setlogmask() wrapper, to allow custom vsyslog() + * @mask: Same as setlogmask() mask + */ +void __setlogmask(int mask) +{ + log_mask = mask; + setlogmask(mask); +} + +/** + * passt_vsyslog() - vsyslog() implementation not using heap memory + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Same as vsyslog() format + * @ap: Same as vsyslog() ap + */ +void passt_vsyslog(int pri, const char *format, va_list ap) +{ + char buf[BUFSIZ]; + int n; + + if (!(LOG_MASK(LOG_PRI(pri)) & log_mask)) + return; + + /* Send without name and timestamp, the system logger should add them */ + n = snprintf(buf, BUFSIZ, "<%i> ", pri); + + n += vsnprintf(buf + n, BUFSIZ - n, format, ap); + + if (format[strlen(format)] != '\n') + n += snprintf(buf + n, BUFSIZ - n, "\n"); + + if (log_opt & LOG_PERROR) + fprintf(stderr, "%s", buf + sizeof("<0>")); + + if (send(log_sock, buf, n, 0) != n) + fprintf(stderr, "Failed to send %i bytes to syslog\n", n); +} diff --git a/log.h b/log.h new file mode 100644 index 0000000..70cad6f --- /dev/null +++ b/log.h @@ -0,0 +1,26 @@ +/* SPDX-License-Identifier: AGPL-3.0-or-later + * Copyright (c) 2022 Red Hat GmbH + * Author: Stefano Brivio + */ + +#ifndef LOG_H +#define LOG_H + +void err(const char *format, ...); +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) + +void __openlog(const char *ident, int option, int facility); +void passt_vsyslog(int pri, const char *format, va_list ap); +void __setlogmask(int mask); + +#endif /* LOG_H */ diff --git a/ndp.c b/ndp.c index 29c4b14..dec36a9 100644 --- a/ndp.c +++ b/ndp.c @@ -30,6 +30,7 @@ #include "util.h" #include "passt.h" #include "tap.h" +#include "log.h"

#define RS 133 #define RA 134 diff --git a/netlink.c b/netlink.c index 15ce213..9719e91 100644 --- a/netlink.c +++ b/netlink.c @@ -30,6 +30,7 @@

#include "util.h" #include "passt.h" +#include "log.h" #include "netlink.h"

/* Socket in init, in target namespace, sequence (just needs to be monotonic) */ diff --git a/packet.c b/packet.c index 6d10ec1..3f82e84 100644 --- a/packet.c +++ b/packet.c @@ -20,6 +20,7 @@

#include "packet.h" #include "util.h" +#include "log.h"

/** * packet_add_do() - Add data as packet descriptor to given pool diff --git a/passt.c b/passt.c index 2c4a986..0c561b2 100644 --- a/passt.c +++ b/passt.c @@ -44,6 +44,7 @@ #include "conf.h" #include "pasta.h" #include "arch.h" +#include "log.h"

#define EPOLL_EVENTS 8

diff --git a/pasta.c b/pasta.c index 1dd8267..1887dd2 100644 --- a/pasta.c +++ b/pasta.c @@ -44,6 +44,7 @@ #include "passt.h" #include "isolation.h" #include "netlink.h" +#include "log.h"

/* PID of child, in case we created a namespace */ static int pasta_child_pid; diff --git a/pcap.c b/pcap.c index 7a48baf..836688d 100644 --- a/pcap.c +++ b/pcap.c @@ -30,6 +30,7 @@

#include "util.h" #include "passt.h" +#include "log.h"

#define PCAP_VERSION_MINOR 4

diff --git a/tap.c b/tap.c index 5540c18..bdcc161 100644 --- a/tap.c +++ b/tap.c @@ -52,6 +52,7 @@ #include "netlink.h" #include "pasta.h" #include "packet.h" +#include "log.h"

/* IPv4 (plus ARP) and IPv6 message batches from tap/guest to IP handlers */ static PACKET_POOL_NOINIT(pool_tap4, TAP_MSGS, pkt_buf); diff --git a/tcp.c b/tcp.c index 8ec991c..830dc88 100644 --- a/tcp.c +++ b/tcp.c @@ -298,6 +298,7 @@ #include "pcap.h" #include "conf.h" #include "tcp_splice.h" +#include "log.h"

#define TCP_FRAMES_MEM 128 #define TCP_FRAMES \ diff --git a/tcp_splice.c b/tcp_splice.c index edbcfd4..4a015d0 100644 --- a/tcp_splice.c +++ b/tcp_splice.c @@ -47,6 +47,7 @@

#include "util.h" #include "passt.h" +#include "log.h"

#define MAX_PIPE_SIZE (8UL * 1024 * 1024) #define TCP_SPLICE_MAX_CONNS (128 * 1024) diff --git a/udp.c b/udp.c index d1be622..5422fdd 100644 --- a/udp.c +++ b/udp.c @@ -116,6 +116,7 @@ #include "passt.h" #include "tap.h" #include "pcap.h" +#include "log.h"

#define UDP_CONN_TIMEOUT 180 /* s, timeout for ephemeral or local bind */ #define UDP_SPLICE_FRAMES 32 diff --git a/util.c b/util.c index 6b86ead..b366167 100644 --- a/util.c +++ b/util.c @@ -19,8 +19,6 @@ #include #include #include -#include -#include #include #include #include @@ -29,124 +27,7 @@ #include "passt.h" #include "packet.h" #include "lineread.h" - -/* For __openlog() and __setlogmask() wrappers, and passt_vsyslog() */ -static int log_mask; -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, ...) { \ - struct timespec tp; \ - va_list args; \ - \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG)) { \ - clock_gettime(CLOCK_REALTIME, &tp); \ - fprintf(stderr, "%li.%04li: ", \ - tp.tv_sec - log_debug_start, \ - tp.tv_nsec / (100L * 1000)); \ - } else { \ - va_start(args, format); \ - passt_vsyslog(level, format, args); \ - va_end(args); \ - } \ - \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ - setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ - va_start(args, format); \ - (void)vfprintf(stderr, format, args); \ - va_end(args); \ - if (format[strlen(format)] != '\n') \ - fprintf(stderr, "\n"); \ - } \ -} - -logfn(err, LOG_ERR) -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) - * @option: openlog() options - * @facility: openlog() facility (LOG_DAEMON) - */ -void __openlog(const char *ident, int option, int facility) -{ - struct timespec tp; - - clock_gettime(CLOCK_REALTIME, &tp); - log_debug_start = tp.tv_sec; - - if (log_sock < 0) { - struct sockaddr_un a = { .sun_family = AF_UNIX, }; - - log_sock = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0); - if (log_sock < 0) - return; - - strncpy(a.sun_path, _PATH_LOG, sizeof(a.sun_path)); - if (connect(log_sock, (const struct sockaddr *)&a, sizeof(a))) { - close(log_sock); - log_sock = -1; - return; - } - } - - log_mask |= facility; - strncpy(log_ident, ident, sizeof(log_ident) - 1); - log_opt = option; - - openlog(ident, option, facility); -} - -/** - * __setlogmask() - setlogmask() wrapper, to allow custom vsyslog() - * @mask: Same as setlogmask() mask - */ -void __setlogmask(int mask) -{ - log_mask = mask; - setlogmask(mask); -} - -/** - * passt_vsyslog() - vsyslog() implementation not using heap memory - * @pri: Facility and level map, same as priority for vsyslog() - * @format: Same as vsyslog() format - * @ap: Same as vsyslog() ap - */ -void passt_vsyslog(int pri, const char *format, va_list ap) -{ - char buf[BUFSIZ]; - int n; - - if (!(LOG_MASK(LOG_PRI(pri)) & log_mask)) - return; - - /* Send without name and timestamp, the system logger should add them */ - n = snprintf(buf, BUFSIZ, "<%i> ", pri); - - n += vsnprintf(buf + n, BUFSIZ - n, format, ap); - - if (format[strlen(format)] != '\n') - n += snprintf(buf + n, BUFSIZ - n, "\n"); - - if (log_opt & LOG_PERROR) - fprintf(stderr, "%s", buf + sizeof("<0>")); - - if (send(log_sock, buf, n, 0) != n) - fprintf(stderr, "Failed to send %i bytes to syslog\n", n); -} +#include "log.h"

#define IPV6_NH_OPT(nh) \ ((nh) == 0 || (nh) == 43 || (nh) == 44 || (nh) == 50 || \ diff --git a/util.h b/util.h index 0c06e34..1adbf04 100644 --- a/util.h +++ b/util.h @@ -6,19 +6,6 @@ #ifndef UTIL_H #define UTIL_H

-void err(const char *format, ...); -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 @@ -196,9 +183,6 @@ struct ipv6_opt_hdr {

/* cppcheck-suppress funcArgNamesDifferent */ __attribute__ ((weak)) int ffsl(long int i) { return __builtin_ffsl(i); } -void __openlog(const char *ident, int option, int facility); -void passt_vsyslog(int pri, const char *format, va_list ap); -void __setlogmask(int mask); char *ipv6_l4hdr(const struct pool *p, int index, size_t offset, uint8_t *proto, size_t *dlen); int sock_l4(const struct ctx *c, int af, uint8_t proto,

-- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, Oct 07, 2022 at 02:47:36AM +0200, Stefano Brivio wrote:

This originated as a result of copy and paste to introduce a second stage for processing options related to port forwarding, has already bitten David in the past, and just gave me hours of fun.

As a matter of fact, the second set of optstring assignments was already incorrect, but it didn't matter because the first one was more restrictive, not allowing optional arguments for -P, -D, -S.

Signed-off-by: Stefano Brivio

Reviewed-by: David Gibson

--- conf.c | 20 ++++++-------------- 1 file changed, 6 insertions(+), 14 deletions(-)

diff --git a/conf.c b/conf.c index ba1d8de..e9cd4a7 100644 --- a/conf.c +++ b/conf.c @@ -1043,25 +1043,23 @@ void conf(struct ctx *c, int argc, char **argv) struct fqdn *dnss = c->dns_search; uint32_t *dns4 = c->ip4.dns; int name, ret, mask, b, i; + const char *optstring; unsigned int ifi = 0; char *runas = NULL; uid_t uid; gid_t gid;

- if (c->mode == MODE_PASTA) + if (c->mode == MODE_PASTA) { c->no_dhcp_dns = c->no_dhcp_dns_search = 1; + optstring = "dqfehI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; + } else { + optstring = "dqfehs:p:P:m:a:n:M:g:i:D:S:46t:u:"; + }

c->tcp.fwd_in.mode = c->tcp.fwd_out.mode = 0; c->udp.fwd_in.f.mode = c->udp.fwd_out.f.mode = 0;

do { - const char *optstring; - - if (c->mode == MODE_PASST) - optstring = "dqfehs:p:P:m:a:n:M:g:i:D:S:46t:u:"; - else - optstring = "dqfehI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; - name = getopt_long(argc, argv, optstring, options, NULL);

switch (name) { @@ -1505,12 +1503,6 @@ void conf(struct ctx *c, int argc, char **argv) optind = 1; do { struct port_fwd *fwd = NULL; - const char *optstring; - - if (c->mode == MODE_PASST) - optstring = "dqfehs:p::P:m:a:n:M:g:i:D::S::46t:u:"; - else - optstring = "dqfehI:p::P:m:a:n:M:g:i:D::S::46t:u:T:U:";

name = getopt_long(argc, argv, optstring, options, NULL); switch (name) {

-- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, Oct 07, 2022 at 02:47:37AM +0200, Stefano Brivio wrote:

This saves some hassle when including passt.h, as we need ETH_ALEN there.

Signed-off-by: Stefano Brivio

Hrm. So I had the impression that passt was using the convention that it's the top level files responsibility to include all the dependencies for a header before including the header, rather than having headers include other headers they need. Was I mistaken? I'm ok with either model, they each have their advantages, but I find sticking to one or the other is generally better than a mix of both. That is, it would be helpful to me for you to clarify the policy, but for this specific patch Reviewed-by: David Gibson

--- passt.h | 2 ++ 1 file changed, 2 insertions(+)

diff --git a/passt.h b/passt.h index 48e1096..de79e7b 100644 --- a/passt.h +++ b/passt.h @@ -133,6 +133,8 @@ struct ip6_ctx { struct in6_addr dns_fwd; };

+#include + /** * struct ctx - Execution context * @mode: Operation mode, qemu/UNIX domain socket or namespace/tap

-- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, 7 Oct 2022 17:51:52 +1100 David Gibson wrote:

On Fri, Oct 07, 2022 at 02:47:38AM +0200, Stefano Brivio wrote:

...

In some environments, such as KubeVirt pods, we might not have a system logger available. We could choose to run in foreground, but this takes away the convenient synchronisation mechanism derived from forking to background when interfaces are ready.

Add optional logging to file with -l/--log-file and --log-size.

Unfortunately, this means we need to duplicate features that are more appropriately implemented by a system logger, such as rotation. Keep that reasonably simple, by using fallocate() with range collapsing where supported (Linux kernel >= 3.15, extent-based ext4 and XFS) and falling back to an unsophisticated block-by-block moving of entries toward the beginning of the file once we reach the (mandatory) size limit.

While at it, clarify the role of LOG_EMERG in passt.c.

Signed-off-by: Stefano Brivio --- Makefile | 2 +- README.md | 2 +- conf.c | 49 ++++++++++- log.c | 251 ++++++++++++++++++++++++++++++++++++++++++++++++++---- log.h | 6 ++ passt.1 | 14 ++- passt.c | 1 + 7 files changed, 300 insertions(+), 25 deletions(-)

diff --git a/Makefile b/Makefile index 74bbfeb..fafb024 100644 --- a/Makefile +++ b/Makefile @@ -41,7 +41,7 @@ SRCS = $(PASST_SRCS) $(QRAP_SRCS) MANPAGES = passt.1 pasta.1 qrap.1

PASST_HEADERS = arch.h arp.h checksum.h conf.h dhcp.h dhcpv6.h icmp.h \ - isolation.h lineread.h ndp.h netlink.h packet.h passt.h pasta.h \ + isolation.h lineread.h log.h ndp.h netlink.h packet.h passt.h pasta.h \ pcap.h port_fwd.h siphash.h tap.h tcp.h tcp_splice.h udp.h util.h HEADERS = $(PASST_HEADERS) seccomp.h

diff --git a/README.md b/README.md index 2c522b2..3dc4fc5 100644 --- a/README.md +++ b/README.md @@ -289,7 +289,7 @@ speeding up local connections, and usually requiring NAT. _pasta_: * ✅ all capabilities dropped, other than `CAP_NET_BIND_SERVICE` (if granted) * ✅ with default options, user, mount, IPC, UTS, PID namespaces are detached * ✅ no external dependencies (other than a standard C library) -* ✅ restrictive seccomp profiles (26 syscalls allowed for _passt_, 40 for +* ✅ restrictive seccomp profiles (30 syscalls allowed for _passt_, 41 for _pasta_ on x86_64)

That's a pity, but I guess we need it.

Yeah :( I started having thoughts about adding some granularity to seccomp profiles based on what arguments are passed, but it still looked a bit overkill just for this.

...

* ✅ examples of [AppArmor](/passt/tree/contrib/apparmor) and [SELinux](/passt/tree/contrib/selinux) profiles available diff --git a/conf.c b/conf.c index e9cd4a7..f22940b 100644 --- a/conf.c +++ b/conf.c @@ -633,6 +633,9 @@ static void usage(const char *name) info( " default: run in background if started from a TTY"); info( " -e, --stderr Log to stderr too"); info( " default: log to system logger only if started from a TTY"); + info( " -l, --log-file PATH Log (only) to given file"); + info( " --log-size BYTES Maximum size of log file"); + info( " default: 1 MiB"); info( " --runas UID|UID:GID Run as given UID, GID, which can be"); info( " numeric, or login and group names"); info( " default: drop to user \"nobody\""); @@ -994,6 +997,7 @@ void conf(struct ctx *c, int argc, char **argv) {"quiet", no_argument, NULL, 'q' }, {"foreground", no_argument, NULL, 'f' }, {"stderr", no_argument, NULL, 'e' }, + {"log-file", required_argument, NULL, 'l' }, {"help", no_argument, NULL, 'h' }, {"socket", required_argument, NULL, 's' }, {"ns-ifname", required_argument, NULL, 'I' }, @@ -1034,26 +1038,28 @@ void conf(struct ctx *c, int argc, char **argv) {"no-netns-quit", no_argument, NULL, 10 }, {"trace", no_argument, NULL, 11 }, {"runas", required_argument, NULL, 12 }, + {"log-size", required_argument, NULL, 13 }, { 0 }, }; struct get_bound_ports_ns_arg ns_ports_arg = { .c = c }; char userns[PATH_MAX] = { 0 }, netns[PATH_MAX] = { 0 }; bool v4_only = false, v6_only = false; + char *runas = NULL, *logfile = NULL; struct in6_addr *dns6 = c->ip6.dns; struct fqdn *dnss = c->dns_search; uint32_t *dns4 = c->ip4.dns; int name, ret, mask, b, i; const char *optstring; unsigned int ifi = 0; - char *runas = NULL; + size_t logsize = 0; uid_t uid; gid_t gid;

if (c->mode == MODE_PASTA) { c->no_dhcp_dns = c->no_dhcp_dns_search = 1; - optstring = "dqfehI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; + optstring = "dqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; } else { - optstring = "dqfehs:p:P:m:a:n:M:g:i:D:S:46t:u:"; + optstring = "dqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; }

c->tcp.fwd_in.mode = c->tcp.fwd_out.mode = 0; @@ -1177,6 +1183,20 @@ void conf(struct ctx *c, int argc, char **argv)

runas = optarg; break; + case 13: + if (logsize) { + err("Multiple --log-size options given"); + usage(argv[0]); + } + + errno = 0; + logsize = strtol(optarg, NULL, 0); + + if (logsize < LOGFILE_SIZE_MIN || errno) { + err("Invalid --log-size: %s", optarg); + usage(argv[0]); + } + break; case 'd': if (c->debug) { err("Multiple --debug options given"); @@ -1192,6 +1212,11 @@ void conf(struct ctx *c, int argc, char **argv) c->foreground = 1; break; case 'e': + if (logfile) { + err("Can't log to both file and stderr"); + usage(argv[0]); + } + if (c->stderr) { err("Multiple --stderr options given"); usage(argv[0]); @@ -1199,6 +1224,19 @@ void conf(struct ctx *c, int argc, char **argv)

c->stderr = 1; break; + case 'l': + if (c->stderr) { + err("Can't log to both stderr and file"); + usage(argv[0]); + } + + if (logfile) { + err("Multiple --log-file options given"); + usage(argv[0]); + } + + logfile = optarg; + break; case 'q': if (c->quiet) { err("Multiple --quiet options given"); @@ -1460,6 +1498,11 @@ void conf(struct ctx *c, int argc, char **argv) if (ret) usage(argv[0]);

+ if (logfile) { + logfile_init(c->mode == MODE_PASST ? "passt" : "pasta", + logfile, logsize); + } + if (c->mode == MODE_PASTA) { if (conf_pasta_ns(&netns_only, userns, netns, optind, argc, argv) < 0) diff --git a/log.c b/log.c index 54a7cbb..1e405e3 100644 --- a/log.c +++ b/log.c @@ -12,7 +12,12 @@ * Author: Stefano Brivio */

+#include +#include +#include +#include #include +#include #include #include #include @@ -20,36 +25,49 @@ #include #include #include -#include

#include "log.h" +#include "util.h" +#include "passt.h"

-/* For __openlog() and __setlogmask() wrappers, and passt_vsyslog() */ -static int log_mask; -static int log_sock = -1; -static char log_ident[BUFSIZ]; -static int log_opt; -static time_t log_debug_start; -int log_trace; +static int log_sock = -1; /* Optional socket to system logger */ +static char log_ident[BUFSIZ]; /* Identifier string for openlog() */ +static int log_mask; /* Current log priority mask */ +static int log_opt; /* Options for openlog() */ + +static int log_file = -1; /* Optional log file descriptor */ +static size_t log_size; /* Maximum log file size in bytes */ +static size_t log_written; /* Currently used bytes in log file */ +static size_t log_cut_size; /* Bytes to cut at start on rotation */ +static char log_header[BUFSIZ]; /* File header, written back on cuts */ + +static time_t log_start; /* Start timestamp */ +int log_trace; /* --trace mode enabled */

#define logfn(name, level) \ void name(const char *format, ...) { \ struct timespec tp; \ va_list args; \ \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG)) { \ + if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) { \ clock_gettime(CLOCK_REALTIME, &tp); \ fprintf(stderr, "%li.%04li: ", \ - tp.tv_sec - log_debug_start, \ + tp.tv_sec - log_start, \ tp.tv_nsec / (100L * 1000)); \ - } else { \ + } \ + \ + if ((LOG_MASK(LOG_PRI(level)) & log_mask) || \ + setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ va_start(args, format); \ - passt_vsyslog(level, format, args); \ + if (log_file != -1) \ + logfile_write(level, format, args); \ + else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG))) \ + passt_vsyslog(level, format, args); \ va_end(args); \ } \ \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ - setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ + if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ + setlogmask(0) == LOG_MASK(LOG_EMERG)) && log_file == -1) { \ va_start(args, format); \ (void)vfprintf(stderr, format, args); \ va_end(args); \ @@ -58,6 +76,16 @@ void name(const char *format, ...) { \ } \ }

+/* Prefixes for log file messages, indexed by priority */ +const char *logfile_prefix[] = { + NULL, NULL, NULL, /* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */ + "ERROR: ", + "WARNING: ", + NULL, /* Unused: LOG_NOTICE */ + "info: ", + " ", /* LOG_DEBUG */ +}; + logfn(err, LOG_ERR) logfn(warn, LOG_WARNING) logfn(info, LOG_INFO) @@ -79,7 +107,7 @@ void __openlog(const char *ident, int option, int facility) struct timespec tp;

clock_gettime(CLOCK_REALTIME, &tp); - log_debug_start = tp.tv_sec; + log_start = tp.tv_sec;

if (log_sock < 0) { struct sockaddr_un a = { .sun_family = AF_UNIX, }; @@ -124,9 +152,6 @@ void passt_vsyslog(int pri, const char *format, va_list ap) char buf[BUFSIZ]; int n;

- if (!(LOG_MASK(LOG_PRI(pri)) & log_mask)) - return; - /* Send without name and timestamp, the system logger should add them */ n = snprintf(buf, BUFSIZ, "<%i> ", pri);

@@ -141,3 +166,193 @@ void passt_vsyslog(int pri, const char *format, va_list ap) if (send(log_sock, buf, n, 0) != n) fprintf(stderr, "Failed to send %i bytes to syslog\n", n); } + +/** + * logfile_init() - Open log file and write header with PID and path + * @name: Identifier for header: passt or pasta + * @path: Path to log file + * @size: Maximum size of log file: log_cut_size is calculatd here + */ +void logfile_init(const char *name, const char *path, size_t size) +{ + char nl = '\n', exe[PATH_MAX] = { 0 }; + int n; + + if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) { + perror("readlink /proc/self/exe"); + exit(EXIT_FAILURE); + } + + log_file = open(path, O_CREAT | O_TRUNC | O_APPEND | O_RDWR | O_CLOEXEC, + S_IRUSR | S_IWUSR);

Do

?

...

+ if (log_file == -1) { + err("Couldn't open log file %s: %s", path, strerror(errno)); + exit(EXIT_FAILURE); + } + + log_size = size ? size : LOGFILE_SIZE_DEFAULT; + + n = snprintf(log_header, sizeof(log_header), "%s: %s (%i)", + name, exe, getpid()); + + if (write(log_file, log_header, n) <= 0 || + write(log_file, &nl, 1) <= 0) { + perror("Couldn't write to log file\n"); + exit(EXIT_FAILURE); + } + + /* For FALLOC_FL_COLLAPSE_RANGE: VFS block size can be up to one page */ + log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE); +} + +/** + * logfile_rotate_fallocate() - Write header, set log_written after fallocate() + * @fd: Log file descriptor + * @ts: Current timestamp + * + * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + */ +static void logfile_rotate_fallocate(int fd, struct timespec *ts) +{ + char buf[BUFSIZ], *nl; + int n; + + if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (read(fd, buf, BUFSIZ) == -1) + return; + + n = snprintf(buf, BUFSIZ, + "%s - log truncated at %li.%04li", log_header, + ts->tv_sec - log_start, ts->tv_nsec / (100L * 1000)); + + /* Avoid partial lines by padding the header with spaces */ + nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1); + if (nl) + memset(buf + n, ' ', nl - (buf + n)); + + if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (write(fd, buf, BUFSIZ) == -1)

Have you tested this path? I thought with O_APPEND, this write would go at the end, regardless of the lseek() above.

With O_APPEND, it would, that's why the caller drops it before we enter this function.

...

+ return; + + log_written -= log_cut_size; +} + +/** + * logfile_rotate_move() - Fallback: move recent entries toward start, then cut + * @fd: Log file descriptor + * @ts: Current timestamp + * + * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + * #syscalls ftruncate + */ +static void logfile_rotate_move(int fd, struct timespec *ts) +{ + int header_len, write_offset, end, discard, n; + char buf[BUFSIZ], *nl; + + header_len = snprintf(buf, BUFSIZ, + "%s - log truncated at %li.%04li\n", log_header, + ts->tv_sec - log_start, + ts->tv_nsec / (100L * 1000));

A common helper for the truncation header seems like it would be a good idea.

There's a newline here, but not in the other case, because here we don't need any padding, given that we're not affected by the alignment of FALLOC_FL_COLLAPSE_RANGE. I tried to have this in a common path, and it invariably leads to splitting into two writes (header plus newline, or header plus padding), which looks worse than the alternative...

...

+ if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (write(fd, buf, header_len) == -1) + return; + + end = write_offset = header_len; + discard = log_cut_size + header_len; + + /* Try to cut cleanly at newline */ + if (lseek(fd, discard, SEEK_SET) == -1) + goto out; + if ((n = read(fd, buf, BUFSIZ)) <= 0) + goto out; + if ((nl = memchr(buf, '\n', n))) + discard += (nl - buf) + 1; + + /* Go to first block to be moved */ + if (lseek(fd, discard, SEEK_SET) == -1) + goto out; + + while ((n = read(fd, buf, BUFSIZ)) > 0) { + end = header_len;

Hrm.. so errors in this section will throw away everything except the header.

...

+ + if (lseek(fd, write_offset, SEEK_SET) == -1) + goto out; + if ((n = write(fd, buf, n)) == -1) + goto out; + write_offset += n; + + if ((n = lseek(fd, 0, SEEK_CUR)) == -1) + goto out; + end = n;

But errors after here will just throw away what we haven't moved so far. Seems a bit inconsistent.

Um, right, I should move this assignment to the end of the loop, after the lseek() below.

...

+ + if (lseek(fd, discard - header_len, SEEK_CUR) == -1) + goto out; + }

I wonder if those whole function would be made simpler using pread() and pwrite() instead of lseek()s all over the place.

Yes, definitely, but I'm afraid we need to keep at least a couple of lseek()s too (see BUGS in the man page of pread() implying I need to switch O_APPEND on and off), and that would mean enabling three additional syscalls, instead of just one. And even if I manage to drop all the lseek()s, would this be worth two additional syscalls instead of one? I'm not sure...

...

+out: + if (ftruncate(fd, end)) + return; + + log_written = end; +} + +/** + * logfile_rotate() - "Rotate" log file once it's full + * @fd: Log file descriptor + * @ts: Current timestamp + * + * Return: 0 on success, negative error code on failure + * + * #syscalls fallocate fcntl + */ +static int logfile_rotate(int fd, struct timespec *ts) +{ + if (fcntl(fd, F_SETFL, O_RDWR /* Drop O_APPEND: explicit lseek() */)) + return -errno; + + /* Collapsing only for Linux kernel >= 3.15, extent-based ext4 or XFS */ + if (!fallocate(fd, FALLOC_FL_COLLAPSE_RANGE, 0, log_cut_size)) + logfile_rotate_fallocate(fd, ts); + else + logfile_rotate_move(fd, ts); + + if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND)) + return -errno; + + return 0; +} + +/** + * logfile_write() - Write entry to log file, trigger rotation if full + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Same as vsyslog() format + * @ap: Same as vsyslog() ap + */ +void logfile_write(int pri, const char *format, va_list ap) +{ + struct timespec ts; + char buf[BUFSIZ]; + int n; + + if (clock_gettime(CLOCK_REALTIME, &ts)) + return; + + n = snprintf(buf, BUFSIZ, "%li.%04li: %s", + ts.tv_sec - log_start, ts.tv_nsec / (100L * 1000), + logfile_prefix[pri]); + + n += vsnprintf(buf + n, BUFSIZ - n, format, ap); + + if (format[strlen(format)] != '\n') + n += snprintf(buf + n, BUFSIZ - n, "\n"); + + if ((log_written + n >= log_size) && logfile_rotate(log_file, &ts)) + return; + + if ((n = write(log_file, buf, n)) >= 0) + log_written += n; +} diff --git a/log.h b/log.h index 70cad6f..ed71cd7 100644 --- a/log.h +++ b/log.h @@ -6,6 +6,10 @@ #ifndef LOG_H #define LOG_H

+#define LOGFILE_SIZE_DEFAULT 1E6

Wouldn't a multiple of the block size make more sense?

In practice, that's already the case for most archs, with this being 256 pages in the vast majority of cases. If I make it explicit, though, I can't report a default value in the man page, which I feel is an important information to have there. Also... does it really matter? fallocate(), here, just cares about blocks we drop from the beginning, not blocks we use in total. -- Stefano

On Fri, 7 Oct 2022 19:57:19 +1100 David Gibson wrote:

On Fri, Oct 07, 2022 at 10:11:45AM +0200, Stefano Brivio wrote:

...

On Fri, 7 Oct 2022 17:51:52 +1100 David Gibson wrote:

...

On Fri, Oct 07, 2022 at 02:47:38AM +0200, Stefano Brivio wrote:

...

In some environments, such as KubeVirt pods, we might not have a system logger available. We could choose to run in foreground, but this takes away the convenient synchronisation mechanism derived from forking to background when interfaces are ready.

Add optional logging to file with -l/--log-file and --log-size.

Unfortunately, this means we need to duplicate features that are more appropriately implemented by a system logger, such as rotation. Keep that reasonably simple, by using fallocate() with range collapsing where supported (Linux kernel >= 3.15, extent-based ext4 and XFS) and falling back to an unsophisticated block-by-block moving of entries toward the beginning of the file once we reach the (mandatory) size limit.

While at it, clarify the role of LOG_EMERG in passt.c.

Signed-off-by: Stefano Brivio --- Makefile | 2 +- README.md | 2 +- conf.c | 49 ++++++++++- log.c | 251 ++++++++++++++++++++++++++++++++++++++++++++++++++---- log.h | 6 ++ passt.1 | 14 ++- passt.c | 1 + 7 files changed, 300 insertions(+), 25 deletions(-)

diff --git a/Makefile b/Makefile index 74bbfeb..fafb024 100644 --- a/Makefile +++ b/Makefile @@ -41,7 +41,7 @@ SRCS = $(PASST_SRCS) $(QRAP_SRCS) MANPAGES = passt.1 pasta.1 qrap.1

PASST_HEADERS = arch.h arp.h checksum.h conf.h dhcp.h dhcpv6.h icmp.h \ - isolation.h lineread.h ndp.h netlink.h packet.h passt.h pasta.h \ + isolation.h lineread.h log.h ndp.h netlink.h packet.h passt.h pasta.h \ pcap.h port_fwd.h siphash.h tap.h tcp.h tcp_splice.h udp.h util.h HEADERS = $(PASST_HEADERS) seccomp.h

diff --git a/README.md b/README.md index 2c522b2..3dc4fc5 100644 --- a/README.md +++ b/README.md @@ -289,7 +289,7 @@ speeding up local connections, and usually requiring NAT. _pasta_: * ✅ all capabilities dropped, other than `CAP_NET_BIND_SERVICE` (if granted) * ✅ with default options, user, mount, IPC, UTS, PID namespaces are detached * ✅ no external dependencies (other than a standard C library) -* ✅ restrictive seccomp profiles (26 syscalls allowed for _passt_, 40 for +* ✅ restrictive seccomp profiles (30 syscalls allowed for _passt_, 41 for _pasta_ on x86_64)

That's a pity, but I guess we need it.

Yeah :( I started having thoughts about adding some granularity to seccomp profiles based on what arguments are passed, but it still looked a bit overkill just for this.

...

...

* ✅ examples of [AppArmor](/passt/tree/contrib/apparmor) and [SELinux](/passt/tree/contrib/selinux) profiles available diff --git a/conf.c b/conf.c index e9cd4a7..f22940b 100644 --- a/conf.c +++ b/conf.c @@ -633,6 +633,9 @@ static void usage(const char *name) info( " default: run in background if started from a TTY"); info( " -e, --stderr Log to stderr too"); info( " default: log to system logger only if started from a TTY"); + info( " -l, --log-file PATH Log (only) to given file"); + info( " --log-size BYTES Maximum size of log file"); + info( " default: 1 MiB"); info( " --runas UID|UID:GID Run as given UID, GID, which can be"); info( " numeric, or login and group names"); info( " default: drop to user \"nobody\""); @@ -994,6 +997,7 @@ void conf(struct ctx *c, int argc, char **argv) {"quiet", no_argument, NULL, 'q' }, {"foreground", no_argument, NULL, 'f' }, {"stderr", no_argument, NULL, 'e' }, + {"log-file", required_argument, NULL, 'l' }, {"help", no_argument, NULL, 'h' }, {"socket", required_argument, NULL, 's' }, {"ns-ifname", required_argument, NULL, 'I' }, @@ -1034,26 +1038,28 @@ void conf(struct ctx *c, int argc, char **argv) {"no-netns-quit", no_argument, NULL, 10 }, {"trace", no_argument, NULL, 11 }, {"runas", required_argument, NULL, 12 }, + {"log-size", required_argument, NULL, 13 }, { 0 }, }; struct get_bound_ports_ns_arg ns_ports_arg = { .c = c }; char userns[PATH_MAX] = { 0 }, netns[PATH_MAX] = { 0 }; bool v4_only = false, v6_only = false; + char *runas = NULL, *logfile = NULL; struct in6_addr *dns6 = c->ip6.dns; struct fqdn *dnss = c->dns_search; uint32_t *dns4 = c->ip4.dns; int name, ret, mask, b, i; const char *optstring; unsigned int ifi = 0; - char *runas = NULL; + size_t logsize = 0; uid_t uid; gid_t gid;

if (c->mode == MODE_PASTA) { c->no_dhcp_dns = c->no_dhcp_dns_search = 1; - optstring = "dqfehI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; + optstring = "dqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; } else { - optstring = "dqfehs:p:P:m:a:n:M:g:i:D:S:46t:u:"; + optstring = "dqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; }

c->tcp.fwd_in.mode = c->tcp.fwd_out.mode = 0; @@ -1177,6 +1183,20 @@ void conf(struct ctx *c, int argc, char **argv)

runas = optarg; break; + case 13: + if (logsize) { + err("Multiple --log-size options given"); + usage(argv[0]); + } + + errno = 0; + logsize = strtol(optarg, NULL, 0); + + if (logsize < LOGFILE_SIZE_MIN || errno) { + err("Invalid --log-size: %s", optarg); + usage(argv[0]); + } + break; case 'd': if (c->debug) { err("Multiple --debug options given"); @@ -1192,6 +1212,11 @@ void conf(struct ctx *c, int argc, char **argv) c->foreground = 1; break; case 'e': + if (logfile) { + err("Can't log to both file and stderr"); + usage(argv[0]); + } + if (c->stderr) { err("Multiple --stderr options given"); usage(argv[0]); @@ -1199,6 +1224,19 @@ void conf(struct ctx *c, int argc, char **argv)

c->stderr = 1; break; + case 'l': + if (c->stderr) { + err("Can't log to both stderr and file"); + usage(argv[0]); + } + + if (logfile) { + err("Multiple --log-file options given"); + usage(argv[0]); + } + + logfile = optarg; + break; case 'q': if (c->quiet) { err("Multiple --quiet options given"); @@ -1460,6 +1498,11 @@ void conf(struct ctx *c, int argc, char **argv) if (ret) usage(argv[0]);

+ if (logfile) { + logfile_init(c->mode == MODE_PASST ? "passt" : "pasta", + logfile, logsize); + } + if (c->mode == MODE_PASTA) { if (conf_pasta_ns(&netns_only, userns, netns, optind, argc, argv) < 0) diff --git a/log.c b/log.c index 54a7cbb..1e405e3 100644 --- a/log.c +++ b/log.c @@ -12,7 +12,12 @@ * Author: Stefano Brivio */

+#include +#include +#include +#include #include +#include #include #include #include @@ -20,36 +25,49 @@ #include #include #include -#include

#include "log.h" +#include "util.h" +#include "passt.h"

-/* For __openlog() and __setlogmask() wrappers, and passt_vsyslog() */ -static int log_mask; -static int log_sock = -1; -static char log_ident[BUFSIZ]; -static int log_opt; -static time_t log_debug_start; -int log_trace; +static int log_sock = -1; /* Optional socket to system logger */ +static char log_ident[BUFSIZ]; /* Identifier string for openlog() */ +static int log_mask; /* Current log priority mask */ +static int log_opt; /* Options for openlog() */ + +static int log_file = -1; /* Optional log file descriptor */ +static size_t log_size; /* Maximum log file size in bytes */ +static size_t log_written; /* Currently used bytes in log file */ +static size_t log_cut_size; /* Bytes to cut at start on rotation */ +static char log_header[BUFSIZ]; /* File header, written back on cuts */ + +static time_t log_start; /* Start timestamp */ +int log_trace; /* --trace mode enabled */

#define logfn(name, level) \ void name(const char *format, ...) { \ struct timespec tp; \ va_list args; \ \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG)) { \ + if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) { \ clock_gettime(CLOCK_REALTIME, &tp); \ fprintf(stderr, "%li.%04li: ", \ - tp.tv_sec - log_debug_start, \ + tp.tv_sec - log_start, \ tp.tv_nsec / (100L * 1000)); \ - } else { \ + } \ + \ + if ((LOG_MASK(LOG_PRI(level)) & log_mask) || \ + setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ va_start(args, format); \ - passt_vsyslog(level, format, args); \ + if (log_file != -1) \ + logfile_write(level, format, args); \ + else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG))) \ + passt_vsyslog(level, format, args); \ va_end(args); \ } \ \ - if (setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ - setlogmask(0) == LOG_MASK(LOG_EMERG)) { \ + if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) || \ + setlogmask(0) == LOG_MASK(LOG_EMERG)) && log_file == -1) { \ va_start(args, format); \ (void)vfprintf(stderr, format, args); \ va_end(args); \ @@ -58,6 +76,16 @@ void name(const char *format, ...) { \ } \ }

+/* Prefixes for log file messages, indexed by priority */ +const char *logfile_prefix[] = { + NULL, NULL, NULL, /* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */ + "ERROR: ", + "WARNING: ", + NULL, /* Unused: LOG_NOTICE */ + "info: ", + " ", /* LOG_DEBUG */ +}; + logfn(err, LOG_ERR) logfn(warn, LOG_WARNING) logfn(info, LOG_INFO) @@ -79,7 +107,7 @@ void __openlog(const char *ident, int option, int facility) struct timespec tp;

clock_gettime(CLOCK_REALTIME, &tp); - log_debug_start = tp.tv_sec; + log_start = tp.tv_sec;

if (log_sock < 0) { struct sockaddr_un a = { .sun_family = AF_UNIX, }; @@ -124,9 +152,6 @@ void passt_vsyslog(int pri, const char *format, va_list ap) char buf[BUFSIZ]; int n;

- if (!(LOG_MASK(LOG_PRI(pri)) & log_mask)) - return; - /* Send without name and timestamp, the system logger should add them */ n = snprintf(buf, BUFSIZ, "<%i> ", pri);

@@ -141,3 +166,193 @@ void passt_vsyslog(int pri, const char *format, va_list ap) if (send(log_sock, buf, n, 0) != n) fprintf(stderr, "Failed to send %i bytes to syslog\n", n); } + +/** + * logfile_init() - Open log file and write header with PID and path + * @name: Identifier for header: passt or pasta + * @path: Path to log file + * @size: Maximum size of log file: log_cut_size is calculatd here + */ +void logfile_init(const char *name, const char *path, size_t size) +{ + char nl = '\n', exe[PATH_MAX] = { 0 }; + int n; + + if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) { + perror("readlink /proc/self/exe"); + exit(EXIT_FAILURE); + } + + log_file = open(path, O_CREAT | O_TRUNC | O_APPEND | O_RDWR | O_CLOEXEC, + S_IRUSR | S_IWUSR);

Do

?

...

...

+ if (log_file == -1) { + err("Couldn't open log file %s: %s", path, strerror(errno)); + exit(EXIT_FAILURE); + } + + log_size = size ? size : LOGFILE_SIZE_DEFAULT; + + n = snprintf(log_header, sizeof(log_header), "%s: %s (%i)", + name, exe, getpid()); + + if (write(log_file, log_header, n) <= 0 || + write(log_file, &nl, 1) <= 0) { + perror("Couldn't write to log file\n"); + exit(EXIT_FAILURE); + } + + /* For FALLOC_FL_COLLAPSE_RANGE: VFS block size can be up to one page */ + log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE); +} + +/** + * logfile_rotate_fallocate() - Write header, set log_written after fallocate() + * @fd: Log file descriptor + * @ts: Current timestamp + * + * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + */ +static void logfile_rotate_fallocate(int fd, struct timespec *ts) +{ + char buf[BUFSIZ], *nl; + int n; + + if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (read(fd, buf, BUFSIZ) == -1) + return; + + n = snprintf(buf, BUFSIZ, + "%s - log truncated at %li.%04li", log_header, + ts->tv_sec - log_start, ts->tv_nsec / (100L * 1000)); + + /* Avoid partial lines by padding the header with spaces */ + nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1); + if (nl) + memset(buf + n, ' ', nl - (buf + n)); + + if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (write(fd, buf, BUFSIZ) == -1)

Have you tested this path? I thought with O_APPEND, this write would go at the end, regardless of the lseek() above.

With O_APPEND, it would, that's why the caller drops it before we enter this function.

Duh, sorry. I completely missed those fcntl()s.

...

...

...

+ return; + + log_written -= log_cut_size; +} + +/** + * logfile_rotate_move() - Fallback: move recent entries toward start, then cut + * @fd: Log file descriptor + * @ts: Current timestamp + * + * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + * #syscalls ftruncate + */ +static void logfile_rotate_move(int fd, struct timespec *ts) +{ + int header_len, write_offset, end, discard, n; + char buf[BUFSIZ], *nl; + + header_len = snprintf(buf, BUFSIZ, + "%s - log truncated at %li.%04li\n", log_header, + ts->tv_sec - log_start, + ts->tv_nsec / (100L * 1000));

A common helper for the truncation header seems like it would be a good idea.

There's a newline here, but not in the other case, because here we don't need any padding, given that we're not affected by the alignment of FALLOC_FL_COLLAPSE_RANGE.

Ah, ok.

...

I tried to have this in a common path, and it invariably leads to splitting into two writes (header plus newline, or header plus padding), which looks worse than the alternative...

...

...

+ if (lseek(fd, 0, SEEK_SET) == -1) + return; + if (write(fd, buf, header_len) == -1) + return; + + end = write_offset = header_len; + discard = log_cut_size + header_len; + + /* Try to cut cleanly at newline */ + if (lseek(fd, discard, SEEK_SET) == -1) + goto out; + if ((n = read(fd, buf, BUFSIZ)) <= 0) + goto out; + if ((nl = memchr(buf, '\n', n))) + discard += (nl - buf) + 1; + + /* Go to first block to be moved */ + if (lseek(fd, discard, SEEK_SET) == -1) + goto out; + + while ((n = read(fd, buf, BUFSIZ)) > 0) { + end = header_len;

Hrm.. so errors in this section will throw away everything except the header.

...

+ + if (lseek(fd, write_offset, SEEK_SET) == -1) + goto out; + if ((n = write(fd, buf, n)) == -1) + goto out; + write_offset += n; + + if ((n = lseek(fd, 0, SEEK_CUR)) == -1) + goto out; + end = n;

But errors after here will just throw away what we haven't moved so far. Seems a bit inconsistent.

Um, right, I should move this assignment to the end of the loop, after the lseek() below.

...

...

+ + if (lseek(fd, discard - header_len, SEEK_CUR) == -1) + goto out; + }

I wonder if those whole function would be made simpler using pread() and pwrite() instead of lseek()s all over the place.

Yes, definitely, but I'm afraid we need to keep at least a couple of lseek()s too (see BUGS in the man page of pread() implying I need to switch O_APPEND on and off), and that would mean enabling three additional syscalls, instead of just one.

And even if I manage to drop all the lseek()s, would this be worth two additional syscalls instead of one? I'm not sure...

...

...

+out: + if (ftruncate(fd, end)) + return; + + log_written = end; +} + +/** + * logfile_rotate() - "Rotate" log file once it's full + * @fd: Log file descriptor + * @ts: Current timestamp + * + * Return: 0 on success, negative error code on failure + * + * #syscalls fallocate fcntl + */ +static int logfile_rotate(int fd, struct timespec *ts) +{ + if (fcntl(fd, F_SETFL, O_RDWR /* Drop O_APPEND: explicit lseek() */)) + return -errno; + + /* Collapsing only for Linux kernel >= 3.15, extent-based ext4 or XFS */ + if (!fallocate(fd, FALLOC_FL_COLLAPSE_RANGE, 0, log_cut_size)) + logfile_rotate_fallocate(fd, ts); + else + logfile_rotate_move(fd, ts); + + if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND)) + return -errno; + + return 0; +} + +/** + * logfile_write() - Write entry to log file, trigger rotation if full + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Same as vsyslog() format + * @ap: Same as vsyslog() ap + */ +void logfile_write(int pri, const char *format, va_list ap) +{ + struct timespec ts; + char buf[BUFSIZ]; + int n; + + if (clock_gettime(CLOCK_REALTIME, &ts)) + return; + + n = snprintf(buf, BUFSIZ, "%li.%04li: %s", + ts.tv_sec - log_start, ts.tv_nsec / (100L * 1000), + logfile_prefix[pri]); + + n += vsnprintf(buf + n, BUFSIZ - n, format, ap); + + if (format[strlen(format)] != '\n') + n += snprintf(buf + n, BUFSIZ - n, "\n"); + + if ((log_written + n >= log_size) && logfile_rotate(log_file, &ts)) + return; + + if ((n = write(log_file, buf, n)) >= 0) + log_written += n; +} diff --git a/log.h b/log.h index 70cad6f..ed71cd7 100644 --- a/log.h +++ b/log.h @@ -6,6 +6,10 @@ #ifndef LOG_H #define LOG_H

+#define LOGFILE_SIZE_DEFAULT 1E6

Wouldn't a multiple of the block size make more sense?

In practice, that's already the case for most archs, with this being 256 pages in the vast majority of cases. If I make it explicit, though, I can't report a default value in the man page, which I feel is an important information to have there.

Uh.. I must be forgetting my obscure C literal syntax. I assumed 1E6 was 1000000.

Whoops, it actually is (of course, it's powers of 10!). I'll change this to (1024 * 1024), even if it doesn't really matter for fallocate() purposes. -- Stefano

On Fri, Oct 07, 2022 at 02:47:39AM +0200, Stefano Brivio wrote:

Signed-off-by: Stefano Brivio

Reviewed-by: David Gibson

--- log.c | 4 ++++ 1 file changed, 4 insertions(+)

diff --git a/log.c b/log.c index 1e405e3..85b13fe 100644 --- a/log.c +++ b/log.c @@ -91,6 +91,10 @@ logfn(warn, LOG_WARNING) logfn(info, LOG_INFO) logfn(debug, LOG_DEBUG)

+/** + * trace_init() - Set log_trace depending on trace (debug) mode + * @enable: Tracing debug mode enabled if non-zero + */ void trace_init(int enable) { log_trace = enable;

-- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, Oct 07, 2022 at 02:47:40AM +0200, Stefano Brivio wrote:

Now that we can log to file, this might start to be relevant.

Uh... I dont' understand the connection here.

Signed-off-by: Stefano Brivio --- Makefile | 3 +++ conf.c | 12 ++++++++++-- log.c | 4 ++-- passt.1 | 4 ++++ util.h | 8 ++++++++ 5 files changed, 27 insertions(+), 4 deletions(-)

diff --git a/Makefile b/Makefile index fafb024..f7ddb84 100644 --- a/Makefile +++ b/Makefile @@ -9,6 +9,8 @@ # Copyright (c) 2021 Red Hat GmbH # Author: Stefano Brivio

+VERSION ?= $(shell git describe --tags HEAD || echo "unknown\ version") + RLIMIT_STACK_VAL := $(shell /bin/sh -c 'ulimit -s') ifeq ($(RLIMIT_STACK_VAL),unlimited) RLIMIT_STACK_VAL := 1024 @@ -31,6 +33,7 @@ FLAGS += -DNETNS_RUN_DIR=\"/run/netns\" FLAGS += -DPASST_AUDIT_ARCH=AUDIT_ARCH_$(AUDIT_ARCH) FLAGS += -DRLIMIT_STACK_VAL=$(RLIMIT_STACK_VAL) FLAGS += -DARCH=\"$(TARGET_ARCH)\" +FLAGS += -DVERSION=\"$(VERSION)\"

PASST_SRCS = arch.c arp.c checksum.c conf.c dhcp.c dhcpv6.c icmp.c igmp.c \ isolation.c lineread.c log.c mld.c ndp.c netlink.c packet.c passt.c \ diff --git a/conf.c b/conf.c index f22940b..4ec3153 100644 --- a/conf.c +++ b/conf.c @@ -626,6 +626,8 @@ static void usage(const char *name) } info("");

+

Extraneous blank line.

+ info( " -v, --version Show version and exit");

I'd suggest just '--version'. '-v' is "verbose" more often than it is "version".

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"); @@ -993,6 +995,7 @@ void conf(struct ctx *c, int argc, char **argv) { int netns_only = 0; struct option options[] = { + {"version", no_argument, NULL, 'v' }, {"debug", no_argument, NULL, 'd' }, {"quiet", no_argument, NULL, 'q' }, {"foreground", no_argument, NULL, 'f' }, @@ -1057,9 +1060,9 @@ void conf(struct ctx *c, int argc, char **argv)

if (c->mode == MODE_PASTA) { c->no_dhcp_dns = c->no_dhcp_dns_search = 1; - optstring = "dqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; + optstring = "vdqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; } else { - optstring = "dqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; + optstring = "vdqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; }

c->tcp.fwd_in.mode = c->tcp.fwd_out.mode = 0; @@ -1197,6 +1200,11 @@ void conf(struct ctx *c, int argc, char **argv) usage(argv[0]); } break; + case 'v': + fprintf(stdout, + c->mode == MODE_PASST ? "passt " : "pasta "); + fprintf(stdout, VERSION_BLOB); + exit(EXIT_SUCCESS); case 'd': if (c->debug) { err("Multiple --debug options given"); diff --git a/log.c b/log.c index 85b13fe..2b088c4 100644 --- a/log.c +++ b/log.c @@ -172,7 +172,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap) }

/** - * logfile_init() - Open log file and write header with PID and path + * logfile_init() - Open log file and write header with PID, version, path * @name: Identifier for header: passt or pasta * @path: Path to log file * @size: Maximum size of log file: log_cut_size is calculatd here @@ -196,7 +196,7 @@ void logfile_init(const char *name, const char *path, size_t size)

log_size = size ? size : LOGFILE_SIZE_DEFAULT;

- n = snprintf(log_header, sizeof(log_header), "%s: %s (%i)", + n = snprintf(log_header, sizeof(log_header), "%s " VERSION ": %s (%i)", name, exe, getpid());

if (write(log_file, log_header, n) <= 0 || diff --git a/passt.1 b/passt.1 index 64236b6..c63a439 100644 --- a/passt.1 +++ b/passt.1 @@ -77,6 +77,10 @@ for performance reasons.

.SH OPTIONS

+.TP +.BR \-v ", " \-\-version +Show version and exit. + .TP .BR \-d ", " \-\-debug Be verbose, don't run in background, don't log to the system logger. diff --git a/util.h b/util.h index 1adbf04..e8f99b6 100644 --- a/util.h +++ b/util.h @@ -6,6 +6,14 @@ #ifndef UTIL_H #define UTIL_H

+#define VERSION_BLOB \ + VERSION "\n" \ + "Copyright (C) 2020-2022 Red Hat\n" \

Fwiw, I believe Red Hat legal suggests simply "Copyright Red Hat". AIUI the "(C)" thing is legally meaningless (unlike the word "copyright" or the actual © symbol), and the years are unnecessary and tend to get out of date.

+ "GNU Affero GPL version 3 or later " \ + "https://www.gnu.org/licenses/agpl-3.0.html\n" \ + "This is free software: you are free to change and redistribute it.\n" \ + "There is NO WARRANTY, to the extent permitted by law.\n\n" + #ifndef SECCOMP_RET_KILL_PROCESS #define SECCOMP_RET_KILL_PROCESS SECCOMP_RET_KILL #endif

-- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, Oct 07, 2022 at 10:15:25AM +0200, Stefano Brivio wrote:

On Fri, 7 Oct 2022 17:57:43 +1100 David Gibson wrote:

...

On Fri, Oct 07, 2022 at 02:47:40AM +0200, Stefano Brivio wrote:

...

Now that we can log to file, this might start to be relevant.

Uh... I dont' understand the connection here.

Because we might have a pile of log files collected somewhere (or logs shared by users) and this adds the version to the log file.

But how is that different with a system logger?

...

...

Signed-off-by: Stefano Brivio --- Makefile | 3 +++ conf.c | 12 ++++++++++-- log.c | 4 ++-- passt.1 | 4 ++++ util.h | 8 ++++++++ 5 files changed, 27 insertions(+), 4 deletions(-)

diff --git a/Makefile b/Makefile index fafb024..f7ddb84 100644 --- a/Makefile +++ b/Makefile @@ -9,6 +9,8 @@ # Copyright (c) 2021 Red Hat GmbH # Author: Stefano Brivio

+VERSION ?= $(shell git describe --tags HEAD || echo "unknown\ version") + RLIMIT_STACK_VAL := $(shell /bin/sh -c 'ulimit -s') ifeq ($(RLIMIT_STACK_VAL),unlimited) RLIMIT_STACK_VAL := 1024 @@ -31,6 +33,7 @@ FLAGS += -DNETNS_RUN_DIR=\"/run/netns\" FLAGS += -DPASST_AUDIT_ARCH=AUDIT_ARCH_$(AUDIT_ARCH) FLAGS += -DRLIMIT_STACK_VAL=$(RLIMIT_STACK_VAL) FLAGS += -DARCH=\"$(TARGET_ARCH)\" +FLAGS += -DVERSION=\"$(VERSION)\"

PASST_SRCS = arch.c arp.c checksum.c conf.c dhcp.c dhcpv6.c icmp.c igmp.c \ isolation.c lineread.c log.c mld.c ndp.c netlink.c packet.c passt.c \ diff --git a/conf.c b/conf.c index f22940b..4ec3153 100644 --- a/conf.c +++ b/conf.c @@ -626,6 +626,8 @@ static void usage(const char *name) } info("");

+

Extraneous blank line.

Oops.

...

...

+ info( " -v, --version Show version and exit");

I'd suggest just '--version'. '-v' is "verbose" more often than it is "version".

Um, yes, I'll drop -v.

...

...

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"); @@ -993,6 +995,7 @@ void conf(struct ctx *c, int argc, char **argv) { int netns_only = 0; struct option options[] = { + {"version", no_argument, NULL, 'v' }, {"debug", no_argument, NULL, 'd' }, {"quiet", no_argument, NULL, 'q' }, {"foreground", no_argument, NULL, 'f' }, @@ -1057,9 +1060,9 @@ void conf(struct ctx *c, int argc, char **argv)

if (c->mode == MODE_PASTA) { c->no_dhcp_dns = c->no_dhcp_dns_search = 1; - optstring = "dqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; + optstring = "vdqfel:hI:p:P:m:a:n:M:g:i:D:S:46t:u:T:U:"; } else { - optstring = "dqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; + optstring = "vdqfel:hs:p:P:m:a:n:M:g:i:D:S:46t:u:"; }

c->tcp.fwd_in.mode = c->tcp.fwd_out.mode = 0; @@ -1197,6 +1200,11 @@ void conf(struct ctx *c, int argc, char **argv) usage(argv[0]); } break; + case 'v': + fprintf(stdout, + c->mode == MODE_PASST ? "passt " : "pasta "); + fprintf(stdout, VERSION_BLOB); + exit(EXIT_SUCCESS); case 'd': if (c->debug) { err("Multiple --debug options given"); diff --git a/log.c b/log.c index 85b13fe..2b088c4 100644 --- a/log.c +++ b/log.c @@ -172,7 +172,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap) }

/** - * logfile_init() - Open log file and write header with PID and path + * logfile_init() - Open log file and write header with PID, version, path * @name: Identifier for header: passt or pasta * @path: Path to log file * @size: Maximum size of log file: log_cut_size is calculatd here @@ -196,7 +196,7 @@ void logfile_init(const char *name, const char *path, size_t size)

log_size = size ? size : LOGFILE_SIZE_DEFAULT;

- n = snprintf(log_header, sizeof(log_header), "%s: %s (%i)", + n = snprintf(log_header, sizeof(log_header), "%s " VERSION ": %s (%i)", name, exe, getpid());

if (write(log_file, log_header, n) <= 0 || diff --git a/passt.1 b/passt.1 index 64236b6..c63a439 100644 --- a/passt.1 +++ b/passt.1 @@ -77,6 +77,10 @@ for performance reasons.

.SH OPTIONS

+.TP +.BR \-v ", " \-\-version +Show version and exit. + .TP .BR \-d ", " \-\-debug Be verbose, don't run in background, don't log to the system logger. diff --git a/util.h b/util.h index 1adbf04..e8f99b6 100644 --- a/util.h +++ b/util.h @@ -6,6 +6,14 @@ #ifndef UTIL_H #define UTIL_H

+#define VERSION_BLOB \ + VERSION "\n" \ + "Copyright (C) 2020-2022 Red Hat\n" \

Fwiw, I believe Red Hat legal suggests simply "Copyright Red Hat". AIUI the "(C)" thing is legally meaningless (unlike the word "copyright" or the actual © symbol), and the years are unnecessary and tend to get out of date.

I just checked coreutils and gcc, but I see both points, I'll change this.

Yeah.. developer copyright statements have an awful lot of cargo culting. -- David Gibson | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you. NOT _the_ _other_ | _way_ _around_! http://www.ozlabs.org/~dgibson

On Fri, 7 Oct 2022 19:37:49 +1100 David Gibson wrote:

On Fri, Oct 07, 2022 at 02:47:42AM +0200, Stefano Brivio wrote:

...

To test log files on a tmpfs mount, we need to unshare the mount namespace, which means using a context for the passt pane is not really practical at the moment, as we can't open a shell there, so we would have to encapsulate all the commands under 'unshare -rUm', plus the "inner" pasta command, running in turn a tcp_rr server.

It might be worth fixing this by e.g. detecting we are trying to spawn an interactive shell and adding a special path in the context setup with some form of stdin redirection -- I'm not sure it's doable though.

For this reason, add a new layout, using a context only for the host pane, while keeping the old command dispatch mechanism for the passt pane.

Blecch. I really hate going backwards with the test mechanisms like this. .. and I don't think you need to, though it will require a slight rearrangement.

AIUI, you want to run basically the same tests against a logfile on the main fs (probably ext4 or xfs) and on tmpfs. So, I'd suggest one test file that does the core tests, with two different setup functions for the two cases. For the normal fs test, set the passt context to be a second host context, for the tmpfs test, set the passt context to nsenter an unshare -rUm.

Sure, I can do it, but I wonder: wouldn't it be worth to eventually try and allow spawning an interactive shell from contexts, so that I can have a single setup function -- which looks definitely better to me, especially given the premises of the patch enabling test selection I just posted? Because, if that's feasible, I would rather keep this temporary regression, for simplicity.

I don't think you need another context to run things within the pasta environment, because AFAICT you can just use a fixed command for each pasta invocation rather than a shell (see details below).

Of course, I tried, and:

...

We also need a new setup function that doesn't start pasta: we want to start and restart it with different options.

Further, we need a 'pint' directive, to send an interrupt to the passt pane: add that in lib/test.

All the tests before the one involving tmpfs and a detached mount namespace were also tested with the context mechanism. To make an eventual conversion easier, pass tcp_crr directly as a command on pasta's command line where feasible.

While at it, fix the comment to the teardown_pasta() function.

The new test set can be semi-conveniently run as:

./run pasta_options/log_to_file

and it checks basic log creation, size of the log file after flooding it with debug entries, rotations, and basic consistency after rotations, on both an existing filesystem and a tmpfs, chosen as it doesn't support collapsing data ranges via fallocate(), hence triggering the fall-back mechanism for logging rotation.

Signed-off-by: Stefano Brivio --- test/lib/layout | 39 +++++++++++++++ test/lib/setup | 15 +++++- test/lib/test | 3 ++ test/pasta_options/log_to_file | 90 ++++++++++++++++++++++++++++++++++ test/run | 4 ++ 5 files changed, 150 insertions(+), 1 deletion(-) create mode 100644 test/pasta_options/log_to_file

diff --git a/test/lib/layout b/test/lib/layout index 79a6c80..fcd1db4 100644 --- a/test/lib/layout +++ b/test/lib/layout @@ -43,6 +43,45 @@ layout_host() { sleep 1 }

+# layout_pasta_simple() - Panes for host and pasta +layout_pasta_simple() { + sleep 3 + + tmux kill-pane -a -t 0 + cmd_write 0 clear + + tmux split-window -v -t passt_test + tmux split-window -h -t passt_test + + PANE_PASST=0 + PANE_HOST=1 + PANE_INFO=2 + + get_info_cols + + tmux send-keys -l -t ${PANE_INFO} 'while cat '"$STATEBASE/log_pipe"'; do :; done' + tmux send-keys -t ${PANE_INFO} -N 100 C-m + tmux select-pane -t ${PANE_INFO} -T "test log" + + if context_exists host; then + pane_watch_contexts ${PANE_HOST} host host + else + tmux pipe-pane -O -t ${PANE_HOST} "cat >> ${LOGDIR}/pane_host.log" + tmux select-pane -t ${PANE_HOST} -T "host" + fi + + if context_exists passt; then + pane_watch_contexts ${PANE_PASST} host host + else + tmux pipe-pane -O -t ${PANE_PASST} "cat >> ${LOGDIR}/pane_passt.log" + tmux select-pane -t ${PANE_PASST} -T "pasta" + fi + + info_layout "single pasta instance" + + sleep 1 +} + # layout_pasta() - Panes for host, pasta, and separate one for namespace layout_pasta() { sleep 3 diff --git a/test/lib/setup b/test/lib/setup index 071e11d..e2d0ff0 100755 --- a/test/lib/setup +++ b/test/lib/setup @@ -106,6 +106,13 @@ setup_pasta() { wait_for [ -f "${STATESETUP}/passt.pid" ] }

+# setup_pasta_options() - Set up layout and host context without starting pasta +setup_pasta_options() { + context_setup_host host + + layout_pasta_simple +} + # setup_passt_in_ns() - Set up namespace (with pasta), run qemu and passt into it setup_passt_in_ns() { context_setup_host host @@ -294,7 +301,7 @@ teardown_passt() { teardown_context_watch ${PANE_GUEST} qemu guest }

-# teardown_passt() - Exit namespace, kill pasta process +# teardown_pasta() - Exit namespace, kill pasta process teardown_pasta() { ${NSHOLDER} "${STATESETUP}/ns.hold" stop context_wait unshare @@ -304,6 +311,12 @@ teardown_pasta() { teardown_context_watch ${PANE_NS} unshare ns }

+# teardown_pasta_options() - Tear down pasta and host context, no namespace +teardown_pasta_options() { + teardown_context_watch ${PANE_HOST} host + teardown_context_watch ${PANE_PASST} passt +} + # teardown_passt_in_ns() - Exit namespace, kill qemu and pasta, remove pid file teardown_passt_in_ns() { context_run ns kill $(cat "${STATESETUP}/qemu.pid") diff --git a/test/lib/test b/test/lib/test index 558d0f0..4c271a5 100755 --- a/test/lib/test +++ b/test/lib/test @@ -137,6 +137,9 @@ test_one_line() { "passtw") pane_or_context_wait passt || TEST_ONE_nok=1 ;; + "pint") + tmux send-keys -t ${PANE_PASST} "C-c" + ;; "pout") __varname="${__arg%% *}" __output="$(pane_or_context_output passt "${__arg#* }")" diff --git a/test/pasta_options/log_to_file b/test/pasta_options/log_to_file new file mode 100644 index 0000000..587bf8e --- /dev/null +++ b/test/pasta_options/log_to_file @@ -0,0 +1,90 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# +# PASST - Plug A Simple Socket Transport +# for qemu/UNIX domain socket mode +# +# PASTA - Pack A Subtle Tap Abstraction +# for network namespace/tap device mode +# +# test/pasta_options/log_to_file - Check log creation, rotations and consistency +# +# Copyright (c) 2022 Red Hat GmbH +# Author: Stefano Brivio + +htools wc tcp_rr tail cut tr sort + +def flood_log_server +passtb tcp_crr --nolog -P 10001 -C 10002 -6 +sleep 1 +endef + +def flood_log_client +host tcp_crr --nolog -P 10001 -C 10002 -6 -c -H ::1 +endef + +def check_log_size_mountns +pout SIZE cat __LOG_FILE__ | wc -c +check [ __SIZE__ -gt $((50 * 1024)) ] +check [ __SIZE__ -lt $((100 * 1024)) ] +endef + +test Log creation + +set PORTS -t 10001,10002 -u 10001,10002 +set LOG_FILE __STATEDIR__/pasta.log + +passt ./pasta -l __LOG_FILE__

Here you can use 'true' instead of starting a shell then exiting.

Sure. This is not even a problem actually, the shell will terminate and I have my small log file.

...

+passt exit +check [ -s __LOG_FILE__ ] + +test Log truncated on creation +passt ./pasta -l __LOG_FILE__ +passt exit

Same here.

Same here.

...

+check [ $(cat __LOG_FILE__ | wc -l) -eq 1 ] + +test Maximum log size +passtb ./pasta --config-net -d -f -l __LOG_FILE__ --log-size $((100 * 1024)) -- sh -c 'while true; do tcp_crr --nolog -P 10001 -C 10002 -6; done'

Here you're already using a command.

Yes, and it works with the context approach, I tested it until this point.

...

+sleep 1 + +flood_log_client +check [ $(cat __LOG_FILE__ | wc -c) -gt $((50 * 1024)) ] +check [ $(cat __LOG_FILE__ | wc -c) -lt $((100 * 1024)) ] + +flood_log_client +check [ $(cat __LOG_FILE__ | wc -c) -gt $((50 * 1024)) ] +check [ $(cat __LOG_FILE__ | wc -c) -lt $((100 * 1024)) ] + +flood_log_client +check [ $(cat __LOG_FILE__ | wc -c) -gt $((50 * 1024)) ] +check [ $(cat __LOG_FILE__ | wc -c) -lt $((100 * 1024)) ] + +pint + +test Timestamp consistency after rotations +check tail -n +2 __LOG_FILE__ | cut -f1 -d' ' | tr -d [.:] | sort -c + +test Maximum log size on tmpfs (no FALLOC_FL_COLLAPSE_RANGE) +passt unshare -rUm +passt mkdir __STATEDIR__/t +passt mount -t tmpfs none __STATEDIR__/t +set LOG_FILE __STATEDIR__/t/log +passt ./pasta --config-net -d -l __LOG_FILE__ --log-size $((100 * 1024))

Here I think you can use the same while true trick as above, rather than starting the server repeatedly.

Not really, because I want to check the size of the log file several times during the test, and I can't do it from outside the mount namespace, hence this: pout SIZE cat __LOG_FILE__ | wc -c in check_log_size_mountns. This would be solved by a separate setup function like the one you mentioned, though. Having a separate context/pane to just check that looks a bit bad for usability (in terms of showing what's going on). So the question here is really if we can avoid having a separate setup function, by means of adapting the context mechanism to enable interactive shells. If we can't, fine. But if we can, I'd leave this as a temporary hack, because it's more usable than the alternative -- for example, I don't have to select two separate tests for this. -- Stefano