[libvirt PATCH 6/7] virMutex*: Warn on error

Tim Wiederhake posted 7 patches 4 years, 6 months ago
[libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Tim Wiederhake 4 years, 6 months ago
`pthread_mutex_destroy`, `pthread_mutex_lock` and `pthread_mutex_unlock`
return an error code that is currently ignored.

Add debug information if one of these operations failed, e.g. when there
is an attempt to destroy a still locked mutex or unlock and already
unlocked mutex.

Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
---
 src/util/virthread.c | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

diff --git a/src/util/virthread.c b/src/util/virthread.c
index e89c1a09fb..f64dbee9e9 100644
--- a/src/util/virthread.c
+++ b/src/util/virthread.c
@@ -35,7 +35,10 @@
 
 #include "viralloc.h"
 #include "virthreadjob.h"
+#include "virlog.h"
 
+#define VIR_FROM_THIS VIR_FROM_THREAD
+VIR_LOG_INIT("util.thread");
 
 int virOnce(virOnceControl *once, virOnceFunc init)
 {
@@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
 
 void virMutexDestroy(virMutex *m)
 {
-    pthread_mutex_destroy(&m->lock);
+    if (pthread_mutex_destroy(&m->lock)) {
+        VIR_WARN("Failed to destroy mutex=%p", m);
+    }
 }
 
 void virMutexLock(virMutex *m)
 {
-    pthread_mutex_lock(&m->lock);
+    if (pthread_mutex_lock(&m->lock)) {
+        VIR_WARN("Failed to lock mutex=%p", m);
+    }
 }
 
 void virMutexUnlock(virMutex *m)
 {
-    pthread_mutex_unlock(&m->lock);
+    if (pthread_mutex_unlock(&m->lock)) {
+        VIR_WARN("Failed to unlock mutex=%p", m);
+    }
 }
 
 
-- 
2.31.1

Re: [libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Daniel P. Berrangé 4 years, 6 months ago
On Thu, Aug 05, 2021 at 03:08:50PM +0200, Tim Wiederhake wrote:
> `pthread_mutex_destroy`, `pthread_mutex_lock` and `pthread_mutex_unlock`
> return an error code that is currently ignored.
> 
> Add debug information if one of these operations failed, e.g. when there
> is an attempt to destroy a still locked mutex or unlock and already
> unlocked mutex.

We ignore the errors because in practice we found impls don't return
any error code when using PTHREAD_MUTEX_NORMAL - it would require use
of PTHREAD_MUTEX_ERRORCHECK.

Did you actually see errors returned for real ?

> 
> Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
> ---
>  src/util/virthread.c | 15 ++++++++++++---
>  1 file changed, 12 insertions(+), 3 deletions(-)
> 
> diff --git a/src/util/virthread.c b/src/util/virthread.c
> index e89c1a09fb..f64dbee9e9 100644
> --- a/src/util/virthread.c
> +++ b/src/util/virthread.c
> @@ -35,7 +35,10 @@
>  
>  #include "viralloc.h"
>  #include "virthreadjob.h"
> +#include "virlog.h"
>  
> +#define VIR_FROM_THIS VIR_FROM_THREAD
> +VIR_LOG_INIT("util.thread");
>  
>  int virOnce(virOnceControl *once, virOnceFunc init)
>  {
> @@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
>  
>  void virMutexDestroy(virMutex *m)
>  {
> -    pthread_mutex_destroy(&m->lock);
> +    if (pthread_mutex_destroy(&m->lock)) {
> +        VIR_WARN("Failed to destroy mutex=%p", m);
> +    }
>  }
>  
>  void virMutexLock(virMutex *m)
>  {
> -    pthread_mutex_lock(&m->lock);
> +    if (pthread_mutex_lock(&m->lock)) {
> +        VIR_WARN("Failed to lock mutex=%p", m);
> +    }
>  }
>  
>  void virMutexUnlock(virMutex *m)
>  {
> -    pthread_mutex_unlock(&m->lock);
> +    if (pthread_mutex_unlock(&m->lock)) {
> +        VIR_WARN("Failed to unlock mutex=%p", m);
> +    }
>  }
>  
>  
> -- 
> 2.31.1
> 

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: [libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Tim Wiederhake 4 years, 6 months ago
On Thu, 2021-08-05 at 14:24 +0100, Daniel P. Berrangé wrote:
> On Thu, Aug 05, 2021 at 03:08:50PM +0200, Tim Wiederhake wrote:
> > `pthread_mutex_destroy`, `pthread_mutex_lock` and
> > `pthread_mutex_unlock`
> > return an error code that is currently ignored.
> > 
> > Add debug information if one of these operations failed, e.g. when
> > there
> > is an attempt to destroy a still locked mutex or unlock and already
> > unlocked mutex.
> 
> We ignore the errors because in practice we found impls don't return
> any error code when using PTHREAD_MUTEX_NORMAL - it would require use
> of PTHREAD_MUTEX_ERRORCHECK.
> 
> Did you actually see errors returned for real ?

Yes. Please note that I apprently copy-pasted the wrong link in the
cover letter. The pipeline for this series is correct
(https://gitlab.com/twiederh/libvirt/-/pipelines/348505233), the
pipeline for only patches 5, 6, 7 that demonstrate the non-zero return
values of pthread_mutex_{lock,unlock,destroy} is here:

https://gitlab.com/twiederh/libvirt/-/pipelines/348505770

Regards,
Tim

> 
> > Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
> > ---
> >  src/util/virthread.c | 15 ++++++++++++---
> >  1 file changed, 12 insertions(+), 3 deletions(-)
> > 
> > diff --git a/src/util/virthread.c b/src/util/virthread.c
> > index e89c1a09fb..f64dbee9e9 100644
> > --- a/src/util/virthread.c
> > +++ b/src/util/virthread.c
> > @@ -35,7 +35,10 @@
> >  
> >  #include "viralloc.h"
> >  #include "virthreadjob.h"
> > +#include "virlog.h"
> >  
> > +#define VIR_FROM_THIS VIR_FROM_THREAD
> > +VIR_LOG_INIT("util.thread");
> >  
> >  int virOnce(virOnceControl *once, virOnceFunc init)
> >  {
> > @@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
> >  
> >  void virMutexDestroy(virMutex *m)
> >  {
> > -    pthread_mutex_destroy(&m->lock);
> > +    if (pthread_mutex_destroy(&m->lock)) {
> > +        VIR_WARN("Failed to destroy mutex=%p", m);
> > +    }
> >  }
> >  
> >  void virMutexLock(virMutex *m)
> >  {
> > -    pthread_mutex_lock(&m->lock);
> > +    if (pthread_mutex_lock(&m->lock)) {
> > +        VIR_WARN("Failed to lock mutex=%p", m);
> > +    }
> >  }
> >  
> >  void virMutexUnlock(virMutex *m)
> >  {
> > -    pthread_mutex_unlock(&m->lock);
> > +    if (pthread_mutex_unlock(&m->lock)) {
> > +        VIR_WARN("Failed to unlock mutex=%p", m);
> > +    }
> >  }
> >  
> >  
> > -- 
> > 2.31.1
> > 
> 
> Regards,
> Daniel


Re: [libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Daniel P. Berrangé 4 years, 6 months ago
On Thu, Aug 05, 2021 at 03:33:57PM +0200, Tim Wiederhake wrote:
> On Thu, 2021-08-05 at 14:24 +0100, Daniel P. Berrangé wrote:
> > On Thu, Aug 05, 2021 at 03:08:50PM +0200, Tim Wiederhake wrote:
> > > `pthread_mutex_destroy`, `pthread_mutex_lock` and
> > > `pthread_mutex_unlock`
> > > return an error code that is currently ignored.
> > > 
> > > Add debug information if one of these operations failed, e.g. when
> > > there
> > > is an attempt to destroy a still locked mutex or unlock and already
> > > unlocked mutex.
> > 
> > We ignore the errors because in practice we found impls don't return
> > any error code when using PTHREAD_MUTEX_NORMAL - it would require use
> > of PTHREAD_MUTEX_ERRORCHECK.
> > 
> > Did you actually see errors returned for real ?
> 
> Yes. Please note that I apprently copy-pasted the wrong link in the
> cover letter. The pipeline for this series is correct
> (https://gitlab.com/twiederh/libvirt/-/pipelines/348505233), the
> pipeline for only patches 5, 6, 7 that demonstrate the non-zero return
> values of pthread_mutex_{lock,unlock,destroy} is here:
> 
> https://gitlab.com/twiederh/libvirt/-/pipelines/348505770

All that's showing is

  (killed by signal 6 SIGABRT)

where's the VIR_WARN output that ought to have ended up on stderr
from the failed test before aborting ?


> > > Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
> > > ---
> > >  src/util/virthread.c | 15 ++++++++++++---
> > >  1 file changed, 12 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/src/util/virthread.c b/src/util/virthread.c
> > > index e89c1a09fb..f64dbee9e9 100644
> > > --- a/src/util/virthread.c
> > > +++ b/src/util/virthread.c
> > > @@ -35,7 +35,10 @@
> > >  
> > >  #include "viralloc.h"
> > >  #include "virthreadjob.h"
> > > +#include "virlog.h"
> > >  
> > > +#define VIR_FROM_THIS VIR_FROM_THREAD
> > > +VIR_LOG_INIT("util.thread");
> > >  
> > >  int virOnce(virOnceControl *once, virOnceFunc init)
> > >  {
> > > @@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
> > >  
> > >  void virMutexDestroy(virMutex *m)
> > >  {
> > > -    pthread_mutex_destroy(&m->lock);
> > > +    if (pthread_mutex_destroy(&m->lock)) {
> > > +        VIR_WARN("Failed to destroy mutex=%p", m);
> > > +    }
> > >  }
> > >  
> > >  void virMutexLock(virMutex *m)
> > >  {
> > > -    pthread_mutex_lock(&m->lock);
> > > +    if (pthread_mutex_lock(&m->lock)) {
> > > +        VIR_WARN("Failed to lock mutex=%p", m);
> > > +    }
> > >  }
> > >  
> > >  void virMutexUnlock(virMutex *m)
> > >  {
> > > -    pthread_mutex_unlock(&m->lock);
> > > +    if (pthread_mutex_unlock(&m->lock)) {
> > > +        VIR_WARN("Failed to unlock mutex=%p", m);
> > > +    }
> > >  }
> > >  
> > >  
> > > -- 
> > > 2.31.1
> > > 
> > 
> > Regards,
> > Daniel
> 
> 

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: [libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Peter Krempa 4 years, 6 months ago
On Thu, Aug 05, 2021 at 15:08:50 +0200, Tim Wiederhake wrote:
> `pthread_mutex_destroy`, `pthread_mutex_lock` and `pthread_mutex_unlock`
> return an error code that is currently ignored.
> 
> Add debug information if one of these operations failed, e.g. when there
> is an attempt to destroy a still locked mutex or unlock and already
> unlocked mutex.
> 
> Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
> ---
>  src/util/virthread.c | 15 ++++++++++++---
>  1 file changed, 12 insertions(+), 3 deletions(-)
> 
> diff --git a/src/util/virthread.c b/src/util/virthread.c
> index e89c1a09fb..f64dbee9e9 100644
> --- a/src/util/virthread.c
> +++ b/src/util/virthread.c
> @@ -35,7 +35,10 @@
>  
>  #include "viralloc.h"
>  #include "virthreadjob.h"
> +#include "virlog.h"
>  
> +#define VIR_FROM_THIS VIR_FROM_THREAD
> +VIR_LOG_INIT("util.thread");
>  
>  int virOnce(virOnceControl *once, virOnceFunc init)
>  {
> @@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
>  
>  void virMutexDestroy(virMutex *m)
>  {
> -    pthread_mutex_destroy(&m->lock);
> +    if (pthread_mutex_destroy(&m->lock)) {
> +        VIR_WARN("Failed to destroy mutex=%p", m);
> +    }
>  }
>  
>  void virMutexLock(virMutex *m)
>  {
> -    pthread_mutex_lock(&m->lock);
> +    if (pthread_mutex_lock(&m->lock)) {
> +        VIR_WARN("Failed to lock mutex=%p", m);
> +    }
>  }
>  
>  void virMutexUnlock(virMutex *m)
>  {
> -    pthread_mutex_unlock(&m->lock);
> +    if (pthread_mutex_unlock(&m->lock)) {
> +        VIR_WARN("Failed to unlock mutex=%p", m);
> +    }
>  }

I'm not very persuaded that this is a good idea:

1) The warning itself is not useful

  The pointer itself is valid only when the program is running, having
  this in the logs has almost no value.

2) It spams logs

  As noted above, by getting just the log you don't get any useful
  information and users tend to report that log is being spammed in
  certain cases, so while this would note that there is something going
  on a lot of additional work is required to figure out what, thus the
  value of such entry is rather low.

3) It can create an endless loop

  VIR_WARN -> VIR_WARN_INT -> virLogMessage -> virLogVMessage ->
  virLogLock -> virMutexLock()

Re: [libvirt PATCH 6/7] virMutex*: Warn on error
Posted by Daniel P. Berrangé 4 years, 6 months ago
On Thu, Aug 05, 2021 at 03:43:11PM +0200, Peter Krempa wrote:
> On Thu, Aug 05, 2021 at 15:08:50 +0200, Tim Wiederhake wrote:
> > `pthread_mutex_destroy`, `pthread_mutex_lock` and `pthread_mutex_unlock`
> > return an error code that is currently ignored.
> > 
> > Add debug information if one of these operations failed, e.g. when there
> > is an attempt to destroy a still locked mutex or unlock and already
> > unlocked mutex.
> > 
> > Signed-off-by: Tim Wiederhake <twiederh@redhat.com>
> > ---
> >  src/util/virthread.c | 15 ++++++++++++---
> >  1 file changed, 12 insertions(+), 3 deletions(-)
> > 
> > diff --git a/src/util/virthread.c b/src/util/virthread.c
> > index e89c1a09fb..f64dbee9e9 100644
> > --- a/src/util/virthread.c
> > +++ b/src/util/virthread.c
> > @@ -35,7 +35,10 @@
> >  
> >  #include "viralloc.h"
> >  #include "virthreadjob.h"
> > +#include "virlog.h"
> >  
> > +#define VIR_FROM_THIS VIR_FROM_THREAD
> > +VIR_LOG_INIT("util.thread");
> >  
> >  int virOnce(virOnceControl *once, virOnceFunc init)
> >  {
> > @@ -83,17 +86,23 @@ int virMutexInitRecursive(virMutex *m)
> >  
> >  void virMutexDestroy(virMutex *m)
> >  {
> > -    pthread_mutex_destroy(&m->lock);
> > +    if (pthread_mutex_destroy(&m->lock)) {
> > +        VIR_WARN("Failed to destroy mutex=%p", m);
> > +    }
> >  }
> >  
> >  void virMutexLock(virMutex *m)
> >  {
> > -    pthread_mutex_lock(&m->lock);
> > +    if (pthread_mutex_lock(&m->lock)) {
> > +        VIR_WARN("Failed to lock mutex=%p", m);
> > +    }
> >  }
> >  
> >  void virMutexUnlock(virMutex *m)
> >  {
> > -    pthread_mutex_unlock(&m->lock);
> > +    if (pthread_mutex_unlock(&m->lock)) {
> > +        VIR_WARN("Failed to unlock mutex=%p", m);
> > +    }
> >  }
> 
> I'm not very persuaded that this is a good idea:
> 
> 1) The warning itself is not useful
> 
>   The pointer itself is valid only when the program is running, having
>   this in the logs has almost no value.
> 
> 2) It spams logs
> 
>   As noted above, by getting just the log you don't get any useful
>   information and users tend to report that log is being spammed in
>   certain cases, so while this would note that there is something going
>   on a lot of additional work is required to figure out what, thus the
>   value of such entry is rather low.
> 
> 3) It can create an endless loop
> 
>   VIR_WARN -> VIR_WARN_INT -> virLogMessage -> virLogVMessage ->
>   virLogLock -> virMutexLock()

I think we could use perror() to make it more useful and avoid
the loop
 
 void virMutexDestroy(virMutex *m)
 {
    if ((errno = pthread_mutex_destroy(&m->lock)) != 0) {
        perror("pthread_mutex_destroy");
     }
 }

still not going to be enough to diagnose the problem fro the
logs though, as we have no use context.

This change would give a bit more of a fighting chance at diagnosis:

in virthread.h

#define virMutexDestroy(m) \
    virMutexDestroyImpl(m, __FILE__, __func__, __LINE__)
void virMutexDestroyImpl(virMutex *mm, const char *file, const char *func, int line);

and in virthread.c

 
void virMutexDestroyImpl(virMutex *m, const char *file, const char *func, int line)
 {
    if ((errno = pthread_mutex_destroy(&m->lock)) != 0) {
                g_autofree char *msg = g_strdup_printf("pthread_mutex_destroy (caller %s in %s:%d)",
                                                       func, file, line);
        perror(msg);
     }
 }


That results in:

$ ./build/tests/qemusecuritytest
TEST: qemusecuritytest
      pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy
!pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy
!pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy
!pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy
!pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy
!pthread_mutex_destroy (caller virObjectLockableDispose in ../src/util/virobject.c:349): Device or resource busy

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