[libvirt] [PATCH] Improve debugging of job enter/exit code

[Daniel P. Berrange]

From: "Daniel P. Berrange" <berrange at redhat.com>

In debugging a recent oVirt/libvirt race condition, I was very
frustrated by lack of logging in the job enter/exit code. This
patch adds some key data which would have been useful in by
debugging attempts.

Signed-off-by: Daniel P. Berrange <berrange at redhat.com>
---
 src/qemu/qemu_domain.c | 45 +++++++++++++++++++++++++++++++++++----------
 1 file changed, 35 insertions(+), 10 deletions(-)

diff --git a/src/qemu/qemu_domain.c b/src/qemu/qemu_domain.c
index b8aec2d..81d0ba9 100644
--- a/src/qemu/qemu_domain.c
+++ b/src/qemu/qemu_domain.c
@@ -1014,6 +1014,12 @@ qemuDomainObjBeginJobInternal(virQEMUDriverPtr driver,
     bool nested = job == QEMU_JOB_ASYNC_NESTED;
     virQEMUDriverConfigPtr cfg = virQEMUDriverGetConfig(driver);
 
+    VIR_DEBUG("Starting %s: %s (async=%s vm=%p name=%s)",
+              job == QEMU_JOB_ASYNC ? "async job" : "job",
+              qemuDomainJobTypeToString(job),
+              qemuDomainAsyncJobTypeToString(priv->job.asyncJob),
+              obj, obj->def->name);
+
     priv->jobs_queued++;
 
     if (virTimeMillisNow(&now) < 0) {
@@ -1032,11 +1038,13 @@ retry:
     }
 
     while (!nested && !qemuDomainNestedJobAllowed(priv, job)) {
+        VIR_DEBUG("Waiting for async job (vm=%p name=%s)", obj, obj->def->name);
         if (virCondWaitUntil(&priv->job.asyncCond, &obj->parent.lock, then) < 0)
             goto error;
     }
 
     while (priv->job.active) {
+        VIR_DEBUG("Waiting for job (vm=%p name=%s)", obj, obj->def->name);
         if (virCondWaitUntil(&priv->job.cond, &obj->parent.lock, then) < 0)
             goto error;
     }
@@ -1049,14 +1057,16 @@ retry:
     qemuDomainObjResetJob(priv);
 
     if (job != QEMU_JOB_ASYNC) {
-        VIR_DEBUG("Starting job: %s (async=%s)",
+        VIR_DEBUG("Started job: %s (async=%s vm=%p name=%s)",
                    qemuDomainJobTypeToString(job),
-                   qemuDomainAsyncJobTypeToString(priv->job.asyncJob));
+                  qemuDomainAsyncJobTypeToString(priv->job.asyncJob),
+                  obj, obj->def->name);
         priv->job.active = job;
         priv->job.owner = virThreadSelfID();
     } else {
-        VIR_DEBUG("Starting async job: %s",
-                  qemuDomainAsyncJobTypeToString(asyncJob));
+        VIR_DEBUG("Started async job: %s (vm=%p name=%s)",
+                  qemuDomainAsyncJobTypeToString(asyncJob),
+                  obj, obj->def->name);
         qemuDomainObjResetAsyncJob(priv);
         priv->job.asyncJob = asyncJob;
         priv->job.asyncOwner = virThreadSelfID();
@@ -1161,9 +1171,10 @@ bool qemuDomainObjEndJob(virQEMUDriverPtr driver, virDomainObjPtr obj)
 
     priv->jobs_queued--;
 
-    VIR_DEBUG("Stopping job: %s (async=%s)",
+    VIR_DEBUG("Stopping job: %s (async=%s vm=%p name=%s)",
               qemuDomainJobTypeToString(job),
-              qemuDomainAsyncJobTypeToString(priv->job.asyncJob));
+              qemuDomainAsyncJobTypeToString(priv->job.asyncJob),
+              obj, obj->def->name);
 
     qemuDomainObjResetJob(priv);
     if (qemuDomainTrackJob(job))
@@ -1180,8 +1191,9 @@ qemuDomainObjEndAsyncJob(virQEMUDriverPtr driver, virDomainObjPtr obj)
 
     priv->jobs_queued--;
 
-    VIR_DEBUG("Stopping async job: %s",
-              qemuDomainAsyncJobTypeToString(priv->job.asyncJob));
+    VIR_DEBUG("Stopping async job: %s (vm=%p name=%s)",
+              qemuDomainAsyncJobTypeToString(priv->job.asyncJob),
+              obj, obj->def->name);
 
     qemuDomainObjResetAsyncJob(priv);
     qemuDomainObjSaveJob(driver, obj);
@@ -1195,8 +1207,9 @@ qemuDomainObjAbortAsyncJob(virDomainObjPtr obj)
 {
     qemuDomainObjPrivatePtr priv = obj->privateData;
 
-    VIR_DEBUG("Requesting abort of async job: %s",
-              qemuDomainAsyncJobTypeToString(priv->job.asyncJob));
+    VIR_DEBUG("Requesting abort of async job: %s (vm=%p name=%s)",
+              qemuDomainAsyncJobTypeToString(priv->job.asyncJob),
+              obj, obj->def->name);
 
     priv->job.asyncAbort = true;
 }
@@ -1232,6 +1245,8 @@ qemuDomainObjEnterMonitorInternal(virQEMUDriverPtr driver,
                  " monitor without asking for a nested job is dangerous");
     }
 
+    VIR_DEBUG("Entering monitor (mon=%p vm=%p name=%s)",
+              priv->mon, obj, obj->def->name);
     virObjectLock(priv->mon);
     virObjectRef(priv->mon);
     ignore_value(virTimeMillisNow(&priv->monStart));
@@ -1253,6 +1268,8 @@ qemuDomainObjExitMonitorInternal(virQEMUDriverPtr driver,
         virObjectUnlock(priv->mon);
 
     virObjectLock(obj);
+    VIR_DEBUG("Exited monitor (mon=%p vm=%p name=%s)",
+              priv->mon, obj, obj->def->name);
 
     priv->monStart = 0;
     if (!hasRefs)
@@ -1321,6 +1338,8 @@ qemuDomainObjEnterAgent(virDomainObjPtr obj)
 {
     qemuDomainObjPrivatePtr priv = obj->privateData;
 
+    VIR_DEBUG("Entering agent (agent=%p vm=%p name=%s)",
+              priv->agent, obj, obj->def->name);
     virObjectLock(priv->agent);
     virObjectRef(priv->agent);
     ignore_value(virTimeMillisNow(&priv->agentStart));
@@ -1344,6 +1363,8 @@ qemuDomainObjExitAgent(virDomainObjPtr obj)
         virObjectUnlock(priv->agent);
 
     virObjectLock(obj);
+    VIR_DEBUG("Exited agent (agent=%p vm=%p name=%s)",
+              priv->agent, obj, obj->def->name);
 
     priv->agentStart = 0;
     if (!hasRefs)
@@ -1352,6 +1373,8 @@ qemuDomainObjExitAgent(virDomainObjPtr obj)
 
 void qemuDomainObjEnterRemote(virDomainObjPtr obj)
 {
+    VIR_DEBUG("Entering remote (vm=%p name=%s)",
+              obj, obj->def->name);
     virObjectRef(obj);
     virObjectUnlock(obj);
 }
@@ -1359,6 +1382,8 @@ void qemuDomainObjEnterRemote(virDomainObjPtr obj)
 void qemuDomainObjExitRemote(virDomainObjPtr obj)
 {
     virObjectLock(obj);
+    VIR_DEBUG("Exited remote (vm=%p name=%s)",
+              obj, obj->def->name);
     virObjectUnref(obj);
 }
 
-- 
1.8.3.1