Index: trunk/src/VBox/HostDrivers/Support/SUPDRVShared.c
===================================================================
--- trunk/src/VBox/HostDrivers/Support/SUPDRVShared.c	(revision 7011)
+++ trunk/src/VBox/HostDrivers/Support/SUPDRVShared.c	(revision 7014)
@@ -39,4 +39,18 @@
 #include <iprt/process.h>
 #include <iprt/log.h>
+
+/*
+ * Logging assignments:
+ *      Log     - useful stuff, like failures.
+ *      LogFlow - program flow, except the really noisy bits.
+ *      Log2    - Cleanup and IDTE
+ *      Log3    - Loader flow noise.
+ *      Log4    - Call VMMR0 flow noise.
+ *      Log5    - Native yet-to-be-defined noise.
+ *      Log6    - Native ioctl flow noise.
+ *
+ * Logging requires BUILD_TYPE=debug and possibly changes to the logger
+ * instanciation in log-vbox.c(pp).
+ */
 
 
@@ -461,4 +475,6 @@
                 RTSpinlockRelease(pDevExt->Spinlock, &SpinlockTmp);
 
+                Log(("supdrvCleanupSession: destroying %p/%d (%p/%p) cpid=%RTproc pid=%RTproc dtor=%p\n",
+                     pObj, pObj->enmType, pObj->pvUser1, pObj->pvUser2, pObj->CreatorProcess, RTProcSelf(), pObj->pfnDestructor));
                 if (pObj->pfnDestructor)
                     pObj->pfnDestructor(pObj, pObj->pvUser1, pObj->pvUser2);
@@ -951,4 +967,7 @@
             /* validate */
             PSUPCALLVMMR0 pReq = (PSUPCALLVMMR0)pReqHdr;
+            Log4(("SUP_IOCTL_CALL_VMMR0: op=%u in=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
+                  pReq->u.In.uOperation, pReq->Hdr.cbIn, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
+
             if (pReq->Hdr.cbIn == SUP_IOCTL_CALL_VMMR0_SIZE(0))
             {
@@ -975,4 +994,13 @@
                     pReq->Hdr.rc = VERR_WRONG_ORDER;
             }
+
+            if (    RT_FAILURE(pReq->Hdr.rc)
+                &&  pReq->Hdr.rc != VERR_INTERRUPTED
+                &&  pReq->Hdr.rc != VERR_TIMEOUT)
+                Log(("SUP_IOCTL_CALL_VMMR0: rc=%Rrc op=%u out=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
+                     pReq->Hdr.rc, pReq->u.In.uOperation, pReq->Hdr.cbOut, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
+            else
+                Log4(("SUP_IOCTL_CALL_VMMR0: rc=%Rrc op=%u out=%u arg=%RX64 p/t=%RTproc/%RTthrd\n",
+                      pReq->Hdr.rc, pReq->u.In.uOperation, pReq->Hdr.cbOut, pReq->u.In.u64Arg, RTProcSelf(), RTThreadNativeSelf()));
             return 0;
         }
@@ -1320,4 +1348,5 @@
                      * Object is to be destroyed, unlink it.
                      */
+                    pObj->u32Magic = SUPDRVOBJ_MAGIC + 1;
                     fDestroy = true;
                     if (pDevExt->pObjs == pObj)
@@ -1347,5 +1376,6 @@
     if (fDestroy)
     {
-        pObj->u32Magic++;
+        Log(("SUPR0ObjRelease: destroying %p/%d (%p/%p) cpid=%RTproc pid=%RTproc dtor=%p\n",
+             pObj, pObj->enmType, pObj->pvUser1, pObj->pvUser2, pObj->CreatorProcess, RTProcSelf(), pObj->pfnDestructor));
         if (pObj->pfnDestructor)
             pObj->pfnDestructor(pObj, pObj->pvUser1, pObj->pvUser2);
@@ -3244,4 +3274,6 @@
                 pImage->cUsage--;
         }
+        else
+            Log(("supdrvIOCtl_LdrFree: Dangling objects in %p/%s!\n", pImage->pvImage, pImage->szName));
     }
     else
Index: trunk/src/VBox/HostDrivers/Support/linux/SUPDrv-linux.c
===================================================================
--- trunk/src/VBox/HostDrivers/Support/linux/SUPDrv-linux.c	(revision 7011)
+++ trunk/src/VBox/HostDrivers/Support/linux/SUPDrv-linux.c	(revision 7014)
@@ -40,4 +40,5 @@
 #include <iprt/err.h>
 #include <iprt/mem.h>
+#include <iprt/log.h>
 
 #include <linux/sched.h>
@@ -687,5 +688,5 @@
                            ".\n",
                            g_DevExt.pGip->u32Mode == SUPGIPMODE_SYNC_TSC ? "'synchronous'" : "'asynchronous'");
-                    dprintf(("VBoxDrv::ModuleInit returning %#x\n", rc));
+                    LogFlow(("VBoxDrv::ModuleInit returning %#x\n", rc));
                     printk(KERN_DEBUG DEVICE_NAME ": Successfully loaded version "
                            VBOX_VERSION_STRING " (interface " xstr(SUPDRVIOC_VERSION) ").\n");
@@ -739,14 +740,14 @@
     }
 #else  /* !CONFIG_VBOXDRV_AS_MISC */
