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

[Daniel P . Berrangé]

On Fri, Jan 18, 2019 at 11:50:39AM -0600, Eric Blake 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.
> 
> 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))

The caveat is that 'strerror' is not required to be thread safe,
however, given that this is Linux only code I guess we can assume
the glibc impl which fortunately is thread safe.

On this point though, does anyone know of any platforms we support[1],
or are likely to support in future, where 'strerror' is *not* thread
safe ?

I see rumours that Windows strerror() is not thread safe but not
found a concrete source for that.

[1] https://qemu.weilnetz.de/doc/qemu-doc.html#Supported-build-platforms



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

Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|