Libguestfs - Nov 2018 - Re: [nbdkit PATCH 0/3] Fix %m usage on BSD

Our use of "%m" in various error messages is testament to the
project's initial life on Linux - but other than Cygwin, I know
of no other platforms supporting that glibc extension.

We COULD audit the code and manually turn "%m" into
"%s"/strerror(errno), but that's a lot of churn. Instead,
let's
fix the few outliers that can't be easily wrapped, then wrap
the remainder.

While I was able to test this on Linux (both that no wrapper is
used by default, and that faking that %m fails causes the wrapper
to do the right thing), I haven't actually tried it on a BSD box,
hence I'll wait for review before pushing.

Eric Blake (3):
  main: Avoid fprintf(%m) for BSD builds
  log: Ensure %m sees correct errno
  log: Guarantee the operation of %m in nbdkit_error()

 docs/nbdkit-filter.pod | 13 +++++++++----
 docs/nbdkit-plugin.pod | 13 +++++++++----
 configure.ac           | 27 +++++++++++++++++++++++++++
 src/internal.h         |  6 ++++++
 src/log-stderr.c       |  4 ++--
 src/log-syslog.c       |  6 +++---
 src/log.c              | 21 +++++++++++++++++++++
 src/main.c             |  4 ++--
 8 files changed, 79 insertions(+), 15 deletions(-)

-- 
2.17.2

printf %m is a glibc extension; using it directly can cause
odd output on BSD. Most of our uses of %m are via nbdkit wrappers,
which will be fixed in a future patch; this was the only %m I
could find in a direct call to the printf family, so it doesn't
hurt to just open-code it.  This particular error is reached
early enough in the process that nbdkit_error() is not a viable
substitute.

Signed-off-by: Eric Blake <eblake@redhat.com>
---
 src/main.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/main.c b/src/main.c
index e80333a..fd6e30e 100644
--- a/src/main.c
+++ b/src/main.c
@@ -1204,8 +1204,8 @@ get_socket_activation (void)
        * and we should exit.
        */
       fprintf (stderr, "%s: socket activation: "
-               "invalid file descriptor fd = %d: %m\n",
-               program_name, fd);
+               "invalid file descriptor fd = %d: %s\n",
+               program_name, fd, strerror(errno));
       exit (EXIT_FAILURE);
     }
   }
-- 
2.17.2

If a user passes %m in a format string, but we do any
intermediate processing that might corrupt errno, then we
risk changing the message that the user intended to be
printed to instead refer to our changed state of errno.
Hoist the saving of errno to occur before any other risky
calls, and restore errno before printing a user-supplied
format.

Signed-off-by: Eric Blake <eblake@redhat.com>
---
 src/log-stderr.c | 4 ++--
 src/log-syslog.c | 6 +++---
 2 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/src/log-stderr.c b/src/log-stderr.c
index 790c2d3..ff0b371 100644
--- a/src/log-stderr.c
+++ b/src/log-stderr.c
@@ -45,11 +45,10 @@
 void
 log_stderr_verror (const char *fs, va_list args)
 {
-  int err;
+  int err = errno;
   const char *name = threadlocal_get_name ();
   size_t instance_num = threadlocal_get_instance_num ();

-  err = errno;
   flockfile (stderr);

   fprintf (stderr, "%s: ", program_name);
@@ -62,6 +61,7 @@ log_stderr_verror (const char *fs, va_list args)
   }

   fprintf (stderr, "error: ");
+  errno = err; /* Must restore in case fs contains %m */
   vfprintf (stderr, fs, args);
   fprintf (stderr, "\n");

diff --git a/src/log-syslog.c b/src/log-syslog.c
index d533c05..611ed04 100644
--- a/src/log-syslog.c
+++ b/src/log-syslog.c
@@ -49,18 +49,17 @@ static const int PRIORITY = LOG_DAEMON|LOG_ERR;
 void
 log_syslog_verror (const char *fs, va_list args)
 {
-  int err;
+  int err = errno;
   const char *name = threadlocal_get_name ();
   size_t instance_num = threadlocal_get_instance_num ();
   CLEANUP_FREE char *msg = NULL;
   size_t len = 0;
   FILE *fp = NULL;

-  err = errno;
-
   fp = open_memstream (&msg, &len);
   if (fp == NULL) {
     /* Fallback to logging using fs, args directly. */
+    errno = err; /* Must restore in case fs contains %m */
     vsyslog (PRIORITY, fs, args);
     goto out;
   }
@@ -72,6 +71,7 @@ log_syslog_verror (const char *fs, va_list args)
     fprintf (fp, ": ");
   }

