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

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

[Stefano Brivio]

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@redhat.com>
Signed-off-by: Stefano Brivio <sbrivio@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);
-- 
@@ -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

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

[Andrea Bolognani]

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@redhat.com>
> Signed-off-by: Stefano Brivio <sbrivio@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@redhat.com>
  Reviewed-by: Andrea Bolognani <abologna@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

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

[David Gibson]

[-- Attachment #1: Type: text/plain, Size: 2575 bytes --]

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@redhat.com>
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

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

[Stefano Brivio]

On Thu, 23 Feb 2023 10:15:15 -0800
Andrea Bolognani <abologna@redhat.com> 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 <abologna@redhat.com>
> > Signed-off-by: Stefano Brivio <sbrivio@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@redhat.com>
>   Reviewed-by: Andrea Bolognani <abologna@redhat.com>

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

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

[Andrea Bolognani]

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@redhat.com> 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