Re: [Qemu-devel] [PATCH v2 3/4] trace: forbid use of %m in trace event format strings

[Eric Blake]

On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> The '%m' format specifier instructs glibc's printf() implementation to
> insert the contents of strerror(errno).

That is a glibc-only extension in printf(), but mandatory (and supported
in ALL platforms) in syslog().  However, you are correct that:

> This is not something that
> should ever be used in trace-events files because several of the
> backends do not use the format string and so this error information is
> invisible to them. The errno value should be given as an explicit
> trace argument instead. Use of '%m' should also be avoided as it is not
> portable to all QEMU build targets.

If all of our traces are compiled to syslog(), it would be portable, but
that's not the case.

What's more, using %m is subject to race conditions - the more code you
have between when the format string containing %m is given, and the
point where the actual error message is emitted, the higher the
probability that some of the intermediate code could have stomped on
errno in the meantime, rendering the logged message incorrect.  And
forcing logging wrappers to save/restore the current state of errno,
just in case they might encounter %m, can get wasteful.

Should checkpatch be taught to flag %m as suspicious?

However, tracing the errno value is NOT what %m did; I'd rather see...

> 
> Signed-off-by: Daniel P. Berrangé <address@hidden>
> ---
>  hw/vfio/pci.c                 | 2 +-
>  hw/vfio/trace-events          | 2 +-
>  scripts/tracetool/__init__.py | 4 ++++
>  3 files changed, 6 insertions(+), 2 deletions(-)
> 
> diff --git a/hw/vfio/pci.c b/hw/vfio/pci.c
> index c0cb1ec289..85f1908cfe 100644
> --- a/hw/vfio/pci.c
> +++ b/hw/vfio/pci.c
> @@ -2581,7 +2581,7 @@ static void vfio_populate_device(VFIOPCIDevice *vdev, 
> Error **errp)
>      ret = ioctl(vdev->vbasedev.fd, VFIO_DEVICE_GET_IRQ_INFO, &irq_info);
>      if (ret) {
>          /* This can fail for an old kernel or legacy PCI dev */
> -        trace_vfio_populate_device_get_irq_info_failure();
> +        trace_vfio_populate_device_get_irq_info_failure(errno);

trace_vfio_populate_device_get_irq_info_failure(strerror(errno))

>      } else if (irq_info.count == 1) {
>          vdev->pci_aer = true;
>      } else {
> diff --git a/hw/vfio/trace-events b/hw/vfio/trace-events
> index a85e8662ea..6d412afc83 100644
> --- a/hw/vfio/trace-events
> +++ b/hw/vfio/trace-events
> @@ -37,7 +37,7 @@ vfio_pci_hot_reset_has_dep_devices(const char *name) "%s: 
> hot reset dependent de
>  vfio_pci_hot_reset_dep_devices(int domain, int bus, int slot, int function, 
> int group_id) "\t%04x:%02x:%02x.%x group %d"
>  vfio_pci_hot_reset_result(const char *name, const char *result) "%s hot 
> reset: %s"
>  vfio_populate_device_config(const char *name, unsigned long size, unsigned 
> long offset, unsigned long flags) "Device %s config:\n  size: 0x%lx, offset: 
> 0x%lx, flags: 0x%lx"
> -vfio_populate_device_get_irq_info_failure(void) "VFIO_DEVICE_GET_IRQ_INFO 
> failure: %m"
> +vfio_populate_device_get_irq_info_failure(int err) "VFIO_DEVICE_GET_IRQ_INFO 
> failure: %d"

vfio_populate_device_get_irq_info_failur(const char *err)
"VFIO_DEVICE_GET_IRQ_INFO failure: %s"

...if we are trying to match the original intent.

>  vfio_realize(const char *name, int group_id) " (%s) group %d"
>  vfio_mdev(const char *name, bool is_mdev) " (%s) is_mdev %d"
>  vfio_add_ext_cap_dropped(const char *name, uint16_t cap, uint16_t offset) 
> "%s address@hidden"
> diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py
> index 3478ac93ab..6fca674936 100644
> --- a/scripts/tracetool/__init__.py
> +++ b/scripts/tracetool/__init__.py
> @@ -274,6 +274,10 @@ class Event(object):
>          props = groups["props"].split()
>          fmt = groups["fmt"]
>          fmt_trans = groups["fmt_trans"]
> +        if fmt.find("%m") != -1 or fmt_trans.find("%m") != -1:
> +            raise ValueError("Event format '%m' is forbidden, pass the error 
> "
> +                             "as an explicit trace argument")

Whether or not checkpatch decides to flag %m as suspicious in the
overall code base, I like that you are forbidding it in trace files.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

signature.asc
Description: OpenPGP digital signature