+  errno = err; /* Must restore in case fs contains %m */
   vfprintf (fp, fs, args);
   fclose (fp);

-- 
2.17.2

printf("%m") is a useful glibc extension, if you are sure
that errno is unchanged between the time of the actual problem
and your output message; it beats the longhand of writing
strerror(errno) yourself.  However, BSD libc does not support
the extension, and can result in awkward error messages like

pread: m

instead of an intended

pread: Input/output error

Solve the problem by probing at configure time if %m works,
(this is a runtime test, but can be overridden for testing or
cross-compiling by setting the nbdkit_cv_func_printf_percent_m
cache variable), and if not, inserting our own wrapper around
vfprintf to manually expand a single instance of %m.  (Thankfully,
it is MUCH easier to do this rewrite for %m, since it does not
consume anything from the va_list arg, than it would be for
any other % sequence where we'd have to write a full printf
parser).

As a caller is unlikely to pass multiple %m in a single format
string, I didn't bother with replacing a second instance; the
documentation updates mention this restriction.

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

---
I have not actually tested on a BSD machine, but did prove to
myself that it works on a glibc system with:
./configure nbdkit_cv_func_printf_percent_m=no
and comparing gdb traces of default and override behaviors.
---
 docs/nbdkit-filter.pod | 13 +++++++++----
 docs/nbdkit-plugin.pod | 13 +++++++++----
 configure.ac           | 27 +++++++++++++++++++++++++++
 src/internal.h         |  6 ++++++
 src/log.c              | 21 +++++++++++++++++++++
 5 files changed, 72 insertions(+), 8 deletions(-)

diff --git a/docs/nbdkit-filter.pod b/docs/nbdkit-filter.pod
index 7d5a549..77ecd7b 100644
--- a/docs/nbdkit-filter.pod
+++ b/docs/nbdkit-filter.pod
@@ -524,7 +524,10 @@ L<printf(3)>:
  void nbdkit_error (const char *fs, ...);
  void nbdkit_verror (const char *fs, va_list args);

-For convenience, C<nbdkit_error> preserves the value of C<errno>.
+For convenience, C<nbdkit_error> preserves the value of C<errno>,
and
+also supports the glibc extension of a single C<%m> in a format string
+expanding to C<strerror(errno)>, even on platforms that don't support
+that natively.

 =head1 DEBUGGING

@@ -540,9 +543,11 @@ L<printf(3)>:
  void nbdkit_debug (const char *fs, ...);
  void nbdkit_vdebug (const char *fs, va_list args);

-For convenience, C<nbdkit_debug> preserves the value of C<errno>.
-Note that C<nbdkit_debug> only prints things when the server is in
-verbose mode (I<-v> option).
+For convenience, C<nbdkit_debug> preserves the value of C<errno>,
and
+also supports the glibc extension of a single C<%m> in a format string
+expanding to C<strerror(errno)>, even on platforms that don't support
+that natively.  Note that C<nbdkit_debug> only prints things when the
+server is in verbose mode (I<-v> option).

 =head2 Debug Flags

diff --git a/docs/nbdkit-plugin.pod b/docs/nbdkit-plugin.pod
index 4754d2c..0f8ef79 100644
--- a/docs/nbdkit-plugin.pod
+++ b/docs/nbdkit-plugin.pod
@@ -254,7 +254,10 @@ L<printf(3)>:
  void nbdkit_error (const char *fs, ...);
  void nbdkit_verror (const char *fs, va_list args);

-For convenience, C<nbdkit_error> preserves the value of C<errno>.
+For convenience, C<nbdkit_error> preserves the value of C<errno>,
and
+also supports the glibc extension of a single C<%m> in a format string
+expanding to C<strerror(errno)>, even on platforms that don't support
+that natively.

 C<nbdkit_set_error> can be called at any time, but only has an impact
 during callbacks for serving data, and only when the callback returns
@@ -831,9 +834,11 @@ L<printf(3)>:
  void nbdkit_debug (const char *fs, ...);
  void nbdkit_vdebug (const char *fs, va_list args);

