[PATCH v2 0/4] libxl: events: debugging output

[PATCH v2 0/4] libxl: events: debugging output

[Ian Jackson]

I was using these to help with debugging the libxl event code.

Changes since v1: Made many of these less spammy.

 1/4 libxl: events: debugging output for timeouts
 2/4 libxl: events: improve debugging output for xs watches
 3/4 libxl: events: debugging output for fds
 4/4 libxl: events: debugging output relating to ao's

[PATCH 1/4] libxl: events: debugging output for timeouts

[Ian Jackson]

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output only occurs if you compile with -DDEBUG=1
---
 tools/libxl/libxl_event.c |   43 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 43 insertions(+), 0 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 7fbd5c3..c095f14 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -19,6 +19,18 @@
 
 #include "libxl_internal.h"
 
+
+//#define DEBUG 1
+
+#ifdef DEBUG
+# define LIBXL__DBG_LOG(ctx, args, ...) \
+    LIBXL__LOG((ctx), XTL_DEBUG, args, __VA_ARGS__)
+#else
+# define LIBXL__DBG_LOG(ctx, args, ...) ((void)0)
+#endif
+#define DBG(args, ...) LIBXL__DBG_LOG(CTX, args, __VA_ARGS__)
+
+
 /*
  * The counter osevent_in_hook is used to ensure that the application
  * honours the reentrancy restriction documented in libxl_event.h.
@@ -169,6 +181,16 @@ static void time_deregister(libxl__gc *gc, libxl__ev_time *ev)
     }
 }
 
+static void time_done_debug(libxl__gc *gc, const char *func,
+                            libxl__ev_time *ev, int rc)
+{
+#ifdef DEBUG
+    libxl__log(CTX, XTL_DEBUG, -1,__FILE__,0,func,
+               "ev_time=%p done rc=%d .func=%p infinite=%d abs=%lu.%06lu",
+               ev, rc, ev->func, ev->infinite,
+               (unsigned long)ev->abs.tv_sec, (unsigned long)ev->abs.tv_usec);
+#endif
+}
 
 int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
                                 libxl__ev_time_callback *func,
@@ -178,6 +200,9 @@ int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p register abs=%lu.%06lu",
+        ev, (unsigned long)abs.tv_sec, (unsigned long)abs.tv_usec);
+
     rc = time_register_finite(gc, ev, abs);
     if (rc) goto out;
 
@@ -185,6 +210,7 @@ int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -199,6 +225,8 @@ int libxl__ev_time_register_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p register ms=%d", ev, milliseconds);
+
     if (milliseconds < 0) {
         ev->infinite = 1;
     } else {
@@ -213,6 +241,7 @@ int libxl__ev_time_register_rel(libxl__gc *gc, libxl__ev_time *ev,
     rc = 0;
 
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -224,6 +253,9 @@ int libxl__ev_time_modify_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p modify abs==%lu.%06lu",
+        ev, (unsigned long)abs.tv_sec, (unsigned long)abs.tv_usec);
+
     assert(libxl__ev_time_isregistered(ev));
 
     if (ev->infinite) {
@@ -240,6 +272,7 @@ int libxl__ev_time_modify_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -252,6 +285,8 @@ int libxl__ev_time_modify_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p modify ms=%d", ev, milliseconds);
+
     assert(libxl__ev_time_isregistered(ev));
 
     if (milliseconds < 0) {
@@ -269,6 +304,7 @@ int libxl__ev_time_modify_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -277,6 +313,8 @@ void libxl__ev_time_deregister(libxl__gc *gc, libxl__ev_time *ev)
 {
     CTX_LOCK;
 
+    DBG("ev_time=%p deregister", ev);
+
     if (!libxl__ev_time_isregistered(ev))
         goto out;
 
@@ -284,6 +322,7 @@ void libxl__ev_time_deregister(libxl__gc *gc, libxl__ev_time *ev)
     ev->func = 0;
 
  out:
+    time_done_debug(gc,__func__,ev,0);
     CTX_UNLOCK;
     return;
 }
@@ -856,6 +895,10 @@ static void afterpoll_internal(libxl__egc *egc, libxl__poller *poller,
 
         time_deregister(gc, etime);
 
+        DBG("ev_time=%p occurs abs=%lu.%06lu",
+            etime, (unsigned long)etime->abs.tv_sec,
+            (unsigned long)etime->abs.tv_usec);
+
         etime->func(egc, etime, &etime->abs);
     }
 }
-- 
1.7.2.5

[PATCH 2/4] libxl: events: improve debugging output for xs watches

[Ian Jackson]

* Add debugging output for register/deregister.
* Make the debugging printfs consistent about the order in which they
  print the information.
* Where we touch the code, change LIBXL__LOG to LOG.

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>
---
 tools/libxl/libxl_event.c |   29 ++++++++++++++++++-----------
 1 files changed, 18 insertions(+), 11 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index c095f14..8d6fec8 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -420,9 +420,8 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
         }
 
         if (w->counterval != counterval) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: counter != %"PRIx32,
-                       epath, token, w->counterval);
+            LOG(DEBUG, "watch w=%p epath=%s token=%s: counter != %"PRIx32,
+                w, epath, token, w->counterval);
             goto ignore;
         }
 
@@ -440,16 +439,14 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
          * See also docs/misc/xenstore.txt.
          */
         if (!xs_path_is_subpath(w->path, epath)) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: not child of wpath=%s",
