[Qemu-devel] [PATCH v2 0/4] trace: make systemtap easier to use for simple logging

[Qemu-devel] [PATCH v2 0/4] trace: make systemtap easier to use for simple logging

[Daniel P. Berrangé]

This is a followup to

 v1: https://lists.gnu.org/archive/html/qemu-devel/2019-01/msg04173.html

Changed in v2:

 - Fix safety of QXL logging
 - Handle format specifier macros is a more reliable manner
 - Fix trace-events files missing newline
 - Remove use of %m formats

Daniel P. Berrangé (4):
  display: ensure qxl log_buf is a nul terminated string
  trace: enforce that every trace-events file has a final newline
  trace: forbid use of %m in trace event format strings
  trace: add ability to do simple printf logging via systemtap

 Makefile                             |   3 +
 Makefile.target                      |  11 +-
 docs/devel/tracing.txt               |  32 +++++
 hw/display/qxl.c                     |   3 +-
 hw/display/trace-events              |   2 +-
 hw/gpio/trace-events                 |   2 +-
 hw/vfio/pci.c                        |   2 +-
 hw/vfio/trace-events                 |   2 +-
 scripts/qemu-trace-stap              | 167 +++++++++++++++++++++++++++
 scripts/tracetool/__init__.py        |   6 +
 scripts/tracetool/format/log_stap.py | 127 ++++++++++++++++++++
 11 files changed, 351 insertions(+), 6 deletions(-)
 create mode 100755 scripts/qemu-trace-stap
 create mode 100644 scripts/tracetool/format/log_stap.py

-- 
2.20.1

[Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Daniel P. Berrangé]

The QXL_IO_LOG command allows the guest to send log messages to the host
via a buffer in the QXLRam struct. QEMU prints these to the console if
the qxl 'guestdebug' option is set to non-zero. It will also feed them
to the trace subsystem if any backends are built-in.

In both cases the log_buf data will get treated as being as a nul
terminated string, by the printf '%s' format specifier and / or other
code reading the buffer.

QEMU does nothing to guarantee that the log_buf really is nul terminated,
so there is potential for out of bounds array access.

This would affect any QEMU which has the log, syslog or ftrace trace
backends built into QEMU. It can only be triggered if the 'qxl_io_log'
trace event is enabled, however, so they are not vulnerable without
specific administrative action to enable this.

It would also affect QEMU if the 'guestdebug' parameter is set to a
non-zero value, which again is not the default and requires explicit
admin opt-in.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 hw/display/qxl.c        | 3 ++-
 hw/display/trace-events | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/hw/display/qxl.c b/hw/display/qxl.c
index 8e9a65e75b..eefdf4baac 100644
--- a/hw/display/qxl.c
+++ b/hw/display/qxl.c
@@ -1763,7 +1763,8 @@ async_common:
         qxl_set_mode(d, val, 0);
         break;
     case QXL_IO_LOG:
-        trace_qxl_io_log(d->id, d->ram->log_buf);
+        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';
+        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);
         if (d->guestdebug) {
             fprintf(stderr, "qxl/guest-%d: %" PRId64 ": %s", d->id,
                     qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL), d->ram->log_buf);
diff --git a/hw/display/trace-events b/hw/display/trace-events
index 5a48c6cb6a..387c6b8931 100644
--- a/hw/display/trace-events
+++ b/hw/display/trace-events
@@ -72,7 +72,7 @@ qxl_interface_update_area_complete_rest(int qid, uint32_t num_updated_rects) "%d
 qxl_interface_update_area_complete_overflow(int qid, int max) "%d max=%d"
 qxl_interface_update_area_complete_schedule_bh(int qid, uint32_t num_dirty) "%d #dirty=%d"
 qxl_io_destroy_primary_ignored(int qid, const char *mode) "%d %s"
-qxl_io_log(int qid, const uint8_t *log_buf) "%d %s"
+qxl_io_log(int qid, const char *log_buf) "%d %s"
 qxl_io_read_unexpected(int qid) "%d"
 qxl_io_unexpected_vga_mode(int qid, uint64_t addr, uint64_t val, const char *desc) "%d 0x%"PRIx64"=%"PRIu64" (%s)"
 qxl_io_write(int qid, const char *mode, uint64_t addr, const char *aname, uint64_t val, unsigned size, int async) "%d %s addr=%"PRIu64 " (%s) val=%"PRIu64" size=%u async=%d"
-- 
2.20.1

Re: [Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Eric Blake]

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

On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> The QXL_IO_LOG command allows the guest to send log messages to the host
> via a buffer in the QXLRam struct. QEMU prints these to the console if
> the qxl 'guestdebug' option is set to non-zero. It will also feed them
> to the trace subsystem if any backends are built-in.
> 
> In both cases the log_buf data will get treated as being as a nul
> terminated string, by the printf '%s' format specifier and / or other
> code reading the buffer.
> 
> QEMU does nothing to guarantee that the log_buf really is nul terminated,
> so there is potential for out of bounds array access.
> 
> This would affect any QEMU which has the log, syslog or ftrace trace
> backends built into QEMU. It can only be triggered if the 'qxl_io_log'
> trace event is enabled, however, so they are not vulnerable without
> specific administrative action to enable this.
> 
> It would also affect QEMU if the 'guestdebug' parameter is set to a
> non-zero value, which again is not the default and requires explicit
> admin opt-in.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  hw/display/qxl.c        | 3 ++-
>  hw/display/trace-events | 2 +-
>  2 files changed, 3 insertions(+), 2 deletions(-)

Reviewed-by: Eric Blake <eblake@redhat.com>

> +++ b/hw/display/qxl.c
> @@ -1763,7 +1763,8 @@ async_common:
>          qxl_set_mode(d, val, 0);
>          break;
>      case QXL_IO_LOG:
> -        trace_qxl_io_log(d->id, d->ram->log_buf);
> +        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';

May lose a character from the log, but the improved safety is worth it.

> +        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);
>          if (d->guestdebug) {
>              fprintf(stderr, "qxl/guest-%d: %" PRId64 ": %s", d->id,
>                      qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL), d->ram->log_buf);
> diff --git a/hw/display/trace-events b/hw/display/trace-events
> index 5a48c6cb6a..387c6b8931 100644
> --- a/hw/display/trace-events
> +++ b/hw/display/trace-events
> @@ -72,7 +72,7 @@ qxl_interface_update_area_complete_rest(int qid, uint32_t num_updated_rects) "%d
>  qxl_interface_update_area_complete_overflow(int qid, int max) "%d max=%d"
>  qxl_interface_update_area_complete_schedule_bh(int qid, uint32_t num_dirty) "%d #dirty=%d"
>  qxl_io_destroy_primary_ignored(int qid, const char *mode) "%d %s"
> -qxl_io_log(int qid, const uint8_t *log_buf) "%d %s"
> +qxl_io_log(int qid, const char *log_buf) "%d %s"
>  qxl_io_read_unexpected(int qid) "%d"
>  qxl_io_unexpected_vga_mode(int qid, uint64_t addr, uint64_t val, const char *desc) "%d 0x%"PRIx64"=%"PRIu64" (%s)"
>  qxl_io_write(int qid, const char *mode, uint64_t addr, const char *aname, uint64_t val, unsigned size, int async) "%d %s addr=%"PRIu64 " (%s) val=%"PRIu64" size=%u async=%d"
> 

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Daniel P. Berrangé]