-For convenience, C<nbdkit_debug> preserves the value of C<errno>.
-Note that C<nbdkit_debug> only prints things when the server is in
-verbose mode (I<-v> option).
+For convenience, C<nbdkit_debug> preserves the value of C<errno>,
and
+also supports the glibc extension of a single C<%m> in a format string
+expanding to C<strerror(errno)>, even on platforms that don't support
+that natively. Note that C<nbdkit_debug> only prints things when the
+server is in verbose mode (I<-v> option).

 =head2 Debug Flags

diff --git a/configure.ac b/configure.ac
index 4b1b004..5735921 100644
--- a/configure.ac
+++ b/configure.ac
@@ -57,6 +57,7 @@ dnl Check for basic C environment.
 AC_PROG_CC_STDC
 AC_PROG_INSTALL
 AC_PROG_CPP
+AC_CANONICAL_HOST

 AC_C_PROTOTYPES
 test "x$U" != "x" && AC_MSG_ERROR([Compiler not
ANSI compliant])
@@ -173,6 +174,32 @@ AC_CHECK_FUNCS([\
 	get_current_dir_name \
 	mkostemp])

+dnl Check whether printf("%m") works
+AC_CACHE_CHECK([whether the printf family supports %m],
+  [nbdkit_cv_func_printf_percent_m],
+  [AC_RUN_IFELSE(
+    [AC_LANG_PROGRAM([[
+#include <stdio.h>
+#include <string.h>
+#include <errno.h>
+    ]], [[
+    char buf[200] = "";
+    errno = EINVAL;
+    snprintf(buf, sizeof buf, "%m");
+    return !!strcmp (buf, strerror (EINVAL));
+    ]])],
+    [nbdkit_cv_func_printf_percent_m=yes],
+    [nbdkit_cv_func_printf_percent_m=no],
+    [[
+    case "$host_os" in
+      *-gnu* | gnu*) nbdkit_cv_func_printf_percent_m=yes;;
+      *) nbdkit_cv_func_printf_percent_m="guessing no";;
+    esac
+    ]])])
+AS_IF([test "x$nbdkit_cv_func_printf_percent_m" = xyes],
+  [AC_DEFINE([HAVE_VFPRINTF_PERCENT_M],[1],
+    [Define to 1 if vfprintf supports %m.])])
+
 old_LIBS="$LIBS"
 AC_SEARCH_LIBS([dlopen], [dl dld], [
         AS_IF([test "x$ac_cv_search_dlopen" != "xnone
required"],
diff --git a/src/internal.h b/src/internal.h
index 4da8851..29ab843 100644
--- a/src/internal.h
+++ b/src/internal.h
@@ -148,6 +148,12 @@ extern int crypto_negotiate_tls (struct connection *conn,
int sockin, int sockou
 #define debug nbdkit_debug

 /* log-*.c */
+#if !HAVE_VFPRINTF_PERCENT_M
+#include <stdio.h>
+#define vfprintf nbdkit_vfprintf
+int __attribute__ ((format (printf, 2, 0)))
+nbdkit_vfprintf(FILE *f, const char *fmt, va_list args);
+#endif
 void log_stderr_verror (const char *fs, va_list args);
 void log_syslog_verror (const char *fs, va_list args);

diff --git a/src/log.c b/src/log.c
index 148df5f..b314ca0 100644
--- a/src/log.c
+++ b/src/log.c
@@ -75,3 +75,24 @@ nbdkit_error (const char *fs, ...)
   nbdkit_verror (fs, args);
   va_end (args);
 }
+
+#if !HAVE_VFPRINTF_PERCENT_M
+/* Work around lack of %m in BSD */
+#undef vfprintf
+
+/* Call the real vfprintf after first changing %m into strerror(errno). */
+int
+nbdkit_vfprintf(FILE *f, const char *fmt, va_list args)
+{
+  char *repl = NULL;
+  char *p = strstr (fmt, "%m"); /* assume strstr doesn't touch
errno */
+  int ret;
+
+  if (p && asprintf(&repl, "%.*s%s%s", (int) (p - fmt),
fmt, strerror (errno),
+                    p + 2) > 0)
+    fmt = repl;
+  ret = vfprintf (f, fmt, args);
+  free (repl);
+  return ret;
+}
+#endif
-- 
2.17.2

On Thu, Nov 29, 2018 at 11:21:27AM -0600, Eric Blake
wrote:
> Our use of "%m" in various error messages is testament to the
> project's initial life on Linux - but other than Cygwin, I know
> of no other platforms supporting that glibc extension.
> 
> We COULD audit the code and manually turn "%m" into
> "%s"/strerror(errno), but that's a lot of churn. Instead,
let's
> fix the few outliers that can't be easily wrapped, then wrap
> the remainder.
> 
> While I was able to test this on Linux (both that no wrapper is
> used by default, and that faking that %m fails causes the wrapper
> to do the right thing), I haven't actually tried it on a BSD box,
> hence I'll wait for review before pushing.
I tested these on FreeBSD 11.2:

  checking whether the printf family supports %m... no

and then:

  $ ./nbdkit file /dev/pci -f -v

(where /dev/pci is unreadable by non-root).  When accessing this
device I see errors like:

  nbdkit: debug: accepted connection
  nbdkit: debug: file: open readonly=0
  nbdkit: error: open: /dev/pci: Permission denied

which I believe are evidence that the %m formatter is being expanded
correctly in plugins/file/file.c.

Also without your patches I see:

  nbdkit: error: open: /dev/pci: m

I checked the patches themselves and they look fine too so:

  ACK series

Thanks,

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into KVM guests.
http://libguestfs.org/virt-v2v

On 11/29/18 11:21 AM, Eric Blake wrote:
> Our use of "%m" in various error messages is testament to the
> project's initial life on Linux - but other than Cygwin, I know
> of no other platforms supporting that glibc extension.
> 
> We COULD audit the code and manually turn "%m" into
> "%s"/strerror(errno), but that's a lot of churn. Instead,
let's
> fix the few outliers that can't be easily wrapped, then wrap
> the remainder.
> 
> While I was able to test this on Linux (both that no wrapper is
> used by default, and that faking that %m fails causes the wrapper
> to do the right thing), I haven't actually tried it on a BSD box,
> hence I'll wait for review before pushing.
Not fixed here, but still worth doing:

Audit and fix all our uses of nbdkit_error("...\n") to drop their 
trailing newline, as nbdkit_error() adds one.  Then update 
nbdkit_error() to actually do smart newline appending (borrowing from 
commit ef4f72ef) so that other callers outside our codebase get smart 
handling by default.

And on a tangent, I just filed a gcc bug about not flagging %m during 
some form of -Wformat:
https://gcc.gnu.org/bugzilla/show_bug.cgi?id=88270

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

On 11/29/18 12:07 PM, Eric Blake wrote:
> On 11/29/18 11:21 AM, Eric Blake wrote:
>> Our use of "%m" in various error messages is testament to the
>> project's initial life on Linux - but other than Cygwin, I know
>> of no other platforms supporting that glibc extension.
>>
>> We COULD audit the code and manually turn "%m" into
>> "%s"/strerror(errno), but that's a lot of churn. Instead,
let's
>> fix the few outliers that can't be easily wrapped, then wrap
>> the remainder.
>>
>> While I was able to test this on Linux (both that no wrapper is
>> used by default, and that faking that %m fails causes the wrapper
>> to do the right thing), I haven't actually tried it on a BSD box,
>> hence I'll wait for review before pushing.
> 
> Not fixed here, but still worth doing:
> 
> Audit and fix all our uses of nbdkit_error("...\n") to drop their
> trailing newline, as nbdkit_error() adds one.  Then update
> nbdkit_error() to actually do smart newline appending (borrowing from
> commit ef4f72ef) so that other callers outside our codebase get smart
> handling by default.
Also not fixed: strerror() is not threadsafe (at all) on FreeBSD. On
glibc, it is at least thread-safe for safe input values (that is, if
passed 0 or a value from <errno.h>, the resulting string has lifetime in
const storage, even if it is mmap'd to a localized translation; and thus
will not be corrupted by other threads' actions); but is not thread-safe
for arbitrary values (such as strerror(-1), where glibc malloc's space
shared between all threads for returning "Unknown error -1", and which
could get corrupted by a parallel thread doing strerror(-2)). But
FreeBSD shares static storage for strerror() results among all threads,
in part because it computes the resulting string via
catopen()/catgets()/catclose() and MUST copy the localized string
somewhere because the source read via catgets() may not survive catclose().

So we really need to audit all use of sterror() in nbdkit and switch
over to strerror_r(), remembering to work around the alternate glibc
signature when _GNU_SOURCE is defined.

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