-                       epath, token, w->path);
+            LOG(DEBUG, "watch w=%p wpath=%s token=%s: unexpected epath=%s",
+                w, w->path, token, epath);
             goto ignore;
         }
 
         /* At last, we have checked everything! */
-        LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                   "watch event: epath=%s token=%s wpath=%s w=%p",
-                   epath, token, w->path, w);
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: event epath=%s",
+            w, w->path, token, epath);
         w->callback(egc, w, w->path, epath);
 
     ignore:
@@ -502,7 +499,11 @@ int libxl__ev_xswatch_register(libxl__gc *gc, libxl__ev_xswatch *w,
     int slotnum = use - CTX->watch_slots;
     w->counterval = CTX->watch_counter++;
 
-    if (!xs_watch(CTX->xsh, path, watch_token(gc, slotnum, w->counterval))) {
+    const char *token = watch_token(gc, slotnum, w->counterval);
+    LOG(DEBUG, "watch w=%p wpath=%s token=%s: register slotnum=%d",
+        w, path, token, slotnum);
+
+    if (!xs_watch(CTX->xsh, path, token)) {
         LIBXL__LOG_ERRNOVAL(CTX, LIBXL__LOG_ERROR, errno,
                             "create watch for path %s", path);
         rc = ERROR_FAIL;
@@ -534,7 +535,11 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
     CTX_LOCK;
 
     if (w->slotnum >= 0) {
-        char *token = watch_token(gc, w->slotnum, w->counterval);
+        const char *token = watch_token(gc, w->slotnum, w->counterval);
+
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: deregister slotnum=%d",
+            w, w->path, token, w->slotnum);
+
         if (!xs_unwatch(CTX->xsh, w->path, token))
             /* Oh well, we will just get watch events forever more
              * and ignore them.  But we should complain to the log. */
@@ -544,6 +549,8 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
         libxl__ev_watch_slot *slot = &CTX->watch_slots[w->slotnum];
         LIBXL_SLIST_INSERT_HEAD(&CTX->watch_freeslots, slot, empty);
         w->slotnum = -1;
+    } else {
+        LOG(DEBUG, "watch w=%p: deregister unregistered", w);
     }
 
     free(w->path);
-- 
1.7.2.5

[PATCH 3/4] libxl: events: debugging output for fds

[Ian Jackson]

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output only occurs if you compile with -DDEBUG=1
---
 tools/libxl/libxl_event.c |   15 +++++++++++++--
 1 files changed, 13 insertions(+), 2 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 8d6fec8..ed8ed5c 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -70,6 +70,8 @@ int libxl__ev_fd_register(libxl__gc *gc, libxl__ev_fd *ev,
 
     CTX_LOCK;
 
+    DBG("ev_fd=%p register fd=%d events=%x", ev, fd, events);
+
     rc = OSEVENT_HOOK(fd_register, fd, &ev->for_app_reg, events, ev);
     if (rc) goto out;
 
@@ -93,6 +95,8 @@ int libxl__ev_fd_modify(libxl__gc *gc, libxl__ev_fd *ev, short events)
     CTX_LOCK;
     assert(libxl__ev_fd_isregistered(ev));
 
+    DBG("ev_fd=%p modify fd=%d events=%x", ev, ev->fd, events);
+
     rc = OSEVENT_HOOK(fd_modify, ev->fd, &ev->for_app_reg, events);
     if (rc) goto out;
 
@@ -108,8 +112,12 @@ void libxl__ev_fd_deregister(libxl__gc *gc, libxl__ev_fd *ev)
 {
     CTX_LOCK;
 
-    if (!libxl__ev_fd_isregistered(ev))
+    if (!libxl__ev_fd_isregistered(ev)) {
+        DBG("ev_fd=%p deregister unregistered",ev);
         goto out;
+    }
+
+    DBG("ev_fd=%p deregister fd=%d", ev, ev->fd);
 
     OSEVENT_HOOK_VOID(fd_deregister, ev->fd, ev->for_app_reg);
     LIBXL_LIST_REMOVE(ev, entry);
@@ -873,8 +881,11 @@ static void afterpoll_internal(libxl__egc *egc, libxl__poller *poller,
             continue;
 
         int revents = afterpoll_check_fd(poller,fds,nfds, efd->fd,efd->events);
-        if (revents)
+        if (revents) {
+            DBG("ev_fd=%p occurs fd=%d events=%x revents=%x",
+                efd, efd->fd, efd->events, revents);
             efd->func(egc, efd, efd->fd, efd->events, revents);
+        }
     }
 
     if (afterpoll_check_fd(poller,fds,nfds, poller->wakeup_pipe[0],POLLIN)) {
-- 
1.7.2.5

[PATCH 4/4] libxl: events: debugging output relating to ao's

[Ian Jackson]

(In libxl__ao_complete_check_progress_reports, introduce libxl_ctx *ctx.)

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output in event loop only occurs if you compile with -DDEBUG=1;
   other new output remains.
 * Remove a mid-function use of AO_GC.  Instead, introduce a ctx
   variable and use that instead.
---
 tools/libxl/libxl_event.c    |   39 +++++++++++++++++++++++++++++++++++----
 tools/libxl/libxl_internal.h |   12 ++++++++----
 2 files changed, 43 insertions(+), 8 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index ed8ed5c..565d2c2 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -1020,11 +1020,14 @@ static void egc_run_callbacks(libxl__egc *egc)
 
     LIBXL_TAILQ_FOREACH_SAFE(ev, &egc->occurred_for_callback, link, ev_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->occurred_for_callback, ev, link);
+        LOG(DEBUG,"event %p callback type=%s",
+            ev, libxl_event_type_to_string(ev->type));
         CTX->event_hooks->event_occurs(CTX->event_hooks_user, ev);
     }
 
     LIBXL_TAILQ_FOREACH_SAFE(aop, &egc->aops_for_callback, entry, aop_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->aops_for_callback, aop, entry);
+        LOG(DEBUG,"ao %p: progress report: callback aop=%p", aop->ao, aop);
         aop->how->callback(CTX, aop->ev, aop->how->for_callback);
 
         CTX_LOCK;
@@ -1037,6 +1040,7 @@ static void egc_run_callbacks(libxl__egc *egc)
     LIBXL_TAILQ_FOREACH_SAFE(ao, &egc->aos_for_callback,
                              entry_for_callback, ao_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->aos_for_callback, ao, entry_for_callback);
+        LOG(DEBUG,"ao %p: completion callback", ao);
         ao->how.callback(CTX, ao->rc, ao->how.u.for_callback);
         CTX_LOCK;
         ao->notified = 1;
@@ -1396,7 +1400,9 @@ int libxl_event_wait(libxl_ctx *ctx, libxl_event **event_r,
 
 void libxl__ao__destroy(libxl_ctx *ctx, libxl__ao *ao)
 {
+    AO_GC;
     if (!ao) return;
+    LOG(DEBUG,"ao %p: destroy",ao);
     if (ao->poller) libxl__poller_put(ctx, ao->poller);
     ao->magic = LIBXL__AO_MAGIC_DESTROYED;
     libxl__free_all(&ao->gc);
@@ -1406,6 +1412,7 @@ void libxl__ao__destroy(libxl_ctx *ctx, libxl__ao *ao)
 void libxl__ao_abort(libxl__ao *ao)
 {
     AO_GC;
+    LOG(DEBUG,"ao %p: abort",ao);
     assert(ao->magic == LIBXL__AO_MAGIC);
     assert(ao->in_initiator);
     assert(!ao->complete);
@@ -1422,6 +1429,8 @@ libxl__gc *libxl__ao_inprogress_gc(libxl__ao *ao)
 
 void libxl__ao_complete(libxl__egc *egc, libxl__ao *ao, int rc)
 {
+    AO_GC;
+    LOG(DEBUG,"ao %p: complete, rc=%d",ao,rc);
     assert(ao->magic == LIBXL__AO_MAGIC);
     assert(!ao->complete);
     ao->complete = 1;
@@ -1439,7 +1448,7 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
      * will, after making the callback, take out the lock again,
      * decrement progress_reports_outstanding, and call us again.
      */
-
+    libxl_ctx *ctx = libxl__gc_owner(&egc->gc);
     assert(ao->progress_reports_outstanding >= 0);
 
     if (!ao->complete || ao->progress_reports_outstanding)
@@ -1451,6 +1460,7 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
             /* don't bother with this if we're not in the event loop */
             libxl__poller_wakeup(egc, ao->poller);
     } else if (ao->how.callback) {
+        LIBXL__LOG(ctx, XTL_DEBUG, "ao %p: complete for callback",ao);
         LIBXL_TAILQ_INSERT_TAIL(&egc->aos_for_callback, ao, entry_for_callback);
     } else {
         libxl_event *ev;
@@ -1463,11 +1473,12 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
         ao->notified = 1;
     }
     if (!ao->in_initiator && ao->notified)
-        libxl__ao__destroy(libxl__gc_owner(&egc->gc), ao);
+        libxl__ao__destroy(ctx, ao);
 }
 
 libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
-                            const libxl_asyncop_how *how)
+                            const libxl_asyncop_how *how,
+                            const char *file, int line, const char *func)
 {
     libxl__ao *ao;
 
@@ -1487,6 +1498,10 @@ libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
         ao->poller = libxl__poller_get(ctx);
         if (!ao->poller) goto out;
     }
+    libxl__log(ctx,XTL_DEBUG,-1,file,line,func,
+               "ao %p: create: how=%p callback=%p poller=%p",
+               ao, how, ao->how.callback, ao->poller);
+
     return ao;
 
  out:
@@ -1495,7 +1510,8 @@ libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
 }
 
 
-int libxl__ao_inprogress(libxl__ao *ao)
+int libxl__ao_inprogress(libxl__ao *ao,
+                         const char *file, int line, const char *func)
 {
     AO_GC;
     int rc;
@@ -1505,6 +1521,14 @@ int libxl__ao_inprogress(libxl__ao *ao)
     assert(ao->in_initiator);
     ao->constructing = 0;
 
+    libxl__log(CTX,XTL_DEBUG,-1,file,line,func,
+               "ao %p: inprogress: poller=%p, flags=%s%s%s%s",
+               ao, ao->poller,
+               ao->constructing ? "o" : "",
+               ao->in_initiator ? "i" : "",
+               ao->complete ? "c" : "",
+               ao->notified ? "n" : "");
+
     if (ao->poller) {
         /* Caller wants it done synchronously. */
         /* We use a fresh gc, so that we can free things
@@ -1521,6 +1545,8 @@ int libxl__ao_inprogress(libxl__ao *ao)
                 break;
             }
 
+            DBG("ao %p: not ready, waiting",ao);
+
             rc = eventloop_iteration(&egc,ao->poller);
             if (rc) {
                 /* Oh dear, this is quite unfortunate. */
@@ -1571,8 +1597,10 @@ void libxl__ao_progress_gethow(libxl_asyncprogress_how *in_state,
 void libxl__ao_progress_report(libxl__egc *egc, libxl__ao *ao,
         const libxl_asyncprogress_how *how, libxl_event *ev)
 {
+    AO_GC;
     ev->for_user = how->for_event;
     if (how->callback == dummy_asyncprogress_callback_ignore) {
+        LOG(DEBUG,"ao %p: progress report: ignored",ao);
         /* ignore */
     } else if (how->callback) {
         libxl__aop_occurred *aop = libxl__zalloc(&egc->gc, sizeof(*aop));
@@ -1581,7 +1609,10 @@ void libxl__ao_progress_report(libxl__egc *egc, libxl__ao *ao,
         aop->ev = ev;
         aop->how = how;
         LIBXL_TAILQ_INSERT_TAIL(&egc->aops_for_callback, aop, entry);
+        LOG(DEBUG,"ao %p: progress report: callback queued aop=%p",ao,aop);
     } else {
+        LOG(DEBUG,"ao %p: progress report: event queued ev=%p type=%s",
+            ao, ev, libxl_event_type_to_string(ev->type));
         libxl__event_occurred(egc, ev);
     }
 }
diff --git a/tools/libxl/libxl_internal.h b/tools/libxl/libxl_internal.h
index 49d01a8..0e084c1 100644
--- a/tools/libxl/libxl_internal.h
+++ b/tools/libxl/libxl_internal.h
@@ -1555,14 +1555,16 @@ _hidden void libxl__egc_cleanup(libxl__egc *egc);
 
 #define AO_CREATE(ctx, domid, ao_how)                           \
     libxl__ctx_lock(ctx);                                       \
-    libxl__ao *ao = libxl__ao_create(ctx, domid, ao_how);       \
+    libxl__ao *ao = libxl__ao_create(ctx, domid, ao_how,        \
+                               __FILE__, __LINE__, __func__);   \
     if (!ao) { libxl__ctx_unlock(ctx); return ERROR_NOMEM; }    \
     libxl__egc egc[1]; LIBXL_INIT_EGC(egc[0],ctx);              \
     AO_GC;
 
 #define AO_INPROGRESS ({                                        \
         libxl_ctx *ao__ctx = libxl__gc_owner(&ao->gc);          \
-        int ao__rc = libxl__ao_inprogress(ao);                  \
+        int ao__rc = libxl__ao_inprogress(ao,                   \
+                               __FILE__, __LINE__, __func__);   \
         libxl__ctx_unlock(ao__ctx); /* gc is now invalid */     \
         EGC_FREE;                                               \
         (ao__rc);                                               \
@@ -1588,8 +1590,10 @@ _hidden void libxl__egc_cleanup(libxl__egc *egc);
 /* All of these MUST be called with the ctx locked.
  * libxl__ao_inprogress MUST be called with the ctx locked exactly once. */
 _hidden libxl__ao *libxl__ao_create(libxl_ctx*, uint32_t domid,
-                                    const libxl_asyncop_how*);
-_hidden int libxl__ao_inprogress(libxl__ao *ao); /* temporarily unlocks */
+                                    const libxl_asyncop_how*,
+       const char *file, int line, const char *func);
+_hidden int libxl__ao_inprogress(libxl__ao *ao,
+       const char *file, int line, const char *func); /* temporarily unlocks */
 _hidden void libxl__ao_abort(libxl__ao *ao);
 _hidden void libxl__ao_complete(libxl__egc *egc, libxl__ao *ao, int rc);
 _hidden libxl__gc *libxl__ao_inprogress_gc(libxl__ao *ao);
-- 
1.7.2.5

Re: [PATCH v2 0/4] libxl: events: debugging output

[Ian Campbell]

On Fri, 2012-05-18 at 19:20 +0100, Ian Jackson wrote:
> I was using these to help with debugging the libxl event code.
> 
> Changes since v1: Made many of these less spammy.

I booted a pv guest with "xl -vvv cr -c" with pygrub and direct kernel
and it wasn't too spammy anymore. I've applied them all.

Thanks,
Ian.

> 
>  1/4 libxl: events: debugging output for timeouts
>  2/4 libxl: events: improve debugging output for xs watches
>  3/4 libxl: events: debugging output for fds
>  4/4 libxl: events: debugging output relating to ao's
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

libxl: events: debugging improvements

[Ian Jackson]

These four patches may help people who are working with the libxl
event machinery:

 1/4 libxl: events: debugging output for timeouts
 2/4 libxl: events: improve debugging output for xs watches
 3/4 libxl: events: debugging output for fds
 4/4 libxl: events: STATE_AO_GC checks ao is still valid

The first three are not intended to cause any change other than the
new debug messages.  The last one should simply cause erroneous code
to crash sooner.

[PATCH 2/4] libxl: events: improve debugging output for xs watches

[Ian Jackson]

* Add debugging output for register/deregister.
* Make the debugging printfs consistent about the order in which they
  print the information.
* Where we touch the code, change LIBXL__LOG to LOG.

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>
---
 tools/libxl/libxl_event.c |   29 ++++++++++++++++++-----------
 1 files changed, 18 insertions(+), 11 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 3956f00..4d31b3c 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -406,9 +406,8 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
         }
 
         if (w->counterval != counterval) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: counter != %"PRIx32,
-                       epath, token, w->counterval);
+            LOG(DEBUG, "watch w=%p epath=%s token=%s: counter != %"PRIx32,
+                w, epath, token, w->counterval);
             goto ignore;
         }
 
@@ -426,16 +425,14 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
          * See also docs/misc/xenstore.txt.
          */
         if (!xs_path_is_subpath(w->path, epath)) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: not child of wpath=%s",
-                       epath, token, w->path);
+            LOG(DEBUG, "watch w=%p wpath=%s token=%s: unexpected epath=%s",
+                w, w->path, token, epath);
             goto ignore;
         }
 
         /* At last, we have checked everything! */
-        LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                   "watch event: epath=%s token=%s wpath=%s w=%p",
-                   epath, token, w->path, w);
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: event epath=%s",
+            w, w->path, token, epath);
         w->callback(egc, w, w->path, epath);
 
     ignore:
