openlog() can be used to set "ident" and have all the log messages
prefixed by it, but only if we call syslog() -- this is implemented
by C libraries.
We don't log messages with syslog(), though, as we have a custom
implementation to ensure we don't need dynamic memory allocation.
This means that it's perfectly useless to call openlog(), and that we
have to prefix every message we log by the identifier on our own.
Reported-by: Andrea Bolognani <abologna(a)redhat.com>
Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com>
---
log.c | 12 +++++-------
1 file changed, 5 insertions(+), 7 deletions(-)
diff --git a/log.c b/log.c
index f23e8ef..bfde6ce 100644
--- a/log.c
+++ b/log.c
@@ -106,7 +106,7 @@ void trace_init(int enable)
}
/**
- * __openlog() - Non-optional openlog() wrapper, to allow custom vsyslog()
+ * __openlog() - Non-optional openlog() implementation, for custom vsyslog()
* @ident: openlog() identity (program name)
* @option: openlog() options
* @facility: openlog() facility (LOG_DAEMON)
@@ -136,8 +136,6 @@ void __openlog(const char *ident, int option, int facility)
log_mask |= facility;
strncpy(log_ident, ident, sizeof(log_ident) - 1);
log_opt = option;
-
- openlog(ident, option, facility);
}
/**
@@ -158,11 +156,11 @@ void __setlogmask(int mask)
*/
void passt_vsyslog(int pri, const char *format, va_list ap)
{
+ int prefix_len, n;
char buf[BUFSIZ];
- int n;
- /* Send without name and timestamp, the system logger should add them */
- n = snprintf(buf, BUFSIZ, "<%i> ", pri);
+ /* Send without timestamp, the system logger should add it */
+ n = prefix_len = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident);
n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
@@ -170,7 +168,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
n += snprintf(buf + n, BUFSIZ - n, "\n");
if (log_opt & LOG_PERROR)
- fprintf(stderr, "%s", buf + sizeof("<0>"));
+ fprintf(stderr, "%s", buf + prefix_len);
if (send(log_sock, buf, n, 0) != n)
fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
--
2.39.1
On Thu, Feb 23, 2023 at 06:35:55PM +0100, Stefano Brivio wrote:openlog() can be used to set "ident" and have all the log messages prefixed by it, but only if we call syslog() -- this is implemented by C libraries. We don't log messages with syslog(), though, as we have a custom implementation to ensure we don't need dynamic memory allocation. This means that it's perfectly useless to call openlog(), and that we have to prefix every message we log by the identifier on our own. Reported-by: Andrea Bolognani <abologna(a)redhat.com> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com> --- log.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-)With this patch applied, the entries I see in the journal after starting a VM go from passt.avx2[519959]: No external routable interface for IPv6 passt.avx2[519959]: Outbound interface (IPv4): enp5s0 MAC[519959]: host[519959]: xx:xx:xx:xx:xx:xx DHCP[519959]: assign[519959]: 192.168.1.62 mask[519959]: 255.255.255.0 router[519959]: 192.168.1.1 DNS[519959]: passt.avx2[519959]: 192.168.1.1 passt.avx2[519959]: DNS search list: passt.avx2[519959]: xxx passt.avx2[519959]: UNIX domain socket bound at /run/libvirt/qemu/passt/12-xxx-net0.socket passt.avx2[519959]: You can now start qemu (>= 7.2, with commit 13c6be96618c): passt.avx2[519959]: kvm ... -device virtio-net-pci,netdev=s -netdev stream,id=s,server=off,addr.type=unix,addr.path=/run/libvirt/qemu/passt/12-xxx-net0.socket passt.avx2[519959]: or qrap, for earlier qemu versions: passt.avx2[519959]: ./qrap 5 kvm ... -net socket,fd=5 -net nic,model=virtio passt.avx2[519960]: accepted connection from PID 0 DHCP[519960]: ack to request passt.avx2[519960]: from xx:xx:xx:xx:xx:xx to passt[523786]: No external routable interface for IPv6 passt[523786]: Outbound interface (IPv4): enp5s0 passt[523786]: MAC: passt[523786]: host: xx:xx:xx:xx:xx:xx passt[523786]: DHCP: passt[523786]: assign: 192.168.1.62 passt[523786]: mask: 255.255.255.0 passt[523786]: router: 192.168.1.1 passt[523786]: DNS: passt[523786]: 192.168.1.1 passt[523786]: DNS search list: passt[523786]: xxx passt[523786]: UNIX domain socket bound at /run/libvirt/qemu/passt/13-xxx-net0.socket passt[523786]: You can now start qemu (>= 7.2, with commit 13c6be96618c): passt[523786]: kvm ... -device virtio-net-pci,netdev=s -netdev stream,id=s,server=off,addr.type=unix,addr.path=/run/libvirt/qemu/passt/13-xxx-net0.socket passt[523786]: or qrap, for earlier qemu versions: passt[523786]: ./qrap 5 kvm ... -net socket,fd=5 -net nic,model=virtio passt[523789]: accepted connection from PID 0 passt[523789]: DHCP: ack to request passt[523789]: from xx:xx:xx:xx:xx:xx which is clearly much better. Tested-by: Andrea Bolognani <abologna(a)redhat.com> Reviewed-by: Andrea Bolognani <abologna(a)redhat.com> Note the change from passt.avx2 to passt. Looking at the process listing, plain passt was used in both cases, so I assume that the passt.avx2 mention is journald trying to fill in the blanks and getting it wrong? -- Andrea Bolognani / Red Hat / Virtualization
On Thu, Feb 23, 2023 at 06:35:55PM +0100, Stefano Brivio wrote:openlog() can be used to set "ident" and have all the log messages prefixed by it, but only if we call syslog() -- this is implemented by C libraries. We don't log messages with syslog(), though, as we have a custom implementation to ensure we don't need dynamic memory allocation. This means that it's perfectly useless to call openlog(), and that we have to prefix every message we log by the identifier on our own. Reported-by: Andrea Bolognani <abologna(a)redhat.com> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com>Reviewed-by: David Gibson <david(a)gibson.dropbear.id.au>--- log.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/log.c b/log.c index f23e8ef..bfde6ce 100644 --- a/log.c +++ b/log.c @@ -106,7 +106,7 @@ void trace_init(int enable) } /** - * __openlog() - Non-optional openlog() wrapper, to allow custom vsyslog() + * __openlog() - Non-optional openlog() implementation, for custom vsyslog() * @ident: openlog() identity (program name) * @option: openlog() options * @facility: openlog() facility (LOG_DAEMON) @@ -136,8 +136,6 @@ void __openlog(const char *ident, int option, int facility) log_mask |= facility; strncpy(log_ident, ident, sizeof(log_ident) - 1); log_opt = option; - - openlog(ident, option, facility); } /** @@ -158,11 +156,11 @@ void __setlogmask(int mask) */ void passt_vsyslog(int pri, const char *format, va_list ap) { + int prefix_len, n; char buf[BUFSIZ]; - int n; - /* Send without name and timestamp, the system logger should add them */ - n = snprintf(buf, BUFSIZ, "<%i> ", pri); + /* Send without timestamp, the system logger should add it */ + n = prefix_len = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident); n += vsnprintf(buf + n, BUFSIZ - n, format, ap); @@ -170,7 +168,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap) n += snprintf(buf + n, BUFSIZ - n, "\n"); if (log_opt & LOG_PERROR) - fprintf(stderr, "%s", buf + sizeof("<0>")); + fprintf(stderr, "%s", buf + prefix_len); if (send(log_sock, buf, n, 0) != n) fprintf(stderr, "Failed to send %i bytes to syslog\n", n);-- 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 Thu, 23 Feb 2023 10:15:15 -0800 Andrea Bolognani <abologna(a)redhat.com> wrote:On Thu, Feb 23, 2023 at 06:35:55PM +0100, Stefano Brivio wrote:Thanks for the tests and review!openlog() can be used to set "ident" and have all the log messages prefixed by it, but only if we call syslog() -- this is implemented by C libraries. We don't log messages with syslog(), though, as we have a custom implementation to ensure we don't need dynamic memory allocation. This means that it's perfectly useless to call openlog(), and that we have to prefix every message we log by the identifier on our own. Reported-by: Andrea Bolognani <abologna(a)redhat.com> Signed-off-by: Stefano Brivio <sbrivio(a)redhat.com> --- log.c | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-)With this patch applied, the entries I see in the journal after starting a VM go from passt.avx2[519959]: No external routable interface for IPv6 passt.avx2[519959]: Outbound interface (IPv4): enp5s0 MAC[519959]: host[519959]: xx:xx:xx:xx:xx:xx DHCP[519959]: assign[519959]: 192.168.1.62 mask[519959]: 255.255.255.0 router[519959]: 192.168.1.1 DNS[519959]: passt.avx2[519959]: 192.168.1.1 passt.avx2[519959]: DNS search list: passt.avx2[519959]: xxx passt.avx2[519959]: UNIX domain socket bound at /run/libvirt/qemu/passt/12-xxx-net0.socket passt.avx2[519959]: You can now start qemu (>= 7.2, with commit 13c6be96618c): passt.avx2[519959]: kvm ... -device virtio-net-pci,netdev=s -netdev stream,id=s,server=off,addr.type=unix,addr.path=/run/libvirt/qemu/passt/12-xxx-net0.socket passt.avx2[519959]: or qrap, for earlier qemu versions: passt.avx2[519959]: ./qrap 5 kvm ... -net socket,fd=5 -net nic,model=virtio passt.avx2[519960]: accepted connection from PID 0 DHCP[519960]: ack to request passt.avx2[519960]: from xx:xx:xx:xx:xx:xx to passt[523786]: No external routable interface for IPv6 passt[523786]: Outbound interface (IPv4): enp5s0 passt[523786]: MAC: passt[523786]: host: xx:xx:xx:xx:xx:xx passt[523786]: DHCP: passt[523786]: assign: 192.168.1.62 passt[523786]: mask: 255.255.255.0 passt[523786]: router: 192.168.1.1 passt[523786]: DNS: passt[523786]: 192.168.1.1 passt[523786]: DNS search list: passt[523786]: xxx passt[523786]: UNIX domain socket bound at /run/libvirt/qemu/passt/13-xxx-net0.socket passt[523786]: You can now start qemu (>= 7.2, with commit 13c6be96618c): passt[523786]: kvm ... -device virtio-net-pci,netdev=s -netdev stream,id=s,server=off,addr.type=unix,addr.path=/run/libvirt/qemu/passt/13-xxx-net0.socket passt[523786]: or qrap, for earlier qemu versions: passt[523786]: ./qrap 5 kvm ... -net socket,fd=5 -net nic,model=virtio passt[523789]: accepted connection from PID 0 passt[523789]: DHCP: ack to request passt[523789]: from xx:xx:xx:xx:xx:xx which is clearly much better. Tested-by: Andrea Bolognani <abologna(a)redhat.com> Reviewed-by: Andrea Bolognani <abologna(a)redhat.com>Note the change from passt.avx2 to passt. Looking at the process listing, plain passt was used in both cases, so I assume that the passt.avx2 mention is journald trying to fill in the blanks and getting it wrong?Yes, it's your system logger filling in the blanks, but it didn't really get it wrong, as the process name is actually "passt.avx2" if the AVX2-enabled build starts. Look at this, cough cough, beauty in arch.c: https://passt.top/passt/tree/arch.c#n21 "passt.avx2" wasn't intended in any case. -- Stefano
On Fri, Feb 24, 2023 at 07:59:37AM +0100, Stefano Brivio wrote:On Thu, 23 Feb 2023 10:15:15 -0800 Andrea Bolognani <abologna(a)redhat.com> wrote:Oh, I see now that I actually have passt.avx2 running, despite the output of ps hiding this fact: $ ps aux | grep bin/passt qemu 173991 [...] /usr/bin/passt [...] $ sudo ls -l /proc/173991/exe [...] /proc/173991/exe -> /usr/bin/passt.avx2 So it looks like everything is indeed working as intended :) -- Andrea Bolognani / Red Hat / VirtualizationNote the change from passt.avx2 to passt. Looking at the process listing, plain passt was used in both cases, so I assume that the passt.avx2 mention is journald trying to fill in the blanks and getting it wrong?Yes, it's your system logger filling in the blanks, but it didn't really get it wrong, as the process name is actually "passt.avx2" if the AVX2-enabled build starts. Look at this, cough cough, beauty in arch.c: https://passt.top/passt/tree/arch.c#n21 "passt.avx2" wasn't intended in any case.