On Fri, Jan 18, 2019 at 11:40:29AM -0600, Eric Blake wrote:
> On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> > The QXL_IO_LOG command allows the guest to send log messages to the host
> > via a buffer in the QXLRam struct. QEMU prints these to the console if
> > the qxl 'guestdebug' option is set to non-zero. It will also feed them
> > to the trace subsystem if any backends are built-in.
> > 
> > In both cases the log_buf data will get treated as being as a nul
> > terminated string, by the printf '%s' format specifier and / or other
> > code reading the buffer.
> > 
> > QEMU does nothing to guarantee that the log_buf really is nul terminated,
> > so there is potential for out of bounds array access.
> > 
> > This would affect any QEMU which has the log, syslog or ftrace trace
> > backends built into QEMU. It can only be triggered if the 'qxl_io_log'
> > trace event is enabled, however, so they are not vulnerable without
> > specific administrative action to enable this.
> > 
> > It would also affect QEMU if the 'guestdebug' parameter is set to a
> > non-zero value, which again is not the default and requires explicit
> > admin opt-in.
> > 
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >  hw/display/qxl.c        | 3 ++-
> >  hw/display/trace-events | 2 +-
> >  2 files changed, 3 insertions(+), 2 deletions(-)
> 
> Reviewed-by: Eric Blake <eblake@redhat.com>
> 
> > +++ b/hw/display/qxl.c
> > @@ -1763,7 +1763,8 @@ async_common:
> >          qxl_set_mode(d, val, 0);
> >          break;
> >      case QXL_IO_LOG:
> > -        trace_qxl_io_log(d->id, d->ram->log_buf);
> > +        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';
> 
> May lose a character from the log, but the improved safety is worth it.

In practice it won't.  The Xorg QXL driver and Windows XDDM DOD driver
don't use this feature at all. The Windows QXL miniport driver uses snprintf
when populating the buffer so will already have truncated if it was going
to overflow.

> 
> > +        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);
> >          if (d->guestdebug) {
> >              fprintf(stderr, "qxl/guest-%d: %" PRId64 ": %s", d->id,
> >                      qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL), d->ram->log_buf);
> > diff --git a/hw/display/trace-events b/hw/display/trace-events
> > index 5a48c6cb6a..387c6b8931 100644
> > --- a/hw/display/trace-events
> > +++ b/hw/display/trace-events
> > @@ -72,7 +72,7 @@ qxl_interface_update_area_complete_rest(int qid, uint32_t num_updated_rects) "%d
> >  qxl_interface_update_area_complete_overflow(int qid, int max) "%d max=%d"
> >  qxl_interface_update_area_complete_schedule_bh(int qid, uint32_t num_dirty) "%d #dirty=%d"
> >  qxl_io_destroy_primary_ignored(int qid, const char *mode) "%d %s"
> > -qxl_io_log(int qid, const uint8_t *log_buf) "%d %s"
> > +qxl_io_log(int qid, const char *log_buf) "%d %s"
> >  qxl_io_read_unexpected(int qid) "%d"
> >  qxl_io_unexpected_vga_mode(int qid, uint64_t addr, uint64_t val, const char *desc) "%d 0x%"PRIx64"=%"PRIu64" (%s)"
> >  qxl_io_write(int qid, const char *mode, uint64_t addr, const char *aname, uint64_t val, unsigned size, int async) "%d %s addr=%"PRIu64 " (%s) val=%"PRIu64" size=%u async=%d"
> > 
> 
> -- 
> Eric Blake, Principal Software Engineer
> Red Hat, Inc.           +1-919-301-3226
> Virtualization:  qemu.org | libvirt.org
> 




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

Re: [Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Gerd Hoffmann]

>      case QXL_IO_LOG:
> -        trace_qxl_io_log(d->id, d->ram->log_buf);
> +        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';
> +        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);
>          if (d->guestdebug) {

Reviewed-by: Gerd Hoffmann <kraxel@redhat.com>

Re: [Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Stefan Hajnoczi]

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

On Fri, Jan 18, 2019 at 05:31:00PM +0000, Daniel P. Berrangé wrote:
> diff --git a/hw/display/qxl.c b/hw/display/qxl.c
> index 8e9a65e75b..eefdf4baac 100644
> --- a/hw/display/qxl.c
> +++ b/hw/display/qxl.c
> @@ -1763,7 +1763,8 @@ async_common:
>          qxl_set_mode(d, val, 0);
>          break;
>      case QXL_IO_LOG:
> -        trace_qxl_io_log(d->id, d->ram->log_buf);
> +        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';
> +        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);

This is a PCI BAR shared with the guest?  Then NUL termination is
subject to races with vcpu threads that modify log_buf[] while we access
it.

The safe way to do this is to copy in log_buf[] and then NUL-terminate
the local copy.

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

Re: [Qemu-devel] [PATCH v2 1/4] display: ensure qxl log_buf is a nul terminated string

[Daniel P. Berrangé]

On Mon, Jan 21, 2019 at 10:45:45AM +0000, Stefan Hajnoczi wrote:
> On Fri, Jan 18, 2019 at 05:31:00PM +0000, Daniel P. Berrangé wrote:
> > diff --git a/hw/display/qxl.c b/hw/display/qxl.c
> > index 8e9a65e75b..eefdf4baac 100644
> > --- a/hw/display/qxl.c
> > +++ b/hw/display/qxl.c
> > @@ -1763,7 +1763,8 @@ async_common:
> >          qxl_set_mode(d, val, 0);
> >          break;
> >      case QXL_IO_LOG:
> > -        trace_qxl_io_log(d->id, d->ram->log_buf);
> > +        d->ram->log_buf[sizeof(d->ram->log_buf) - 1] = '\0';
> > +        trace_qxl_io_log(d->id, (const char *)d->ram->log_buf);
> 
> This is a PCI BAR shared with the guest?  Then NUL termination is
> subject to races with vcpu threads that modify log_buf[] while we access
> it.

Doh, yes, it is racy.

> The safe way to do this is to copy in log_buf[] and then NUL-terminate
> the local copy.

log_buf is 4k in size, which I don't really want to allocate on the
stack. Using malloc would impose a perf penalty on logging but not
sure if that's significant enough to worry about. Alternatively we
could just drop the tracepoint, given that you can already use the
'guestdebug' option to get these fprintf'd to stderr.

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

[Qemu-devel] [PATCH v2 2/4] trace: enforce that every trace-events file has a final newline

[Daniel P. Berrangé]

When generating the trace-events-all file, the build system simply
concatenates all the individual trace-events files. If any one of those
files does not have a final newline, the printf format string will have
the contents of the first line of the next file appended to it, which is
usually a '#' comment.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 hw/gpio/trace-events          | 2 +-
 scripts/tracetool/__init__.py | 2 ++
 2 files changed, 3 insertions(+), 1 deletion(-)