@@ -488,7 +485,11 @@ int libxl__ev_xswatch_register(libxl__gc *gc, libxl__ev_xswatch *w,
     int slotnum = use - CTX->watch_slots;
     w->counterval = CTX->watch_counter++;
 
-    if (!xs_watch(CTX->xsh, path, watch_token(gc, slotnum, w->counterval))) {
+    const char *token = watch_token(gc, slotnum, w->counterval);
+    LOG(DEBUG, "watch w=%p wpath=%s token=%s: register slotnum=%d",
+        w, path, token, slotnum);
+
+    if (!xs_watch(CTX->xsh, path, token)) {
         LIBXL__LOG_ERRNOVAL(CTX, LIBXL__LOG_ERROR, errno,
                             "create watch for path %s", path);
         rc = ERROR_FAIL;
@@ -520,7 +521,11 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
     CTX_LOCK;
 
     if (w->slotnum >= 0) {
-        char *token = watch_token(gc, w->slotnum, w->counterval);
+        const char *token = watch_token(gc, w->slotnum, w->counterval);
+
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: deregister slotnum=%d",
+            w, w->path, token, w->slotnum);
+
         if (!xs_unwatch(CTX->xsh, w->path, token))
             /* Oh well, we will just get watch events forever more
              * and ignore them.  But we should complain to the log. */
@@ -530,6 +535,8 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
         libxl__ev_watch_slot *slot = &CTX->watch_slots[w->slotnum];
         LIBXL_SLIST_INSERT_HEAD(&CTX->watch_freeslots, slot, empty);
         w->slotnum = -1;
+    } else {
+        LOG(DEBUG, "watch w=%p: deregister unregistered", w);
     }
 
     free(w->path);
-- 
1.7.2.5