-#ifdef CONFIG_DEVFS_FS
+# ifdef CONFIG_DEVFS_FS
     /*
      * Unregister a device entry
      */
     VBOX_UNREGISTER_DEVFS(g_hDevFsVBoxDrv);
-#endif // devfs
+# endif /* devfs */
     rc = VBOX_UNREGISTER_DEVICE(g_iModuleMajor, DEVICE_NAME);
     if (rc < 0)
     {
-        dprintf(("unregister_chrdev failed with rc=%#x (major:%d)\n", rc, g_iModuleMajor));
+        dprintf(("VBOX_UNREGISTER_DEVICE failed with rc=%#x (major:%d)\n", rc, g_iModuleMajor));
     }
 #endif /* !CONFIG_VBOXDRV_AS_MISC */
@@ -771,5 +772,5 @@
     int                 rc;
     PSUPDRVSESSION      pSession;
-    dprintf(("VBoxDrvLinuxCreate: pFilp=%p\n", pFilp));
+    Log(("VBoxDrvLinuxCreate: pFilp=%p pid=%d/%d %s\n", pFilp, RTProcSelf(), current->pid, current->comm));
 
     /*
@@ -785,7 +786,9 @@
     }
 
-    dprintf(("VBoxDrvLinuxCreate: g_DevExt=%p pSession=%p rc=%d\n", &g_DevExt, pSession, rc));
     pFilp->private_data = pSession;
 
+    Log(("VBoxDrvLinuxCreate: g_DevExt=%p pSession=%p rc=%d/%d (pid=%d/%d %s)\n",
+         &g_DevExt, pSession, rc, VBoxDrvLinuxErr2LinuxErr(rc),
+         RTProcSelf(), current->pid, current->comm));
     return VBoxDrvLinuxErr2LinuxErr(rc);
 }
@@ -800,5 +803,6 @@
 static int VBoxDrvLinuxClose(struct inode *pInode, struct file *pFilp)
 {
-    dprintf(("VBoxDrvLinuxClose: pFilp=%p private_data=%p\n", pFilp, pFilp->private_data));
+    Log(("VBoxDrvLinuxClose: pFilp=%p pSession=%p pid=%d/%d %s\n",
+         pFilp, pFilp->private_data, RTProcSelf(), current->pid, current->comm));
     supdrvCloseSession(&g_DevExt, (PSUPDRVSESSION)pFilp->private_data);
     pFilp->private_data = NULL;
@@ -861,5 +865,5 @@
     uint32_t            cbBuf;
 
-    dprintf2(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p\n", pFilp, uCmd, (void *)ulArg));
+    Log6(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p pid=%d/%d\n", pFilp, uCmd, (void *)ulArg, RTProcSelf(), current->pid));
 
     /*
@@ -868,10 +872,10 @@
     if (RT_UNLIKELY(copy_from_user(&Hdr, (void *)ulArg, sizeof(Hdr))))
     {
-        dprintf(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx,) failed; uCmd=%#x.\n", ulArg, uCmd));
+        Log(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx,) failed; uCmd=%#x.\n", ulArg, uCmd));
         return -EFAULT;
     }
     if (RT_UNLIKELY((Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK) != SUPREQHDR_FLAGS_MAGIC))
     {
-        dprintf(("VBoxDrvLinuxIOCtl: bad header magic %#x; uCmd=%#x\n", Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK, uCmd));
+        Log(("VBoxDrvLinuxIOCtl: bad header magic %#x; uCmd=%#x\n", Hdr.fFlags & SUPREQHDR_FLAGS_MAGIC_MASK, uCmd));
         return -EINVAL;
     }
@@ -883,10 +887,10 @@
     if (RT_UNLIKELY(cbBuf > _1M*16))
     {
-        dprintf(("VBoxDrvLinuxIOCtl: too big cbBuf=%#x; uCmd=%#x\n", cbBuf, uCmd));
+        Log(("VBoxDrvLinuxIOCtl: too big cbBuf=%#x; uCmd=%#x\n", cbBuf, uCmd));
         return -E2BIG;
     }
     if (RT_UNLIKELY(cbBuf != _IOC_SIZE(uCmd) && _IOC_SIZE(uCmd)))
     {
-        dprintf(("VBoxDrvLinuxIOCtl: bad ioctl cbBuf=%#x _IOC_SIZE=%#x; uCmd=%#x.\n", cbBuf, _IOC_SIZE(uCmd), uCmd));
+        Log(("VBoxDrvLinuxIOCtl: bad ioctl cbBuf=%#x _IOC_SIZE=%#x; uCmd=%#x.\n", cbBuf, _IOC_SIZE(uCmd), uCmd));
         return -EINVAL;
     }
@@ -899,5 +903,5 @@
     if (RT_UNLIKELY(copy_from_user(pHdr, (void *)ulArg, Hdr.cbIn)))
     {
-        dprintf(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx, %#x) failed; uCmd=%#x.\n", ulArg, Hdr.cbIn, uCmd));
+        Log(("VBoxDrvLinuxIOCtl: copy_from_user(,%#lx, %#x) failed; uCmd=%#x.\n", ulArg, Hdr.cbIn, uCmd));
         RTMemFree(pHdr);
         return -EFAULT;
@@ -929,10 +933,10 @@
     else
     {
-        dprintf(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p failed, rc=%d\n", pFilp, uCmd, (void *)ulArg, rc));
+        Log(("VBoxDrvLinuxIOCtl: pFilp=%p uCmd=%#x ulArg=%p failed, rc=%d\n", pFilp, uCmd, (void *)ulArg, rc));
         rc = -EINVAL;
     }
     RTMemFree(pHdr);
 
-    dprintf2(("VBoxDrvLinuxIOCtl: returns %d\n", rc));
+    Log6(("VBoxDrvLinuxIOCtl: returns %d (pid=%d/%d)\n", rc, RTProcSelf(), current->pid));
     return rc;
 }
@@ -984,5 +988,5 @@
     unsigned i;
 #endif
-    dprintf(("VBoxDrvLinuxInitGip:\n"));
+    LogFlow(("VBoxDrvLinuxInitGip:\n"));
 
     /*
@@ -992,5 +996,5 @@
     if (!pPage)
     {
-        dprintf(("VBoxDrvLinuxInitGip: failed to allocate the GIP page\n"));
+        Log(("VBoxDrvLinuxInitGip: failed to allocate the GIP page\n"));
         return -ENOMEM;
     }
@@ -1009,6 +1013,6 @@
     pDevExt->ulLastJiffies  = jiffies;
     pDevExt->u64LastMonotime = (uint64_t)pDevExt->ulLastJiffies * TICK_NSEC;
-    dprintf(("VBoxDrvInitGIP: TICK_NSEC=%ld HZ=%d jiffies=%ld now=%lld\n",
-             TICK_NSEC, HZ, pDevExt->ulLastJiffies, pDevExt->u64LastMonotime));
+    Log(("VBoxDrvInitGIP: TICK_NSEC=%ld HZ=%d jiffies=%ld now=%lld\n",
+         TICK_NSEC, HZ, pDevExt->ulLastJiffies, pDevExt->u64LastMonotime));
     supdrvGipInit(pDevExt, pGip, HCPhys, pDevExt->u64LastMonotime,
                   HZ <= 1000 ? HZ : 1000);
@@ -1045,5 +1049,5 @@
     unsigned i;
 #endif
-    dprintf(("VBoxDrvLinuxTermGip:\n"));
+    LogFlow(("VBoxDrvLinuxTermGip:\n"));
 
     /*
@@ -1232,5 +1236,5 @@
     pgprot_t        pgFlags;
     pgprot_val(pgFlags) = _PAGE_PRESENT | _PAGE_USER;
-    dprintf2(("supdrvOSGipMap: ppGip=%p\n", ppGip));
+    LogFlow(("supdrvOSGipMap: ppGip=%p\n", ppGip));
 
     /*
@@ -1255,5 +1259,5 @@
         {
             rc = SUPDRV_ERR_NO_MEMORY;
-            dprintf(("supdrvOSGipMap: no vma found for ulAddr=%#lx!\n", ulAddr));
+            Log(("supdrvOSGipMap: no vma found for ulAddr=%#lx!\n", ulAddr));
         }
 #endif
@@ -1261,10 +1265,10 @@
         {
             rc = SUPDRV_ERR_NO_MEMORY;
-            dprintf(("supdrvOSGipMap: remap_page_range failed rc2=%d\n", rc2));
+            Log(("supdrvOSGipMap: remap_page_range failed rc2=%d\n", rc2));
         }
     }
     else
     {
-        dprintf(("supdrvOSGipMap: do_mmap failed ulAddr=%#lx\n", ulAddr));
+        Log(("supdrvOSGipMap: do_mmap failed ulAddr=%#lx\n", ulAddr));
         rc = SUPDRV_ERR_NO_MEMORY;
     }
@@ -1277,5 +1281,5 @@
     {
         *ppGip = (PSUPGLOBALINFOPAGE)ulAddr;
-        dprintf2(("supdrvOSGipMap: ppGip=%p\n", *ppGip));
+        LogFlow(("supdrvOSGipMap: ppGip=%p\n", *ppGip));
         return 0;
     }
@@ -1291,5 +1295,5 @@
     }
 
-    dprintf2(("supdrvOSGipMap: returns %d\n", rc));
+    LogFlow(("supdrvOSGipMap: returns %d\n", rc));
     return rc;
 }
@@ -1304,5 +1308,5 @@
 int VBOXCALL supdrvOSGipUnmap(PSUPDRVDEVEXT pDevExt, PSUPGLOBALINFOPAGE pGip)
 {
-    dprintf2(("supdrvOSGipUnmap: pGip=%p\n", pGip));
+    LogFlow(("supdrvOSGipUnmap: pGip=%p\n", pGip));
     if (current->mm)
     {
@@ -1311,5 +1315,5 @@
         up_write(&current->mm->mmap_sem);
     }
-    dprintf2(("supdrvOSGipUnmap: returns 0\n"));
+    LogFlow(("supdrvOSGipUnmap: returns 0\n"));
     return 0;
 }
@@ -1323,5 +1327,5 @@
 void  VBOXCALL  supdrvOSGipResume(PSUPDRVDEVEXT pDevExt)
 {
-    dprintf2(("supdrvOSGipResume:\n"));
+    LogFlow(("supdrvOSGipResume:\n"));
     ASMAtomicXchgU8(&pDevExt->fGIPSuspended, false);
 #ifdef CONFIG_SMP
@@ -1377,5 +1381,5 @@
     unsigned i;
 #endif
-    dprintf2(("supdrvOSGipSuspend:\n"));
+    LogFlow(("supdrvOSGipSuspend:\n"));
     ASMAtomicXchgU8(&pDevExt->fGIPSuspended, true);
 