diff --git a/hw/gpio/trace-events b/hw/gpio/trace-events
index cb41a89756..5d4dd200c2 100644
--- a/hw/gpio/trace-events
+++ b/hw/gpio/trace-events
@@ -4,4 +4,4 @@
 nrf51_gpio_read(uint64_t offset, uint64_t r) "offset 0x%" PRIx64 " value 0x%" PRIx64
 nrf51_gpio_write(uint64_t offset, uint64_t value) "offset 0x%" PRIx64 " value 0x%" PRIx64
 nrf51_gpio_set(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
-nrf51_gpio_update_output_irq(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
\ No newline at end of file
+nrf51_gpio_update_output_irq(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py
index 0e3c9e146c..3478ac93ab 100644
--- a/scripts/tracetool/__init__.py
+++ b/scripts/tracetool/__init__.py
@@ -350,6 +350,8 @@ def read_events(fobj, fname):
 
     events = []
     for lineno, line in enumerate(fobj, 1):
+        if line[-1] != '\n':
+            raise ValueError("%s does not end with a new line" % fname)
         if not line.strip():
             continue
         if line.lstrip().startswith('#'):
-- 
2.20.1

Re: [Qemu-devel] [PATCH v2 2/4] trace: enforce that every trace-events file has a final newline

[Eric Blake]

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

On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> When generating the trace-events-all file, the build system simply
> concatenates all the individual trace-events files. If any one of those
> files does not have a final newline, the printf format string will have
> the contents of the first line of the next file appended to it, which is
> usually a '#' comment.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  hw/gpio/trace-events          | 2 +-
>  scripts/tracetool/__init__.py | 2 ++
>  2 files changed, 3 insertions(+), 1 deletion(-)
> 

Reviewed-by: Eric Blake <eblake@redhat.com>

Does checkpatch and/or patchew flag what are intended to be text files
but which lack a trailing newline?  If not, how hard would it be to get
them to do so?

> diff --git a/hw/gpio/trace-events b/hw/gpio/trace-events
> index cb41a89756..5d4dd200c2 100644
> --- a/hw/gpio/trace-events
> +++ b/hw/gpio/trace-events
> @@ -4,4 +4,4 @@
>  nrf51_gpio_read(uint64_t offset, uint64_t r) "offset 0x%" PRIx64 " value 0x%" PRIx64
>  nrf51_gpio_write(uint64_t offset, uint64_t value) "offset 0x%" PRIx64 " value 0x%" PRIx64
>  nrf51_gpio_set(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
> -nrf51_gpio_update_output_irq(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
> \ No newline at end of file
> +nrf51_gpio_update_output_irq(int64_t line, int64_t value) "line %" PRIi64 " value %" PRIi64
> diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py

Fixes the problem file...

> index 0e3c9e146c..3478ac93ab 100644
> --- a/scripts/tracetool/__init__.py
> +++ b/scripts/tracetool/__init__.py
> @@ -350,6 +350,8 @@ def read_events(fobj, fname):
>  
>      events = []
>      for lineno, line in enumerate(fobj, 1):
> +        if line[-1] != '\n':
> +            raise ValueError("%s does not end with a new line" % fname)

and ensures that no future trace-events files will have the problem,
whether or not checkpatch flags other such files.

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Qemu-devel] [PATCH v2 2/4] trace: enforce that every trace-events file has a final newline

[Daniel P. Berrangé]

On Fri, Jan 18, 2019 at 11:42:14AM -0600, Eric Blake wrote:
> On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> > When generating the trace-events-all file, the build system simply
> > concatenates all the individual trace-events files. If any one of those
> > files does not have a final newline, the printf format string will have
> > the contents of the first line of the next file appended to it, which is
> > usually a '#' comment.
> > 
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >  hw/gpio/trace-events          | 2 +-
> >  scripts/tracetool/__init__.py | 2 ++
> >  2 files changed, 3 insertions(+), 1 deletion(-)
> > 
> 
> Reviewed-by: Eric Blake <eblake@redhat.com>
> 
> Does checkpatch and/or patchew flag what are intended to be text files
> but which lack a trailing newline?  If not, how hard would it be to get
> them to do so?

it probably should check for missing newlines at end of file, but I'm
going to let someone else tackle that due to time pressures on what
was supposed to be a quick enhancement :-)



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

Re: [Qemu-devel] [PATCH v2 2/4] trace: enforce that every trace-events file has a final newline

[Stefan Hajnoczi]

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

On Fri, Jan 18, 2019 at 05:31:01PM +0000, Daniel P. Berrangé wrote:
> When generating the trace-events-all file, the build system simply
> concatenates all the individual trace-events files. If any one of those
> files does not have a final newline, the printf format string will have
> the contents of the first line of the next file appended to it, which is
> usually a '#' comment.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  hw/gpio/trace-events          | 2 +-
>  scripts/tracetool/__init__.py | 2 ++
>  2 files changed, 3 insertions(+), 1 deletion(-)

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

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

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

[Daniel P. Berrangé]

The '%m' format specifier instructs glibc's printf() implementation to
insert the contents of strerror(errno). 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.

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);
     } 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_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")
+
         if len(fmt_trans) > 0:
             fmt = [fmt_trans, fmt]
         args = Arguments.build(groups["args"])
-- 
2.20.1

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

[Eric Blake]

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

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

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

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

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

[Alex Williamson]

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

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

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

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

[Eric Blake]

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

On 1/22/19 8:32 AM, Daniel P. Berrangé wrote:

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

If we are going to worry about thread-safety of strerror(), we have a
LOT of code to scrub (we are using it rather liberally throughout the
code base).

> 
> 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'm not coming up with one, and I think the problem is independent of
this series (if we DO have a problem, it's a series all its own to
eradicate the use of strerror() in favor of something safer, either
picking strerror_l() or dealing with the glibc vs. BSD differences in
strerror_r()).


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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

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

[Daniel P. Berrangé]

On Tue, Jan 22, 2019 at 11:19:42AM -0600, Eric Blake wrote:
> On 1/22/19 8:32 AM, Daniel P. Berrangé wrote:
> 
> >>> +++ 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.
> 
> If we are going to worry about thread-safety of strerror(), we have a
> LOT of code to scrub (we are using it rather liberally throughout the
> code base).

Yes, indeed we do and it was something that always worried me a little
(as well as a few other non-reentrant APIs we used previously).

> > 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'm not coming up with one, and I think the problem is independent of
> this series (if we DO have a problem, it's a series all its own to
> eradicate the use of strerror() in favor of something safer, either
> picking strerror_l() or dealing with the glibc vs. BSD differences in
> strerror_r()).

Agree that its not really something for this series - this just
made me think of it again.

We went through the scrubbing in libvirt to use the sane, but still
tedious to call, variant of strerror_r() many years ago. With luck
though it is a worry that can be confined the dustbin of ancient
UNIX history....unless someone can point to evidence to the contrary ?

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

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

[Eric Blake]

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

On 1/22/19 11:23 AM, Daniel P. Berrangé wrote:

> 
>>> 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'm not coming up with one, and I think the problem is independent of
>> this series (if we DO have a problem, it's a series all its own to
>> eradicate the use of strerror() in favor of something safer, either
>> picking strerror_l() or dealing with the glibc vs. BSD differences in
>> strerror_r()).
> 
> Agree that its not really something for this series - this just
> made me think of it again.

Shoot - FreeBSD strerror() is not threadsafe:
https://github.com/freebsd/freebsd/blob/master/lib/libc/string/strerror.c#L119

char *
strerror(int num)
{
	static char ebuf[NL_TEXTMAX];

	if (strerror_r(num, ebuf, sizeof(ebuf)) != 0)
		errno = EINVAL;
	return (ebuf);
}

> 
> We went through the scrubbing in libvirt to use the sane, but still
> tedious to call, variant of strerror_r() many years ago. With luck
> though it is a worry that can be confined the dustbin of ancient
> UNIX history....unless someone can point to evidence to the contrary ?

libvirt has it easy - they let gnulib do all the work of futzing around
with getting a working strerror() despite platform bugs and despite
glibc's insistence on a non-POSIX signature if _GNU_SOURCE is defined.
We'll have to do a bit more legwork.

That said, I've added it to:
https://wiki.qemu.org/Contribute/BiteSizedTasks#Error_checking

if someone wants to do the grunt work.

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

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

[Thomas Huth]

[-- Attachment #1.1: Type: text/plain, Size: 1954 bytes --]

On 22/01/2019 19.10, Eric Blake wrote:
> On 1/22/19 11:23 AM, Daniel P. Berrangé wrote:
> 
>>
>>>> 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'm not coming up with one, and I think the problem is independent of
>>> this series (if we DO have a problem, it's a series all its own to
>>> eradicate the use of strerror() in favor of something safer, either
>>> picking strerror_l() or dealing with the glibc vs. BSD differences in
>>> strerror_r()).
>>
>> Agree that its not really something for this series - this just
>> made me think of it again.
> 
> Shoot - FreeBSD strerror() is not threadsafe:
> https://github.com/freebsd/freebsd/blob/master/lib/libc/string/strerror.c#L119
> 
> char *
> strerror(int num)
> {
> 	static char ebuf[NL_TEXTMAX];
> 
> 	if (strerror_r(num, ebuf, sizeof(ebuf)) != 0)
> 		errno = EINVAL;
> 	return (ebuf);
> }
> 
>>
>> We went through the scrubbing in libvirt to use the sane, but still
>> tedious to call, variant of strerror_r() many years ago. With luck
>> though it is a worry that can be confined the dustbin of ancient
>> UNIX history....unless someone can point to evidence to the contrary ?
> 
> libvirt has it easy - they let gnulib do all the work of futzing around
> with getting a working strerror() despite platform bugs and despite
> glibc's insistence on a non-POSIX signature if _GNU_SOURCE is defined.
> We'll have to do a bit more legwork.
> 
> That said, I've added it to:
> https://wiki.qemu.org/Contribute/BiteSizedTasks#Error_checking
> 
> if someone wants to do the grunt work.

I think we should change that task to switch to g_strerror() from glib
instead ... as far as I can see, this is a proper wrapper around
strerror_r(), so we don't have to deal with the implementation oddities
of strerror_r() in QEMU.

 Thomas


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

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

[Daniel P. Berrangé]

On Fri, Oct 18, 2019 at 11:31:15AM +0200, Thomas Huth wrote:
> On 22/01/2019 19.10, Eric Blake wrote:
> > On 1/22/19 11:23 AM, Daniel P. Berrangé wrote:
> > 
> >>
> >>>> 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'm not coming up with one, and I think the problem is independent of
> >>> this series (if we DO have a problem, it's a series all its own to
> >>> eradicate the use of strerror() in favor of something safer, either
> >>> picking strerror_l() or dealing with the glibc vs. BSD differences in
> >>> strerror_r()).
> >>
> >> Agree that its not really something for this series - this just
> >> made me think of it again.
> > 
> > Shoot - FreeBSD strerror() is not threadsafe:
> > https://github.com/freebsd/freebsd/blob/master/lib/libc/string/strerror.c#L119
> > 
> > char *
> > strerror(int num)
> > {
> > 	static char ebuf[NL_TEXTMAX];
> > 
> > 	if (strerror_r(num, ebuf, sizeof(ebuf)) != 0)
> > 		errno = EINVAL;
> > 	return (ebuf);
> > }
> > 
> >>
> >> We went through the scrubbing in libvirt to use the sane, but still
> >> tedious to call, variant of strerror_r() many years ago. With luck
> >> though it is a worry that can be confined the dustbin of ancient
> >> UNIX history....unless someone can point to evidence to the contrary ?
> > 
> > libvirt has it easy - they let gnulib do all the work of futzing around
> > with getting a working strerror() despite platform bugs and despite
> > glibc's insistence on a non-POSIX signature if _GNU_SOURCE is defined.
> > We'll have to do a bit more legwork.
> > 
> > That said, I've added it to:
> > https://wiki.qemu.org/Contribute/BiteSizedTasks#Error_checking
> > 
> > if someone wants to do the grunt work.
> 
> I think we should change that task to switch to g_strerror() from glib
> instead ... as far as I can see, this is a proper wrapper around
> strerror_r(), so we don't have to deal with the implementation oddities
> of strerror_r() in QEMU.

Yeah, I think using g_strerror() makes sense. We've just adopted that
in libvirt precisely to avoid these platform portability oddities and
the really unpleasant API calling convention of strerror_r().


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

[Qemu-devel] [PATCH v2 4/4] trace: add ability to do simple printf logging via systemtap

[Daniel P. Berrangé]

The dtrace systemtap trace backend for QEMU is very powerful but it is
also somewhat unfriendly to users who aren't familiar with systemtap,
or who don't need its power right now.

  stap -e "....some strange script...."

The 'log' backend for QEMU by comparison is very crude but incredibly
easy to use:

 $ qemu -d trace:qio* ...some args...
 23266@1547735759.137292:qio_channel_socket_new Socket new ioc=0x563a8a39d400
 23266@1547735759.137305:qio_task_new Task new task=0x563a891d0570 source=0x563a8a39d400 func=0x563a86f1e6c0 opaque=0x563a89078000
 23266@1547735759.137326:qio_task_thread_start Task thread start task=0x563a891d0570 worker=0x563a86f1ce50 opaque=0x563a891d9d90
 23273@1547735759.137491:qio_task_thread_run Task thread run task=0x563a891d0570
 23273@1547735759.137503:qio_channel_socket_connect_sync Socket connect sync ioc=0x563a8a39d400 addr=0x563a891d9d90
 23273@1547735759.138108:qio_channel_socket_connect_fail Socket connect fail ioc=0x563a8a39d400

This commit introduces a way to do simple printf style logging of probe
points using systemtap. In particular it creates another set of tapsets,
one per emulator:

  /usr/share/systemtap/tapset/qemu-*-log.stp

These pre-define probe functions which simply call printf() on their
arguments. The printf() format string is taken from the normal
trace-events files, with a little munging to the format specifiers
to cope with systemtap's more restrictive syntax.

With this you can now do

 $ stap -e 'probe qemu.system.x86_64.log.qio*{}'
 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00
 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400
 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70
 22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0

We go one step further though and introduce a 'qemu-trace-stap' tool to
make this even easier

 $ qemu-trace-stap run qemu-system-x86_64 qio*
 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00
 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400
 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70
 22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0

This tool is clever in that it will automatically change the
SYSTEMTAP_TAPSET env variable to point to the directory containing the
right set of probes for the QEMU binary path you give it. This is useful
if you have QEMU installed in /usr but are trying to test and trace a
binary in /home/berrange/usr/qemu-git. In that case you'd do

 $ qemu-trace-stap run /home/berrange/usr/qemu-git/bin/qemu-system-x86_64 qio*

And it'll make sure /home/berrange/usr/qemu-git/share/systemtap/tapset
is used for the trace session

The 'qemu-trace-stap' script takes a verbose arg so you can understand
what it is running

 $ qemu-trace-stap run /home/berrange/usr/qemu-git/bin/qemu-system-x86_64 qio*
 Using tapset dir '/home/berrange/usr/qemu-git/share/systemtap/tapset' for binary '/home/berrange/usr/qemu-git/bin/qemu-system-x86_64'
 Compiling script 'probe qemu.system.x86_64.log.qio* {}'
 Running script, <Ctrl>-c to quit
 ...trace output...

It can enable multiple probes at once

 $ qemu-trace-stap run qemu-system-x86_64 qio* qcrypto* buffer*

Finally if you can't remember what probes are valid it can tell you

 $ qemu-trace-stap list qemu-system-x86_64
 ahci_check_irq
 ahci_cmd_done
 ahci_dma_prepare_buf
 ahci_dma_prepare_buf_fail
 ahci_dma_rw_buf
 ahci_irq_lower
 ...snip...

Or list just those matching a prefix pattern

 $ qemu-trace-stap list -v qemu-system-x86_64 qio*
 Using tapset dir '/home/berrange/usr/qemu-git/share/systemtap/tapset' for binary '/home/berrange/usr/qemu-git/bin/qemu-system-x86_64'
 Listing probes with name 'qemu.system.x86_64.log.qio*'
 qio_channel_command_abort
 qio_channel_command_new_pid
 qio_channel_command_new_spawn
 qio_channel_command_wait
 qio_channel_file_new_fd
 ...snip...

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 Makefile                             |   3 +
 Makefile.target                      |  11 +-
 docs/devel/tracing.txt               |  32 +++++
 scripts/qemu-trace-stap              | 167 +++++++++++++++++++++++++++
 scripts/tracetool/format/log_stap.py | 127 ++++++++++++++++++++
 5 files changed, 339 insertions(+), 1 deletion(-)
 create mode 100755 scripts/qemu-trace-stap
 create mode 100644 scripts/tracetool/format/log_stap.py

diff --git a/Makefile b/Makefile
index dccba1dca2..22e481e7ba 100644
--- a/Makefile
+++ b/Makefile
@@ -736,6 +736,9 @@ endif
 ifneq ($(HELPERS-y),)
 	$(call install-prog,$(HELPERS-y),$(DESTDIR)$(libexecdir))
 endif
+ifdef CONFIG_TRACE_SYSTEMTAP
+	$(INSTALL_PROG) "scripts/qemu-trace-stap" $(DESTDIR)$(bindir)
+endif
 ifneq ($(BLOBS),)
 	set -e; for x in $(BLOBS); do \
 		$(INSTALL_DATA) $(SRC_PATH)/pc-bios/$$x "$(DESTDIR)$(qemu_datadir)"; \
diff --git a/Makefile.target b/Makefile.target
index 39f72e81be..401dc1ea6f 100644
--- a/Makefile.target
+++ b/Makefile.target
@@ -45,7 +45,7 @@ config-target.h: config-target.h-timestamp
 config-target.h-timestamp: config-target.mak
 
 ifdef CONFIG_TRACE_SYSTEMTAP
-stap: $(QEMU_PROG).stp-installed $(QEMU_PROG).stp $(QEMU_PROG)-simpletrace.stp
+stap: $(QEMU_PROG).stp-installed $(QEMU_PROG).stp $(QEMU_PROG)-simpletrace.stp $(QEMU_PROG)-log.stp
 
 ifdef CONFIG_USER_ONLY
 TARGET_TYPE=user
@@ -84,6 +84,14 @@ $(QEMU_PROG)-simpletrace.stp: $(BUILD_DIR)/trace-events-all $(tracetool-y)
 		--probe-prefix=qemu.$(TARGET_TYPE).$(TARGET_NAME) \
 		$< > $@,"GEN","$(TARGET_DIR)$(QEMU_PROG)-simpletrace.stp")
 
+$(QEMU_PROG)-log.stp: $(BUILD_DIR)/trace-events-all $(tracetool-y)
+	$(call quiet-command,$(TRACETOOL) \
+		--group=all \
+		--format=log-stap \
+		--backends=$(TRACE_BACKENDS) \
+		--probe-prefix=qemu.$(TARGET_TYPE).$(TARGET_NAME) \
+		$< > $@,"GEN","$(TARGET_DIR)$(QEMU_PROG)-log.stp")
+
 else
 stap:
 endif
@@ -227,6 +235,7 @@ ifdef CONFIG_TRACE_SYSTEMTAP
 	$(INSTALL_DIR) "$(DESTDIR)$(qemu_datadir)/../systemtap/tapset"
 	$(INSTALL_DATA) $(QEMU_PROG).stp-installed "$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG).stp"
 	$(INSTALL_DATA) $(QEMU_PROG)-simpletrace.stp "$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG)-simpletrace.stp"
+	$(INSTALL_DATA) $(QEMU_PROG)-log.stp "$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG)-log.stp"
 endif
 
 GENERATED_FILES += config-target.h
diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.txt
index bc52f12485..53327cd35b 100644
--- a/docs/devel/tracing.txt
+++ b/docs/devel/tracing.txt
@@ -317,6 +317,38 @@ probes:
                          --target-name x86_64 \
                          <trace-events-all >qemu.stp
 
+To facilitate simple usage of systemtap where there merely needs to be printf
+logging of certain probes, a helper script "qemu-trace-stap" is provided
+
+This can list all probes available for a given QEMU emulator binary:
+
+     $ qemu-trace-stap list qemu-system-x86_64
+     ahci_check_irq
+     ahci_cmd_done
+     ahci_dma_prepare_buf
+     ahci_dma_prepare_buf_fail
+     ahci_dma_rw_buf
+     ahci_irq_lower
+     ...snip...
+
+Optionally restricted to a pattern prefix:
+
+     $ qemu-trace-stap list qemu-system-x86_64 qio*
+     qio_channel_command_abort
+     qio_channel_command_new_pid
+     qio_channel_command_new_spawn
+     qio_channel_command_wait
+     qio_channel_file_new_fd
+     ...snip...
+
+It can then run a simple systemtap script which prints each requested probe
+
+     $ qemu-trace-stap run qemu-system-x86_64 qio*
+     22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00
+     22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400
+     22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70
+     22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0
+
 == Trace event properties ==
 
 Each event in the "trace-events-all" file can be prefixed with a space-separated
diff --git a/scripts/qemu-trace-stap b/scripts/qemu-trace-stap
new file mode 100755
index 0000000000..2db7b1470c
--- /dev/null
+++ b/scripts/qemu-trace-stap
@@ -0,0 +1,167 @@
+#!/usr/bin/python
+# -*- python -*-
+#
+#  Copyright (C) 2019 Red Hat, Inc
+#
+#  QEMU SystemTap Trace Tool
+#
+#  This program is free software; you can redistribute it and/or modify
+#  it under the terms of the GNU General Public License as published by
+#  the Free Software Foundation; under version 2 of the License.
+#
+#  This program is distributed in the hope that it will be useful,
+#  but WITHOUT ANY WARRANTY; without even the implied warranty of
+#  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+#  GNU General Public License for more details.
+#
+#  You should have received a copy of the GNU General Public License
+#  along with this program; if not, see <http://www.gnu.org/licenses/>.
+
+from __future__ import print_function
+
+import argparse
+import copy
+import os.path
+import re
+import subprocess
+import sys
+
+
+def probe_prefix(binary):
+    dirname, filename = os.path.split(binary)
+    return re.sub("-", ".", filename) + ".log"
+
+
+def which(binary):
+    for path in os.environ["PATH"].split(os.pathsep):
+        if os.path.exists(os.path.join(path, binary)):
+                return os.path.join(path, binary)
+
+    print("Unable to find '%s' in $PATH" % binary)
+    sys.exit(1)
+
+
+def tapset_dir(binary):
+    dirname, filename = os.path.split(binary)
+    if dirname == '':
+        thisfile = which(binary)
+    else:
+        thisfile = os.path.realpath(binary)
+        if not os.path.exists(thisfile):
+            print("Unable to find '%s'" % thisfile)
+            sys.exit(1)
+
+    basedir = os.path.split(thisfile)[0]
+    tapset = os.path.join(basedir, "..", "share", "systemtap", "tapset")
+    return os.path.realpath(tapset)
+
+
+def tapset_env(tapset_dir):
+    tenv = copy.copy(os.environ)
+    tenv["SYSTEMTAP_TAPSET"] = tapset_dir
+    return tenv
+
+def cmd_run(args):
+    prefix = probe_prefix(args.binary)
+    tapsets = tapset_dir(args.binary)
+
+    if args.verbose:
+        print("Using tapset dir '%s' for binary '%s'" % (tapsets, args.binary))
+
+    probes = []
+    for probe in args.probes:
+        probes.append("probe %s.%s {}" % (prefix, probe))
+    if len(probes) == 0:
+        probes.append("probe %s.* {}" % prefix)
+
+    script = " ".join(probes)
+    if args.verbose:
+        print("Compiling script '%s'" % script)
+        script = """probe begin { print("Running script, <Ctrl>-c to quit\\n") } """ + script
+    subprocess.call(["stap", "-e", script],
+                    env=tapset_env(tapsets))
+
+
+def cmd_list(args):
+    tapsets = tapset_dir(args.binary)
+
+    if args.verbose:
+        print("Using tapset dir '%s' for binary '%s'" % (tapsets, args.binary))
+
+    def print_probes(verbose, name):
+        prefix = probe_prefix(args.binary)
+        offset = len(prefix) + 1
+        script = prefix + "." + name
+
+        if verbose:
+            print("Listing probes with name '%s'" % script)
+        proc = subprocess.Popen(["stap", "-l", script],
+                                stdout=subprocess.PIPE, env=tapset_env(tapsets))
+        out, err = proc.communicate()
+        if proc.returncode != 0:
+            print("No probes found, are the tapsets installed in %s" % tapset_dir(args.binary))
+            sys.exit(1)
+
+        for line in out.splitlines():
+            if line.startswith(prefix):
+                print("%s" % line[offset:])
+
+    if len(args.probes) == 0:
+        print_probes(args.verbose, "*")
+    else:
+        for probe in args.probes:
+            print_probes(args.verbose, probe)
+
+
+def main():
+    parser = argparse.ArgumentParser(description="QEMU SystemTap trace tool")
+
+    subparser = parser.add_subparsers(help="commands")
+    subparser.required = True
+    subparser.dest = "command"
+
+    runparser = subparser.add_parser("run", help="Run a trace session",
+                                     formatter_class=argparse.RawDescriptionHelpFormatter,
+                                     epilog="""
+
+To watch all trace points on the qemu-system-x86_64 binary:
+
+   %(argv0)s run qemu-system-x86_64
+
+To only watch the trace points matching the qio* and qcrypto* patterns
+
+   %(argv0)s run qemu-system-x86_64 qio* qcrypto*
+""" % {"argv0": sys.argv[0]})
+    runparser.set_defaults(func=cmd_run)
+    runparser.add_argument("-v", "--verbose", help="Print verbose progress info",
+                           action='store_true')
+    runparser.add_argument("binary", help="QEMU system or user emulator binary")
+    runparser.add_argument("probes", help="Probe names or wildcards",
+                           nargs=argparse.REMAINDER)
+
+    listparser = subparser.add_parser("list", help="List probe points",
+                                      formatter_class=argparse.RawDescriptionHelpFormatter,
+                                      epilog="""
+
+To list all trace points on the qemu-system-x86_64 binary:
+
+   %(argv0)s list qemu-system-x86_64
+
+To only list the trace points matching the qio* and qcrypto* patterns
+
+   %(argv0)s list qemu-system-x86_64 qio* qcrypto*
+""" % {"argv0": sys.argv[0]})
+    listparser.set_defaults(func=cmd_list)
+    listparser.add_argument("-v", "--verbose", help="Print verbose progress info",
+                            action='store_true')
+    listparser.add_argument("binary", help="QEMU system or user emulator binary")
+    listparser.add_argument("probes", help="Probe names or wildcards",
+                            nargs=argparse.REMAINDER)
+
+    args = parser.parse_args()
+
+    args.func(args)
+    sys.exit(0)
+
+if __name__ == '__main__':
+    main()
diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
new file mode 100644
index 0000000000..3ccbc09d61
--- /dev/null
+++ b/scripts/tracetool/format/log_stap.py
@@ -0,0 +1,127 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""
+Generate .stp file that printfs log messages (DTrace with SystemTAP only).
+"""
+
+__author__     = "Daniel P. Berrange <berrange@redhat.com>"
+__copyright__  = "Copyright (C) 2014-2019, Red Hat, Inc."
+__license__    = "GPL version 2 or (at your option) any later version"
+
+__maintainer__ = "Daniel Berrange"
+__email__      = "berrange@redhat.com"
+
+import re
+
+from tracetool import out
+from tracetool.backend.dtrace import binary, probeprefix
+from tracetool.backend.simple import is_string
+from tracetool.format.stap import stap_escape
+
+def global_var_name(name):
+    return probeprefix().replace(".", "_") + "_" + name
+
+STATE_SKIP = 0
+STATE_LITERAL = 1
+STATE_MACRO = 2
+
+def c_macro_to_format(macro):
+    if macro.startswith("PRI"):
+        return macro[3]
+
+    if macro == "TARGET_FMT_plx":
+        return "%016x"
+
+    raise Exception("Unhandled macro '%s'" % macro)
+
+def c_fmt_to_stap(fmt):
+    state = 0
+    bits = []
+    literal = ""
+    macro = ""
+    escape = 0;
+    for i in range(len(fmt)):
+        if fmt[i] == '\\':
+            if escape:
+                escape = 0
+            else:
+                escape = 1
+            if state != STATE_LITERAL:
+                raise Exception("Unexpected escape outside string literal")
+            literal = literal + fmt[i]
+        elif fmt[i] == '"' and not escape:
+            if state == STATE_LITERAL:
+                state = STATE_SKIP
+                bits.append(literal)
+                literal = ""
+            else:
+                if state == STATE_MACRO:
+                    bits.append(c_macro_to_format(macro))
+                state = STATE_LITERAL
+        elif fmt[i] == ' ' or fmt[i] == '\t':
+            if state == STATE_MACRO:
+                bits.append(c_macro_to_format(macro))
+                macro = ""
+                state = STATE_SKIP
+            elif state == STATE_LITERAL:
+                literal = literal + fmt[i]
+        else:
+            escape = 0
+            if state == STATE_SKIP:
+                state = STATE_MACRO
+
+            if state == STATE_LITERAL:
+                literal = literal + fmt[i]
+            else:
+                macro = macro + fmt[i]
+
+    if state == STATE_MACRO:
+        bits.append(c_macro_to_format(macro))
+    elif state == STATE_LITERAL:
+        bits.append(literal)
+
+    fmt = re.sub("%(\d*)z(x|u|d)", "%\\1\\2", "".join(bits))
+    return fmt
+
+def generate(events, backend, group):
+    out('/* This file is autogenerated by tracetool, do not edit. */',
+        '')
+
+    for event_id, e in enumerate(events):
+        if 'disable' in e.properties:
+            continue
+
+        out('probe %(probeprefix)s.log.%(name)s = %(probeprefix)s.%(name)s ?',
+            '{',
+            probeprefix=probeprefix(),
+            name=e.name)
+
+        # Get references to userspace strings
+        for type_, name in e.args:
+            name = stap_escape(name)
+            if is_string(type_):
+                out('    try {',
+                    '        arg%(name)s_str = %(name)s ? ' +
+                    'user_string_n(%(name)s, 512) : "<null>"',
+                    '    } catch {}',
+                    name=name)
+
+        # Determine systemtap's view of variable names
+        fields = ["pid()", "gettimeofday_ns()"]
+        for type_, name in e.args:
+            name = stap_escape(name)
+            if is_string(type_):
+                fields.append("arg" + name + "_str")
+            else:
+                fields.append(name)
+
+        # Emit the entire record in a single SystemTap printf()
+        arg_str = ', '.join(arg for arg in fields)
+        fmt_str = "%d@%d " + e.name + " " + c_fmt_to_stap(e.fmt) + "\\n"
+        out('    printf("%(fmt_str)s", %(arg_str)s)',
+            fmt_str=fmt_str, arg_str=arg_str)
+
+        out('}')
+
+    out()
-- 
2.20.1

Re: [Qemu-devel] [PATCH v2 4/4] trace: add ability to do simple printf logging via systemtap

[Eric Blake]

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

On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> The dtrace systemtap trace backend for QEMU is very powerful but it is
> also somewhat unfriendly to users who aren't familiar with systemtap,
> or who don't need its power right now.
> 
>   stap -e "....some strange script...."
> 

> We go one step further though and introduce a 'qemu-trace-stap' tool to
> make this even easier
> 
>  $ qemu-trace-stap run qemu-system-x86_64 qio*
>  22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00

One thing I did not immediately get on the first read, and therefore
which may be worth mentioning in the docs portion of the patch:

Am I correct that stap is always run as a separate process from the
process(es) being traced, and that you can start the two in either order
(qemu first, then stap; or stap first, then qemu), where the tracing is
effectively output as long as both processes are running and trace
points being hit in the qemu process?


> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  Makefile                             |   3 +
>  Makefile.target                      |  11 +-
>  docs/devel/tracing.txt               |  32 +++++
>  scripts/qemu-trace-stap              | 167 +++++++++++++++++++++++++++
>  scripts/tracetool/format/log_stap.py | 127 ++++++++++++++++++++

Overall, I'm impressed with the concept, but my familiarity with stap
and python is weak enough that I'm not leaving a formal R-b.  Still,
I'll give it a shot at looking for anything that stands out as I read
through.

>  5 files changed, 339 insertions(+), 1 deletion(-)
>  create mode 100755 scripts/qemu-trace-stap
>  create mode 100644 scripts/tracetool/format/log_stap.py
> 
> diff --git a/Makefile b/Makefile
> index dccba1dca2..22e481e7ba 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -736,6 +736,9 @@ endif
>  ifneq ($(HELPERS-y),)
>  	$(call install-prog,$(HELPERS-y),$(DESTDIR)$(libexecdir))
>  endif
> +ifdef CONFIG_TRACE_SYSTEMTAP
> +	$(INSTALL_PROG) "scripts/qemu-trace-stap" $(DESTDIR)$(bindir)
> +endif

No man page being installed?  If we're planning on this binary being
available on a similar par with qemu-io, it deserves some installed
documentation.


> +++ b/docs/devel/tracing.txt
> @@ -317,6 +317,38 @@ probes:
>                           --target-name x86_64 \
>                           <trace-events-all >qemu.stp
>  
> +To facilitate simple usage of systemtap where there merely needs to be printf
> +logging of certain probes, a helper script "qemu-trace-stap" is provided
> +

Trailing '.' would look better

> +This can list all probes available for a given QEMU emulator binary:
> +
> +     $ qemu-trace-stap list qemu-system-x86_64
> +     ahci_check_irq
> +     ahci_cmd_done
> +     ahci_dma_prepare_buf
> +     ahci_dma_prepare_buf_fail
> +     ahci_dma_rw_buf
> +     ahci_irq_lower
> +     ...snip...
> +
> +Optionally restricted to a pattern prefix:
> +
> +     $ qemu-trace-stap list qemu-system-x86_64 qio*
> +     qio_channel_command_abort
> +     qio_channel_command_new_pid
> +     qio_channel_command_new_spawn
> +     qio_channel_command_wait
> +     qio_channel_file_new_fd
> +     ...snip...
> +
> +It can then run a simple systemtap script which prints each requested probe

Trailing ':' would look better

> +
> +     $ qemu-trace-stap run qemu-system-x86_64 qio*
> +     22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00
> +     22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400
> +     22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70
> +     22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0
> +

> +++ b/scripts/qemu-trace-stap

> +
> +def main():
> +    parser = argparse.ArgumentParser(description="QEMU SystemTap trace tool")
> +
> +    subparser = parser.add_subparsers(help="commands")
> +    subparser.required = True
> +    subparser.dest = "command"
> +
> +    runparser = subparser.add_parser("run", help="Run a trace session",
> +                                     formatter_class=argparse.RawDescriptionHelpFormatter,
> +                                     epilog="""
> +
> +To watch all trace points on the qemu-system-x86_64 binary:
> +
> +   %(argv0)s run qemu-system-x86_64
> +
> +To only watch the trace points matching the qio* and qcrypto* patterns
> +
> +   %(argv0)s run qemu-system-x86_64 qio* qcrypto*

This output is not copy-pastable - it includes shell globs which might
inadvertantly expand based on the contents of $PWD. Should you amend the
output to be properly quoted for reuse in shell commands?

> +""" % {"argv0": sys.argv[0]})
> +    runparser.set_defaults(func=cmd_run)
> +    runparser.add_argument("-v", "--verbose", help="Print verbose progress info",
> +                           action='store_true')
> +    runparser.add_argument("binary", help="QEMU system or user emulator binary")
> +    runparser.add_argument("probes", help="Probe names or wildcards",
> +                           nargs=argparse.REMAINDER)
> +
> +    listparser = subparser.add_parser("list", help="List probe points",
> +                                      formatter_class=argparse.RawDescriptionHelpFormatter,
> +                                      epilog="""
> +
> +To list all trace points on the qemu-system-x86_64 binary:
> +
> +   %(argv0)s list qemu-system-x86_64
> +
> +To only list the trace points matching the qio* and qcrypto* patterns
> +
> +   %(argv0)s list qemu-system-x86_64 qio* qcrypto*

and again

> +""" % {"argv0": sys.argv[0]})
> +    listparser.set_defaults(func=cmd_list)
> +    listparser.add_argument("-v", "--verbose", help="Print verbose progress info",
> +                            action='store_true')
> +    listparser.add_argument("binary", help="QEMU system or user emulator binary")
> +    listparser.add_argument("probes", help="Probe names or wildcards",
> +                            nargs=argparse.REMAINDER)
> +
> +    args = parser.parse_args()
> +
> +    args.func(args)
> +    sys.exit(0)
> +
> +if __name__ == '__main__':
> +    main()
> diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
> new file mode 100644
> index 0000000000..3ccbc09d61
> --- /dev/null
> +++ b/scripts/tracetool/format/log_stap.py
> @@ -0,0 +1,127 @@
> +#!/usr/bin/env python
> +# -*- coding: utf-8 -*-
> +
> +"""
> +Generate .stp file that printfs log messages (DTrace with SystemTAP only).
> +"""
> +
> +__author__     = "Daniel P. Berrange <berrange@redhat.com>"
> +__copyright__  = "Copyright (C) 2014-2019, Red Hat, Inc."
> +__license__    = "GPL version 2 or (at your option) any later version"
> +
> +__maintainer__ = "Daniel Berrange"
> +__email__      = "berrange@redhat.com"
> +
> +import re
> +
> +from tracetool import out
> +from tracetool.backend.dtrace import binary, probeprefix
> +from tracetool.backend.simple import is_string
> +from tracetool.format.stap import stap_escape
> +
> +def global_var_name(name):
> +    return probeprefix().replace(".", "_") + "_" + name
> +
> +STATE_SKIP = 0
> +STATE_LITERAL = 1
> +STATE_MACRO = 2
> +
> +def c_macro_to_format(macro):
> +    if macro.startswith("PRI"):
> +        return macro[3]
> +
> +    if macro == "TARGET_FMT_plx":
> +        return "%016x"

Do we really want to permit TARGET_FMT in our trace-events files, or
should that be fixed in hw/tpm/trace-events?  See commit 73ff0610.

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Qemu-devel] [PATCH v2 4/4] trace: add ability to do simple printf logging via systemtap

[Stefan Hajnoczi]

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

On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote:
> On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> > +def c_macro_to_format(macro):
> > +    if macro.startswith("PRI"):
> > +        return macro[3]
> > +
> > +    if macro == "TARGET_FMT_plx":
> > +        return "%016x"
> 
> Do we really want to permit TARGET_FMT in our trace-events files, or
> should that be fixed in hw/tpm/trace-events?  See commit 73ff0610.

TARGET_FMT_plx is constant across all QEMU targets.  I think supporting
it is nice since it makes writing trace events more natural/convenient.

Stefan

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

Re: [Qemu-devel] [PATCH v2 4/4] trace: add ability to do simple printf logging via systemtap

[Daniel P. Berrangé]

On Mon, Jan 21, 2019 at 10:53:14AM +0000, Stefan Hajnoczi wrote:
> On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote:
> > On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> > > +def c_macro_to_format(macro):
> > > +    if macro.startswith("PRI"):
> > > +        return macro[3]
> > > +
> > > +    if macro == "TARGET_FMT_plx":
> > > +        return "%016x"
> > 
> > Do we really want to permit TARGET_FMT in our trace-events files, or
> > should that be fixed in hw/tpm/trace-events?  See commit 73ff0610.
> 
> TARGET_FMT_plx is constant across all QEMU targets.  I think supporting
> it is nice since it makes writing trace events more natural/convenient.

Yep, I'm fine with supporting custom macros beyond PRI* in trace-events,
provided that they can be subsituted out with a simple formats code for
stap.

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

Re: [Qemu-devel] [PATCH v2 4/4] trace: add ability to do simple printf logging via systemtap

[Daniel P. Berrangé]

On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote:
> On 1/18/19 11:31 AM, Daniel P. Berrangé wrote:
> > The dtrace systemtap trace backend for QEMU is very powerful but it is
> > also somewhat unfriendly to users who aren't familiar with systemtap,
> > or who don't need its power right now.
> > 
> >   stap -e "....some strange script...."
> > 
> 
> > We go one step further though and introduce a 'qemu-trace-stap' tool to
> > make this even easier
> > 
> >  $ qemu-trace-stap run qemu-system-x86_64 qio*
> >  22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00
> 
> One thing I did not immediately get on the first read, and therefore
> which may be worth mentioning in the docs portion of the patch:
> 
> Am I correct that stap is always run as a separate process from the
> process(es) being traced, and that you can start the two in either order
> (qemu first, then stap; or stap first, then qemu), where the tracing is
> effectively output as long as both processes are running and trace
> points being hit in the qemu process?

If you're using the stap binary directly you have a choice of it
working against any existing process on the system, or you can have
it launch the process on your behalf and target just that one process.

For our wrapper script I'm only targetting the former, since I think
the common case is that someone/something else has already run the
QEMU process. I could however easily add a "-p PID" option too which
would allow the trace to be tailored to a specific QEMU process, instead
of all running QEMU processes.

And yes, there's no ordering dependancy - unless it is critical that
you see traces from QEMU's early initialization of course, in which
case you'd launch the tracing first.

> >  5 files changed, 339 insertions(+), 1 deletion(-)
> >  create mode 100755 scripts/qemu-trace-stap
> >  create mode 100644 scripts/tracetool/format/log_stap.py
> > 
> > diff --git a/Makefile b/Makefile
> > index dccba1dca2..22e481e7ba 100644
> > --- a/Makefile
> > +++ b/Makefile
> > @@ -736,6 +736,9 @@ endif
> >  ifneq ($(HELPERS-y),)
> >  	$(call install-prog,$(HELPERS-y),$(DESTDIR)$(libexecdir))
> >  endif
> > +ifdef CONFIG_TRACE_SYSTEMTAP
> > +	$(INSTALL_PROG) "scripts/qemu-trace-stap" $(DESTDIR)$(bindir)
> > +endif
> 
> No man page being installed?  If we're planning on this binary being
> available on a similar par with qemu-io, it deserves some installed
> documentation.

Heh, no good deed / quick enhancement goes unpunished :-P Yes, I'll
do a proper job of this and write a man page too :-)


> > +To watch all trace points on the qemu-system-x86_64 binary:
> > +
> > +   %(argv0)s run qemu-system-x86_64
> > +
> > +To only watch the trace points matching the qio* and qcrypto* patterns
> > +
> > +   %(argv0)s run qemu-system-x86_64 qio* qcrypto*
> 
> This output is not copy-pastable - it includes shell globs which might
> inadvertantly expand based on the contents of $PWD. Should you amend the
> output to be properly quoted for reuse in shell commands?

Yes, that is true


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