[PATCH] log: Send identifier string in log messages, openlog() won't work for us

older
[libvirt PATCH 0/3] Support for...

Stefano Brivio

23 Feb 2023 23 Feb '23

6:35 p.m.

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 Signed-off-by: Stefano Brivio --- 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

Show replies by date

Andrea Bolognani

23 Feb 23 Feb

7:15 p.m.

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 Signed-off-by: Stefano Brivio --- 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 Reviewed-by: Andrea Bolognani 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

Stefano Brivio

24 Feb 24 Feb

7:59 a.m.

On Thu, 23 Feb 2023 10:15:15 -0800 Andrea Bolognani wrote:

...

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 Signed-off-by: Stefano Brivio --- 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 Reviewed-by: Andrea Bolognani

Thanks for the tests and review!

...

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

Andrea Bolognani

8:44 p.m.

On Fri, Feb 24, 2023 at 07:59:37AM +0100, Stefano Brivio wrote:

...

On Thu, 23 Feb 2023 10:15:15 -0800 Andrea Bolognani wrote:

...
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.

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 / Virtualization

David Gibson

12:31 a.m.

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 Signed-off-by: Stefano Brivio

Reviewed-by: David Gibson

...

--- 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

855

Age (days ago)

856

Last active (days ago)

List overview

Download

4 comments

3 participants

participants (3)

Andrea Bolognani
David Gibson
Stefano Brivio