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

[Alex Williamson <alex.williamson@redhat.com>]

On Fri, 18 Jan 2019 11:50:39 -0600
Eric Blake <eblake@redhat.com> wrote:

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

It's portable to all QEMU build targets that support vfio, but we can
remove it if we want it out of the trace system, which of course does
support other 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é <berrange@redhat.com>
> > ---
> >  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))

Yep, I agree, the intent of the original code is not maintained.
Thanks,

Alex

> >      } 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 0x%x@0x%x"
> > 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.
>