]> git.ipfire.org Git - thirdparty/open-vm-tools.git/commitdiff
HGFS: OS X client logging improvements
authorVMware, Inc <>
Thu, 2 Aug 2012 06:52:07 +0000 (23:52 -0700)
committerDmitry Torokhov <dtor@vmware.com>
Thu, 2 Aug 2012 18:23:08 +0000 (11:23 -0700)
Making the logging more consistent and much more useful.

Signed-off-by: Dmitry Torokhov <dtor@vmware.com>
open-vm-tools/lib/hgfsServer/hgfsServer.c
open-vm-tools/modules/freebsd/vmhgfs/debug.c
open-vm-tools/modules/freebsd/vmhgfs/debug.h
open-vm-tools/modules/freebsd/vmhgfs/vnopscommon.c

index dccdffd7d5063c49dc21ad8422c2a18735ca5a08..853ec6b2c0bb8fb873ca186d1063fdd9f5e40d9a 100644 (file)
@@ -3281,6 +3281,8 @@ HgfsServerCleanupDeletedFolders(void)
       HgfsSharedFolderProperties *folder =
          DblLnkLst_Container(link, HgfsSharedFolderProperties, links);
       if (folder->markedForDeletion) {
+         LOG(8, ("%s: removing shared folder handle %#x\n",
+                 __FUNCTION__, folder->notificationHandle));
          if (!HgfsNotify_RemoveSharedFolder(folder->notificationHandle)) {
             LOG(4, ("Problem removing %d shared folder handle\n",
                     folder->notificationHandle));
@@ -3329,11 +3331,19 @@ HgfsServer_RegisterSharedFolder(const char *shareName,   // IN: shared folder na
    DblLnkLst_Links *link, *nextElem;
    HgfsSharedFolderHandle result = HGFS_INVALID_FOLDER_HANDLE;
 
+   LOG(8, ("%s: %s, %s, %s\n", __FUNCTION__,
+           (shareName ? shareName : "NULL"), (sharePath ? sharePath : "NULL"),
+           (addFolder ? "add" : "remove")));
+
    if (!gHgfsDirNotifyActive) {
       LOG(8, ("%s: notification disabled\n", __FUNCTION__));
       goto exit;
    }
 
+   LOG(8, ("%s: %s, %s, %s - active notification\n", __FUNCTION__,
+           (shareName ? shareName : "NULL"), (sharePath ? sharePath : "NULL"),
+           (addFolder ? "add" : "remove")));
+
    if (NULL == shareName) {
       /*
        * The function is invoked with shareName NULL when all shares has been
@@ -3683,6 +3693,7 @@ HgfsServerEnumerateSharedFolders(void)
    void *state;
    Bool success = FALSE;
 
+   LOG(8, ("%s: entered\n", __FUNCTION__));
    state = HgfsServerPolicy_GetSharesInit();
    if (NULL != state) {
       Bool done;
@@ -3702,15 +3713,18 @@ HgfsServerEnumerateSharedFolders(void)
                                                        HGFS_OPEN_MODE_READ_ONLY,
                                                        &sharePathLen, &sharePath);
             if (HGFS_NAME_STATUS_COMPLETE == nameStatus) {
+               LOG(8, ("%s: registering share %s path %s\n", __FUNCTION__, shareName, sharePath));
                handle = HgfsServer_RegisterSharedFolder(shareName, sharePath,
                                                         TRUE);
                success = handle != HGFS_INVALID_FOLDER_HANDLE;
+               LOG(8, ("%s: registering share %s hnd %#x\n", __FUNCTION__, shareName, handle));
             }
          }
       } while (!done && success);
 
       HgfsServerPolicy_GetSharesCleanup(state);
    }
+   LOG(8, ("%s: exit %d\n", __FUNCTION__, success));
    return success;
 }
 
@@ -3905,6 +3919,7 @@ HgfsServerAllocateSession(HgfsTransportSessionInfo *transportSession, // IN:
       HgfsServerSetSessionCapability(HGFS_OP_WRITE_FAST_V4,
                                      HGFS_REQUEST_SUPPORTED, session);
       if (gHgfsDirNotifyActive) {
+         LOG(8, ("%s: notify is enabled\n", __FUNCTION__));
          if (HgfsServerEnumerateSharedFolders()) {
             HgfsServerSetSessionCapability(HGFS_OP_SET_WATCH_V4,
                                            HGFS_REQUEST_SUPPORTED, session);
@@ -3954,13 +3969,17 @@ HgfsServerAllocateSession(HgfsTransportSessionInfo *transportSession, // IN:
 static void
 HgfsDisconnectSessionInt(HgfsSessionInfo *session)    // IN: session context
 {
+   LOG(8, ("%s: entered\n", __FUNCTION__));
 
    ASSERT(session);
    ASSERT(session->nodeArray);
    ASSERT(session->searchArray);
+
    if (session->activeNotification) {
+      LOG(8, ("%s: calling notify component to disconnect\n", __FUNCTION__));
       HgfsNotify_RemoveSessionSubscribers(session);
    }
+   LOG(8, ("%s: exit\n", __FUNCTION__));
 }
 
 
@@ -6907,10 +6926,14 @@ HgfsServerSetDirWatchByHandle(HgfsInputParam *input,         // IN: Input params
 
    if (HgfsHandle2NotifyInfo(dir, input->session, &fileName, &fileNameSize,
                              &sharedFolder)) {
+      LOG(4, ("%s: adding a subscriber on shared folder handle %#x\n", __FUNCTION__,
+               sharedFolder));
       *watchId = HgfsNotify_AddSubscriber(sharedFolder, fileName, events, watchTree,
                                           HgfsServerDirWatchEvent, input->session);
       status = (HGFS_INVALID_SUBSCRIBER_HANDLE == *watchId) ? HGFS_ERROR_INTERNAL :
                                                               HGFS_ERROR_SUCCESS;
+      LOG(4, ("%s: result of add subscriber id %"FMT64"x status %u\n", __FUNCTION__,
+               *watchId, status));
    } else {
       status = HGFS_ERROR_INTERNAL;
    }
@@ -6990,22 +7013,28 @@ HgfsServerSetDirWatchByName(HgfsInputParam *input,         // IN: Input params
             nameStatus = CPName_ConvertFrom((char const **) &next, &nameSize,
                                             &tempSize, &tempPtr);
             if (HGFS_NAME_STATUS_COMPLETE == nameStatus) {
+               LOG(8, ("%s: adding subscriber on share hnd %#x\n", __FUNCTION__, sharedFolder));
                *watchId = HgfsNotify_AddSubscriber(sharedFolder, tempBuf, events,
                                                    watchTree, HgfsServerDirWatchEvent,
                                                    input->session);
                 status = (HGFS_INVALID_SUBSCRIBER_HANDLE == *watchId) ?
                                               HGFS_ERROR_INTERNAL : HGFS_ERROR_SUCCESS;
+               LOG(8, ("%s: adding subscriber on share hnd %#x result %u\n", __FUNCTION__,
+                       sharedFolder, status));
             } else {
                LOG(4, ("%s: Conversion to platform specific name failed\n",
                        __FUNCTION__));
                status = HgfsPlatformConvertFromNameStatus(nameStatus);
             }
          } else {
+            LOG(8, ("%s: adding subscriber on share hnd %#x\n", __FUNCTION__, sharedFolder));
             *watchId = HgfsNotify_AddSubscriber(sharedFolder, "", events, watchTree,
                                                 HgfsServerDirWatchEvent,
                                                 input->session);
             status = (HGFS_INVALID_SUBSCRIBER_HANDLE == *watchId) ? HGFS_ERROR_INTERNAL :
                                                                     HGFS_ERROR_SUCCESS;
+            LOG(8, ("%s: adding subscriber on share hnd %#x result %u\n", __FUNCTION__,
+                     sharedFolder, status));
          }
       } else if (HGFS_NAME_STATUS_INCOMPLETE_BASE == nameStatus) {
          LOG(4, ("%s: Notification for root share is not supported yet\n",
@@ -7122,11 +7151,14 @@ HgfsServerRemoveDirNotifyWatch(HgfsInputParam *input)  // IN: Input params
 
    if (HgfsUnpackRemoveWatchRequest(input->payload, input->payloadSize, input->op,
                                     &watchId)) {
+      LOG(8, ("%s: remove subscriber on subscr id %"FMT64"x\n", __FUNCTION__, watchId));
       if (HgfsNotify_RemoveSubscriber(watchId)) {
          status = HGFS_ERROR_SUCCESS;
       } else {
          status = HGFS_ERROR_INTERNAL;
       }
+      LOG(8, ("%s: remove subscriber on subscr id %"FMT64"x result %u\n", __FUNCTION__,
+               watchId, status));
    } else {
       status = HGFS_ERROR_PROTOCOL;
    }
index 8eb1584c27a547515aa5ad5cbced8ca8046e1213..5618c90e6e13ada5d6d6ee934527883a02cfd6d4 100644 (file)
  */
 
 
+#if defined __APPLE__
+#include <sys/proc.h>         // for proc_selfpid/name
+#include <string.h>
+#include "kernelStubs.h"
+#endif // defined __APPLE__
 #include "vm_basic_types.h"
 #include "debug.h"
 
 /*
  * Global functions
  */
+static const char *gHgfsOperationNames[] = {
+   "HGFS_OP_OPEN",
+   "HGFS_OP_READ",
+   "HGFS_OP_WRITE",
+   "HGFS_OP_CLOSE",
+   "HGFS_OP_SEARCH_OPEN",
+   "HGFS_OP_SEARCH_READ",
+   "HGFS_OP_SEARCH_CLOSE",
+   "HGFS_OP_GETATTR",
+   "HGFS_OP_SETATTR",
+   "HGFS_OP_CREATE_DIR",
+   "HGFS_OP_DELETE_FILE",
+   "HGFS_OP_DELETE_DIR",
+   "HGFS_OP_RENAME",
+   "HGFS_OP_QUERY_VOLUME_INFO",
+   "HGFS_OP_OPEN_V2",
+   "HGFS_OP_GETATTR_V2",
+   "HGFS_OP_SETATTR_V2",
+   "HGFS_OP_SEARCH_READ_V2",
+   "HGFS_OP_CREATE_SYMLINK",
+   "HGFS_OP_SERVER_LOCK_CHANGE",
+   "HGFS_OP_CREATE_DIR_V2",
+   "HGFS_OP_DELETE_FILE_V2",
+   "HGFS_OP_DELETE_DIR_V2",
+   "HGFS_OP_RENAME_V2",
+   "HGFS_OP_OPEN_V3",
+   "HGFS_OP_READ_V3",
+   "HGFS_OP_WRITE_V3",
+   "HGFS_OP_CLOSE_V3",
+   "HGFS_OP_SEARCH_OPEN_V3",
+   "HGFS_OP_SEARCH_READ_V3",
+   "HGFS_OP_SEARCH_CLOSE_V3",
+   "HGFS_OP_GETATTR_V3",
+   "HGFS_OP_SETATTR_V3",
+   "HGFS_OP_CREATE_DIR_V3",
+   "HGFS_OP_DELETE_FILE_V3",
+   "HGFS_OP_DELETE_DIR_V3",
+   "HGFS_OP_RENAME_V3",
+   "HGFS_OP_QUERY_VOLUME_INFO_V3",
+   "HGFS_OP_CREATE_SYMLINK_V3",
+   "HGFS_OP_SERVER_LOCK_CHANGE_V3",
+   "HGFS_OP_WRITE_WIN32_STREAM_V3",
+   "HGFS_OP_CREATE_SESSION_V4",
+   "HGFS_OP_DESTROY_SESSION_V4",
+   "HGFS_OP_READ_FAST_V4",
+   "HGFS_OP_WRITE_FAST_V4",
+   "HGFS_OP_SET_WATCH_V4",
+   "HGFS_OP_REMOVE_WATCH_V4",
+   "HGFS_OP_NOTIFY_V4",
+   "HGFS_OP_SEARCH_READ_V4",
+};
+
+#if defined VMX86_DEVEL
+static uint32 HgfsDebugGetSequenceNumber(void);
+static int HgfsDebugGetProcessInfo(char *pidName, size_t pidNameBufsize);
+static void *HgfsDebugGetCurrentThread(void);
+#endif // defined VMX86_DEVEL
+
+
+/*
+ *----------------------------------------------------------------------------
+ *
+ * HgfsDebugPrint --
+ *
+ *      Prints the operation of an request structure.
+ *
+ * Results:
+ *      None.
+ *
+ * Side effects:
+ *      None.
+ *
+ *----------------------------------------------------------------------------
+ */
+
+void
+HgfsDebugPrint(int type, const char *funcname, unsigned int linenum, const char *fmt, ...)
+{
+#if defined VMX86_DEVEL
+#if defined __APPLE__
+   if (0 != (type & VM_DEBUG_LEV) ||
+       VM_DEBUG_ALWAYS == type) {
+      char *fmsg;
+      size_t fmsgLen;
+      va_list args;
+
+      va_start(args, fmt);
+      fmsg = Str_Vasprintf(&fmsgLen, fmt, args);
+      va_end(args);
+
+      if (NULL != fmsg) {
+         int pid;
+         void *thrd;
+         char pidname[64];
+         uint32 seqNo;
+
+         thrd = HgfsDebugGetCurrentThread();
+         pid = HgfsDebugGetProcessInfo(pidname, sizeof pidname);
+         seqNo = HgfsDebugGetSequenceNumber();
+
+         kprintf("|%08u|%p.%08d.%s| %s:%2.2u: %s",
+                 seqNo, thrd, pid, pidname, funcname, linenum, fmsg);
+
+         free(fmsg);
+      }
+   }
+#endif // defined __APPLE__
+#endif // defined VMX86_DEVEL
+}
+
+
+/*
+ *----------------------------------------------------------------------------
+ *
+ * HgfsDebugPrintOperation --
+ *
+ *      Prints the operation of an request structure.
+ *
+ * Results:
+ *      None.
+ *
+ * Side effects:
+ *      None.
+ *
+ *----------------------------------------------------------------------------
+ */
+
+void
+HgfsDebugPrintOperation(HgfsKReqHandle req)
+{
+   HgfsRequest *requestHeader;
+
+   ASSERT(NULL != req);
+
+   requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
+
+   if (requestHeader->op < ARRAYSIZE(gHgfsOperationNames)) {
+      DEBUG(VM_DEBUG_STRUCT, " operation: %s\n", gHgfsOperationNames[requestHeader->op]);
+   } else {
+      DEBUG(VM_DEBUG_STRUCT, " operation: INVALID %d\n", requestHeader->op);
+   }
+}
+
+
+#if defined VMX86_DEVEL
+/*
+ *----------------------------------------------------------------------------
+ *
+ * HgfsDebugGetProcessInfo --
+ *
+ *      Gets the process name and ID making a request.
+ *
+ * Results:
+ *      PID of current process, and name in the buffer.
+ *
+ * Side effects:
+ *      None.
+ *
+ *----------------------------------------------------------------------------
+ */
+
+static int
+HgfsDebugGetProcessInfo(char *pidname,          // OUT: buffer for name
+                        size_t pidNameBufsize)  // IN: size of buffer
+{
+   int curPid = -1;
+   *pidname = '\0';
+#if defined __APPLE__
+   curPid = proc_selfpid();
+   proc_name(curPid, pidname, pidNameBufsize);
+#endif // defined __APPLE__
+   return curPid;
+}
+
+
+/*
+ *----------------------------------------------------------------------------
+ *
+ * HgfsDebugGetCurrentThreadId --
+ *
+ *      Gets the current thread making a request.
+ *
+ * Results:
+ *      TID of current thread.
+ *
+ * Side effects:
+ *      None.
+ *
+ *----------------------------------------------------------------------------
+ */
+
+static void *
+HgfsDebugGetCurrentThread(void)
+{
+   void *thread = NULL;
+#if defined __APPLE__
+   thread = current_thread();
+#endif // defined __APPLE__
+   return thread;
+}
+#endif // defined VMX86_DEVEL
 
 
 /*
@@ -110,3 +316,29 @@ HgfsDebugPrintVattr(const HgfsVnodeAttr *vap)
    DEBUG(VM_DEBUG_STRUCT, " va_create_time.tv_nsec: %ld\n", vap->va_create_time.tv_nsec);
 #endif
 }
+
+
+#if defined VMX86_DEVEL
+/*
+ *----------------------------------------------------------------------------
+ *
+ * HgfsDebugGetSequenceNumber --
+ *
+ *      Log a sequence number in case we suspect log messages getting dropped
+ *
+ * Results:
+ *      The next sequence number.
+ *
+ * Side effects:
+ *      None.
+ *
+ *----------------------------------------------------------------------------
+ */
+
+static uint32
+HgfsDebugGetSequenceNumber(void)
+{
+   static uint32 ghgfsDebugLogSeq = 0;
+   return ++ghgfsDebugLogSeq;
+}
+#endif // defined VMX86_DEVEL
index 3baede77f6d9f1fd600b0ebc54610f40651dce61..72862c75706118373cf18b042cf83b0b5462835c 100644 (file)
@@ -52,7 +52,7 @@
 #define VM_DEBUG_FAIL          VM_DEBUG_ALWAYS
 #define VM_DEBUG_NOTSUP         VM_DEBUG_ALWAYS
 #define VM_DEBUG_ENTRY          (1 << 1)
-#define VM_DEBUG_DONE          (1 << 2)
+#define VM_DEBUG_EXIT           (1 << 2)
 #define VM_DEBUG_LOAD          (1 << 3)
 #define VM_DEBUG_INFO           (1 << 4)
 #define VM_DEBUG_STRUCT         (1 << 5)
 #define VM_DEBUG_HSHTBL         (1 << 17)
 #define VM_DEBUG_HANDLE         (1 << 18)
 #define VM_DEBUG_STATE          (1 << 19)
+#define VM_DEBUG_VNODE          (1 << 20)
 #define VM_DEBUG_ALL            (~0)
 
 #if defined VMX86_DEVEL
-#  define VM_DEBUG_LEV (VM_DEBUG_ALWAYS | VM_DEBUG_FAIL)
+#define VM_DEBUG_LEV (VM_DEBUG_ALWAYS | VM_DEBUG_ENTRY | VM_DEBUG_EXIT | VM_DEBUG_FAIL)
 #endif
 
 #ifdef VM_DEBUG_LEV
                 : 0)
 #  elif defined __APPLE__
 #    define DEBUG(type, fmt, ...)                             \
-                 ((type & VM_DEBUG_LEV) ?                     \
-                  (kprintf("%s:%u: " fmt,                     \
-                       __func__, __LINE__, ##__VA_ARGS__))    \
-                  : (void)0)
+                 HgfsDebugPrint(type, __func__, __LINE__, fmt, ##__VA_ARGS__)
 #  endif
 #else
 #  define DEBUG(type, ...)
 #endif
 
-
 /*
  * Global functions
  */
 
+void HgfsDebugPrint(int type, const char *funcname, unsigned int linenum, const char *fmt, ...);
 void HgfsDebugPrintVattr(const HgfsVnodeAttr *vap);
+void HgfsDebugPrintOperation(HgfsKReqHandle req);
 
 #endif // _DEBUG_H_
index 27064c277d1815affacc876a1e9230d7cd1990a0..b309fd6562333b4943135f656f285644d8d06aed 100644 (file)
@@ -104,15 +104,20 @@ HgfsRenameInt(struct vnode *fvp,          // IN: "from" file
    uint32 repSize;
    int ret;
 
-   DEBUG(VM_DEBUG_LOG, "Trace enter.\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s -> %.*s/%.*s).\n",
+         HGFS_VP_TO_FILENAME_LENGTH(fvp), HGFS_VP_TO_FILENAME(fvp),
+         HGFS_VP_TO_FILENAME_LENGTH(tdvp), HGFS_VP_TO_FILENAME(tdvp),
+         (int)tcnp->cn_namelen, tcnp->cn_nameptr);
+
    /* No cross-device renaming. */
    if (HGFS_VP_TO_MP(fvp) != HGFS_VP_TO_MP(tdvp)) {
-      return EXDEV;
+      ret = EXDEV;
+      goto out;
    }
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return ret;
+      goto out;
    }
 
    requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
@@ -216,7 +221,6 @@ HgfsRenameInt(struct vnode *fvp,          // IN: "from" file
    }
 
    /* Successfully renamed file on the server. */
-    DEBUG(VM_DEBUG_DONE, "done.\n");
 
 destroyOut:
    HgfsKReq_ReleaseRequest(sip->reqs, req);
@@ -225,6 +229,7 @@ out:
    if (dstFullPath != NULL) {
       os_free(dstFullPath, MAXPATHLEN);
    }
+   DEBUG(VM_DEBUG_EXIT, "Exit(%d).\n", ret);
    return ret;
 }
 
@@ -267,11 +272,13 @@ HgfsReaddirInt(struct vnode *vp, // IN    : Directory vnode to get entries from.
    char *fullName = NULL;       /* Hashed to generate inode number */
    int ret = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n",  HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
+
    /* uio_offset is a signed quantity. */
    if (HGFS_UIOP_TO_OFFSET(uiop) < 0) {
       DEBUG(VM_DEBUG_FAIL, "fed negative offset.\n");
-      return EINVAL;
+      ret = EINVAL;
+      goto out;
    }
 
    /*
@@ -291,7 +298,8 @@ HgfsReaddirInt(struct vnode *vp, // IN    : Directory vnode to get entries from.
    ret = HgfsGetOpenFileHandle(vp, &handle);
    if (ret) {
       DEBUG(VM_DEBUG_FAIL, "could not get handle.\n");
-      return EINVAL;
+      ret = EINVAL;
+      goto out;
    }
 
    /*
@@ -299,7 +307,8 @@ HgfsReaddirInt(struct vnode *vp, // IN    : Directory vnode to get entries from.
     */
    fullName = os_malloc(MAXPATHLEN, M_WAITOK);
    if (!fullName) {
-      return ENOMEM;
+      ret = ENOMEM;
+      goto out;
    }
 
    /*
@@ -439,12 +448,13 @@ HgfsReaddirInt(struct vnode *vp, // IN    : Directory vnode to get entries from.
     */
    HGFS_UIOP_SET_OFFSET(uiop, offset);
 
-   DEBUG(VM_DEBUG_DONE, "done (ret=%d, *eofp=%d).\n", ret, *eofp);
+   DEBUG(VM_DEBUG_EXIT, "done (ret=%d, *eofp=%d).\n", ret, *eofp);
 out:
    if (fullName != NULL) {
       os_free(fullName, MAXPATHLEN);
    }
-   DEBUG(VM_DEBUG_ENTRY, "exiting %s.\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -474,7 +484,8 @@ HgfsGetattrInt(struct vnode *vp,      // IN : vnode of the file
    HgfsAttrV2 hgfsAttrV2;
    int ret = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
+
    /* XXX It would be nice to do a GetattrByHandle when possible here. */
    ret = HgfsDoGetattrByName(HGFS_VP_TO_FILENAME(vp), sip, &hgfsAttrV2);
 
@@ -487,7 +498,8 @@ HgfsGetattrInt(struct vnode *vp,      // IN : vnode of the file
       HgfsAttrToBSD(vp, &hgfsAttrV2, vap);
    }
 
-   DEBUG(VM_DEBUG_LOG, "Exit %s -> %d.\n",  HGFS_VP_TO_FILENAME(vp), ret);
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -524,13 +536,13 @@ HgfsSetattrInt(struct vnode *vp,     // IN : vnode of the file
    uint32 fullPathLen;
    int ret;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
    ASSERT(vp);
    ASSERT(vap);
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return ret;
+      goto out;
    }
 
    requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
@@ -608,10 +620,10 @@ HgfsSetattrInt(struct vnode *vp,     // IN : vnode of the file
    }
 
 destroyOut:
-   DEBUG(VM_DEBUG_DONE, "done with ret = %d\n", ret);
    HgfsKReq_ReleaseRequest(sip->reqs, req);
 out:
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -643,19 +655,18 @@ HgfsRmdirInt(struct vnode *dvp,          // IN: parent directory
             struct componentname *cnp)  // IN: Only used for debugging
 {
    int ret = 0;
-
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(dvp);
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
-
-   DEBUG(VM_DEBUG_ENTRY, "HgfsRmdir().\n");
 
-   DEBUG(VM_DEBUG_ENTRY, "dvp=%p (%s), nm=%s, vp=%p (%s)\n",
-         dvp, (HGFS_VP_TO_FP(dvp)) ? HGFS_VP_TO_FILENAME(dvp) : "dvp->v_data null",
-         cnp->cn_nameptr, vp,
-         (HGFS_VP_TO_FP(vp)) ? HGFS_VP_TO_FILENAME(vp) : "vp->v_data null");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s/%.*s)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
 
    ret = HgfsDelete(sip, HGFS_VP_TO_FILENAME(vp), HGFS_OP_DELETE_DIR_V3);
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s/%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
+
    return ret;
 }
 
@@ -685,11 +696,11 @@ int HgfsRemoveInt(struct vnode *vp) // IN: Vnode to delete
 
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
-   DEBUG(VM_DEBUG_ENTRY, "HgfsRemove().\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
 
    /* Removing directories is a no-no; save that for VNOP_RMDIR. */
    if (HGFS_VP_TO_VTYPE(vp) == VDIR) {
+      DEBUG(VM_DEBUG_FAIL, "HgfsRemove(). on dir ret EPERM\n");
       ret = EPERM;
       goto out;
    }
@@ -701,7 +712,8 @@ int HgfsRemoveInt(struct vnode *vp) // IN: Vnode to delete
    ret = HgfsDelete(sip, HGFS_VP_TO_FILENAME(vp), HGFS_OP_DELETE_FILE_V3);
 
 out:
-   DEBUG(VM_DEBUG_LOG, "Exit %s -> %d.\n",  HGFS_VP_TO_FILENAME(vp), ret);
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -720,7 +732,7 @@ out:
  *      (Solaris Internals, p536)
  *
  * Results:
- *      Returns 0 on success and an error code on error.
+ *      Always returns 0 success.
  *
  * Side effects:
  *      None.
@@ -734,7 +746,9 @@ HgfsCloseInt(struct vnode *vp, // IN: Vnode to close.
 {
    int ret = 0;
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s, %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+        mode);
 
    /*
     * If we are closing a directory we need to send a SEARCH_CLOSE request,
@@ -757,7 +771,8 @@ HgfsCloseInt(struct vnode *vp, // IN: Vnode to close.
       ret = EINVAL;
       break;
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d -> 0)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+        ret);
    return 0;
 }
 
@@ -792,33 +807,38 @@ HgfsOpenInt(struct vnode *vp,           // IN: Vnode to open.
             HgfsOpenType openType)      // IN: TRUE if called outside of VNOP_OPEN.
 {
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   int ret = 0;
+
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s, %d, %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         mode, openType);
 
    switch(HGFS_VP_TO_VTYPE(vp)) {
    case VDIR:
-      DEBUG(VM_DEBUG_COMM, "opening a directory\n");
-      return HgfsDirOpen(sip, vp, openType);
+      DEBUG(VM_DEBUG_LOG, "opening a directory\n");
+      ret = HgfsDirOpen(sip, vp, openType);
+      break;
 
    case VREG:
-      {
-         /*
-          * If HgfsCreate() was called prior to this then is would set permissions
-          * in HgfsFile that we need to pass to HgfsFileOpen.
-          * If HgfsCreate has not been called then file already exists and permissions
-          * are ignored by HgfsFileOpen.
-          */
-         DEBUG(VM_DEBUG_COMM, "opening a file with flag %x\n", mode);
-         return HgfsFileOpen(sip, vp, mode, HGFS_VP_TO_PERMISSIONS(vp), openType);
-      }
+      /*
+       * If HgfsCreate() was called prior to this then is would set permissions
+       * in HgfsFile that we need to pass to HgfsFileOpen.
+       * If HgfsCreate has not been called then file already exists and permissions
+       * are ignored by HgfsFileOpen.
+       */
+      DEBUG(VM_DEBUG_LOG, "opening a file with flag %x\n", mode);
+      ret = HgfsFileOpen(sip, vp, mode, HGFS_VP_TO_PERMISSIONS(vp), openType);
+      break;
 
    default:
       DEBUG(VM_DEBUG_FAIL,
             "HgfsOpen: unrecognized file of type %d.\n", HGFS_VP_TO_VTYPE(vp));
-      return EINVAL;
+      ret = EINVAL;
+      break;
    }
 
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
-   return 0;
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), ret);
+   return ret;
 }
 
 
@@ -854,13 +874,11 @@ HgfsLookupInt(struct vnode *dvp,         // IN : directory vnode
    int ret = 0;
    int len = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(dvp));
-
    ASSERT(dvp);
    ASSERT(vpp);
    ASSERT(cnp);
 
-   DEBUG(VM_DEBUG_ENTRY, "HgfsLookupInt(%.*s, %.*s).\n",
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s, %.*s).\n",
          HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
          (int)cnp->cn_namelen, cnp->cn_nameptr);
 
@@ -944,12 +962,14 @@ HgfsLookupInt(struct vnode *dvp,         // IN : directory vnode
       if ((cnp->cn_nameiop == CREATE || cnp->cn_nameiop == RENAME) &&
           cnp->cn_flags & ISLASTCN) {
          ret = EJUSTRETURN;
+         DEBUG(VM_DEBUG_FAIL, "GetattrByName error %d for \"%s\".\n", ret, path);
         goto out;
       }
    }
 
    /* Got an error from HgfsDoGetattrByName, return it to the caller. */
    if (ret) {
+      DEBUG(VM_DEBUG_FAIL, "GetattrByName error %d for \"%s\".\n", ret, path);
       goto out;
    }
 
@@ -983,7 +1003,9 @@ out:
    if (path != NULL) {
       os_free(path, MAXPATHLEN);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %d for %s.\n", ret, HGFS_VP_TO_FILENAME(dvp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s, %.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr, ret);
    return ret;
 }
 
@@ -1011,20 +1033,23 @@ out:
  *----------------------------------------------------------------------------
  */
 
-int HgfsCreateInt(struct vnode *dvp,         // IN : Directory vnode
-                 struct vnode **vpp,        // OUT: Pointer to new vnode
-                 struct componentname *cnp, // IN : Location to create new vnode
-                 int mode)                  // IN : Mode of vnode being created.
+int
+HgfsCreateInt(struct vnode *dvp,         // IN : Directory vnode
+              struct vnode **vpp,        // OUT: Pointer to new vnode
+              struct componentname *cnp, // IN : Location to create new vnode
+              int mode)                  // IN : Mode of vnode being created.
 {
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(dvp);
    char *fullname = NULL;       // allocated from M_TEMP; free when done.
    int ret = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(dvp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s/%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr);
 
    if (*vpp != NULL) {
-      DEBUG(VM_DEBUG_ALWAYS, "vpp (%p) not null\n", vpp);
-      return EEXIST;
+      DEBUG(VM_DEBUG_FAIL, "vpp (%p) not null\n", vpp);
+      ret = EEXIST;
+      goto out;
    }
 
    /* If we have gotten to this point then we know that we need to create a
@@ -1033,7 +1058,8 @@ int HgfsCreateInt(struct vnode *dvp,         // IN : Directory vnode
     */
    fullname = os_malloc(MAXPATHLEN, M_WAITOK);
    if (!fullname) {
-      return ENOMEM;
+      ret = ENOMEM;
+      goto out;
    }
 
    ret = HgfsMakeFullName(HGFS_VP_TO_FILENAME(dvp),  // Name of directory to create in
@@ -1068,10 +1094,13 @@ int HgfsCreateInt(struct vnode *dvp,         // IN : Directory vnode
       ret = ENAMETOOLONG;
    }
 
+out:
    if (fullname != NULL) {
       os_free(fullname, MAXPATHLEN);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(dvp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s/%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr, ret);
    return ret;
 }
 
@@ -1111,10 +1140,11 @@ HgfsReadInt(struct vnode *vp, // IN    : Vnode to read from
    uint64_t offset;
    int ret;
 
-   DEBUG(VM_DEBUG_ENTRY, "entry %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
 
    /* We can't read from directories, that's what readdir() is for. */
    if (HGFS_VP_TO_VTYPE(vp) != VREG) {
+      DEBUG(VM_DEBUG_FAIL, "Can only read regular files.\n");
       ret = (HGFS_VP_TO_VTYPE(vp) == VDIR) ? EISDIR : EPERM;
       DEBUG(VM_DEBUG_FAIL, "Read not a reg file type %d ret %d.\n", HGFS_VP_TO_VTYPE(vp), ret);
       return ret;
@@ -1175,7 +1205,7 @@ HgfsReadInt(struct vnode *vp, // IN    : Vnode to read from
 
       if (size == 0) {
          /* For a zero byte length read we return success. */
-         DEBUG(VM_DEBUG_DONE, "size of 0 ret -> 0.\n");
+         DEBUG(VM_DEBUG_EXIT, "size of 0 ret -> 0.\n");
          return 0;
       }
 
@@ -1183,7 +1213,7 @@ HgfsReadInt(struct vnode *vp, // IN    : Vnode to read from
       ret = HgfsDoRead(sip, handle, offset, size, uiop);
       if (ret == 0) {
          /* On end of file we return success */
-         DEBUG(VM_DEBUG_DONE, "end of file reached.\n");
+         DEBUG(VM_DEBUG_EXIT, "end of file reached.\n");
          return 0;
       } else if (ret == -EBADF) { // Stale host handle
          ret = HgfsRefreshHandle(vp, sip, &handle);
@@ -1213,7 +1243,7 @@ HgfsReadInt(struct vnode *vp, // IN    : Vnode to read from
    } while (HGFS_UIOP_TO_RESID(uiop));
 
    /* We fulfilled the user's read request, so return success. */
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> 0)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
    return 0;
 }
 
@@ -1246,15 +1276,16 @@ HgfsWriteInt(struct vnode *vp, // IN    : the vnode of the file
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
    HgfsHandle handle;
    uint64_t offset;
-   int ret;
+   int ret = 0;
    int error = 0;
 
-   DEBUG(VM_DEBUG_ENTRY, "entry. (vp=%p)\n", vp);
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
 
    /* Skip write requests for 0 bytes. */
    if (HGFS_UIOP_TO_RESID(uiop) == 0) {
       DEBUG(VM_DEBUG_INFO, "write of 0 bytes requested.\n");
-      return 0;
+      error = 0;
+      goto out;
    }
 
    DEBUG(VM_DEBUG_INFO, "file is %s\n", HGFS_VP_TO_FILENAME(vp));
@@ -1262,7 +1293,8 @@ HgfsWriteInt(struct vnode *vp, // IN    : the vnode of the file
    /* Off_t is a signed type. */
    if (HGFS_UIOP_TO_OFFSET(uiop) < 0) {
       DEBUG(VM_DEBUG_FAIL, "given negative offset.\n");
-      return EINVAL;
+      error = EINVAL;
+      goto out;
    }
 
    /* This is where the user will begin writing into the file. */
@@ -1272,7 +1304,8 @@ HgfsWriteInt(struct vnode *vp, // IN    : the vnode of the file
    ret = HgfsGetOpenFileHandle(vp, &handle);
    if (ret) {
       DEBUG(VM_DEBUG_FAIL, "could not get handle.\n");
-      return EINVAL;
+      error = EINVAL;
+      goto out;
    }
 
    /* Flush mmaped data to maintain data coherence between mmap and read. */
@@ -1339,8 +1372,11 @@ HgfsWriteInt(struct vnode *vp, // IN    : the vnode of the file
          os_SetSize(vp, oldSize + writtenData);
       }
    }
+
+out:
    /* We have completed the user's write request, so return. */
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp), error);
 
    return error;
 }
@@ -1382,9 +1418,9 @@ HgfsMkdirInt(struct vnode *dvp,         // IN : directory vnode
    uint32 fullNameLen;
    int ret;
 
-   DEBUG(VM_DEBUG_ENTRY, "dvp=%p (%s), dirname=%s, vpp=%p\n",
-                         dvp, HGFS_VP_TO_FILENAME(dvp), cnp->cn_nameptr,
-                         *vpp);
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s/%.*s,%d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr, mode);
 
    /*
     * We need to construct the full path of the directory to create then send
@@ -1397,7 +1433,8 @@ HgfsMkdirInt(struct vnode *dvp,         // IN : directory vnode
    /* Construct the complete path of the directory to create. */
    fullName = os_malloc(MAXPATHLEN, M_WAITOK);
    if (!fullName) {
-      return ENOMEM;
+      ret = ENOMEM;
+      goto out;
    }
 
    ret = HgfsMakeFullName(HGFS_VP_TO_FILENAME(dvp),        // Parent directory
@@ -1480,6 +1517,7 @@ HgfsMkdirInt(struct vnode *dvp,         // IN : directory vnode
                       mode, 0);
    if (ret) {
       ret = EIO;
+      DEBUG(VM_DEBUG_FAIL, "Error encountered creating vnode ret = %d\n", ret);
       goto destroyOut;
    }
 
@@ -1492,7 +1530,9 @@ out:
    if (fullName != NULL) {
       os_free(fullName, MAXPATHLEN);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(dvp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s/%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr, ret);
    return ret;
 }
 
@@ -1532,7 +1572,8 @@ HgfsDirOpen(HgfsSuperInfo *sip,         // IN: Superinfo pointer
    fp = HGFS_VP_TO_FP(vp);
    ASSERT(fp);
 
-   DEBUG(VM_DEBUG_ENTRY, "opening dir \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s,%d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         openType);
 
    /*
     *  If the directory is already opened then we are done.
@@ -1561,7 +1602,9 @@ HgfsDirOpen(HgfsSuperInfo *sip,         // IN: Superinfo pointer
    }
    os_rw_lock_unlock_exclusive(fp->handleLock);
 
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -1601,10 +1644,15 @@ HgfsRequestHostFileHandle(HgfsSuperInfo *sip,   // IN: Superinfo pointer
    fullPath = HGFS_VP_TO_FILENAME(vp);
    fullPathLen = HGFS_VP_TO_FILENAME_LENGTH(vp);
 
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s, %d, %d, %o)\n", fullPathLen, fullPath,
+         *openMode, openFlags, permissions);
+
    /* First see if we can get the most permissive read/write open mode */
    ret = HgfsSendOpenRequest(sip, HGFS_OPEN_MODE_READ_WRITE, openFlags,
                              permissions, fullPath, fullPathLen, handle);
    if (ret) {
+      DEBUG(VM_DEBUG_FAIL, "Open failed %d, re-submitting original mode = %d.\n",
+            ret, *openMode);
       if (ret == EACCES && HGFS_OPEN_MODE_READ_WRITE != *openMode) {
          /*
           * Failed to open in read/write open mode because of denied access.
@@ -1621,6 +1669,7 @@ HgfsRequestHostFileHandle(HgfsSuperInfo *sip,   // IN: Superinfo pointer
    } else {
       *openMode = HGFS_OPEN_MODE_READ_WRITE;
    }
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", fullPathLen, fullPath, ret);
    return ret;
 }
 
@@ -1664,7 +1713,9 @@ HgfsFileOpen(HgfsSuperInfo *sip,        // IN: Superinfo pointer
    fp = HGFS_VP_TO_FP(vp);
    ASSERT(fp);
 
-   DEBUG(VM_DEBUG_ENTRY, "opening \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s,%d,%d,%o)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         flag, openType, permissions);
 
    /*
     * Check if the user is trying to create a new share. This check was
@@ -1680,7 +1731,8 @@ HgfsFileOpen(HgfsSuperInfo *sip,        // IN: Superinfo pointer
     */
    if (HgfsAttemptToCreateShare(HGFS_VP_TO_FILENAME(vp), flag)) {
       DEBUG (VM_DEBUG_LOG, "An attempt to create a new share was made.\n");
-      return EACCES;
+      ret = EACCES;
+      goto out;
    }
 
    /* Convert FreeBSD modes to Hgfs modes */
@@ -1722,7 +1774,8 @@ HgfsFileOpen(HgfsSuperInfo *sip,        // IN: Superinfo pointer
    os_rw_lock_unlock_exclusive(fp->handleLock);
 
 out:
-   DEBUG(VM_DEBUG_LOG, "Exit (%d) %s.\n", ret,  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -1757,7 +1810,8 @@ HgfsRefreshHandle(struct vnode *vp,          // IN: Vnode of file to open
    fp = HGFS_VP_TO_FP(vp);
    ASSERT(fp);
 
-   DEBUG(VM_DEBUG_ENTRY, "Refresh handle\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
+
    os_rw_lock_lock_exclusive(fp->handleLock);
    if (fp->handle != *handle) {
       /* Handle has been refreshed in another thread. */
@@ -1782,6 +1836,8 @@ HgfsRefreshHandle(struct vnode *vp,          // IN: Vnode of file to open
 out:
    os_rw_lock_unlock_exclusive(fp->handleLock);
 
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -1814,7 +1870,7 @@ HgfsDirClose(HgfsSuperInfo *sip,        // IN: Superinfo pointer
    ASSERT(sip);
    ASSERT(vp);
 
-   DEBUG(VM_DEBUG_ENTRY, "closing \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
 
    /*
     * Check to see if we should close the file handle on the host ( which happen when
@@ -1823,7 +1879,8 @@ HgfsDirClose(HgfsSuperInfo *sip,        // IN: Superinfo pointer
    if (HgfsReleaseOpenFileHandle(vp, OPENREQ_OPEN, &handleToClose) == 0) {
       ret = HgfsCloseServerDirHandle(sip, handleToClose);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -1857,7 +1914,8 @@ HgfsFileClose(HgfsSuperInfo *sip,       // IN: Superinfo pointer
    ASSERT(sip);
    ASSERT(vp);
 
-   DEBUG(VM_DEBUG_ENTRY, "closing file \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s,%d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         flags);
 
    /*
     * Check to see if we should close the file handle on the host ( which happen when
@@ -1866,7 +1924,8 @@ HgfsFileClose(HgfsSuperInfo *sip,       // IN: Superinfo pointer
    if (HgfsReleaseOpenFileHandle(vp, OPENREQ_OPEN, &handleToClose) == 0) {
       ret = HgfsCloseServerFileHandle(sip, handleToClose);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -1916,11 +1975,12 @@ HgfsDoRead(HgfsSuperInfo *sip,  // IN: Superinfo pointer
    ASSERT(uiop);
    ASSERT(size <= HGFS_IO_MAX); // HgfsRead() should guarantee this
 
-   DEBUG(VM_DEBUG_ENTRY, "entry.\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%u,%"FMT64"u,%u)\n", handle, offset, size);
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return -ret;
+      ret = -ret;
+      goto out;
    }
 
    requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
@@ -1994,10 +2054,10 @@ HgfsDoRead(HgfsSuperInfo *sip,  // IN: Superinfo pointer
 
 success:
    ret = reply->actualSize;
-   DEBUG(VM_DEBUG_DONE, "successfully read %d bytes to user.\n", ret);
 destroyOut:
    HgfsKReq_ReleaseRequest(sip->reqs, req);
 out:
+   DEBUG(VM_DEBUG_EXIT, "Exit(%u -> %d)\n", handle, ret);
    return ret;
 }
 
@@ -2045,14 +2105,16 @@ HgfsDoWrite(HgfsSuperInfo *sip, // IN: Superinfo pointer
    uint32 repSize;
    int ret;
 
-   DEBUG(VM_DEBUG_LOG, "Trace enter.\n");
    ASSERT(sip);
    ASSERT(uiop);
    ASSERT(size <= HGFS_IO_MAX); // HgfsWrite() guarantees this
 
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%u,%d,%"FMT64"u,%u)\n", handle, ioflag, offset, size);
+
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return -ret;
+      ret = -ret;
+      goto out;
    }
 
    requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
@@ -2114,7 +2176,7 @@ HgfsDoWrite(HgfsSuperInfo *sip, // IN: Superinfo pointer
 
    if (HgfsKReq_GetPayloadSize(req) != repSize) {
       DEBUG(VM_DEBUG_FAIL,
-            "HgfsDoWrite: invalid size of reply on successful reply.\n");
+            "Error: invalid size of reply on successful reply.\n");
       ret = -EPROTO;
       goto destroyOut;
    }
@@ -2123,11 +2185,11 @@ HgfsDoWrite(HgfsSuperInfo *sip, // IN: Superinfo pointer
 
    /* The write was completed successfully, so return the amount written. */
    ret = reply->actualSize;
-   DEBUG(VM_DEBUG_DONE, "wrote %d bytes.\n", ret);
 
 destroyOut:
    HgfsKReq_ReleaseRequest(sip->reqs, req);
 out:
+   DEBUG(VM_DEBUG_EXIT, "Exit(%u -> %d)\n", handle, ret);
    return ret;
 }
 
@@ -2167,11 +2229,11 @@ HgfsDelete(HgfsSuperInfo *sip,          // IN: Superinfo
    ASSERT(filename);
    ASSERT((op == HGFS_OP_DELETE_FILE_V3) || (op == HGFS_OP_DELETE_DIR_V3));
 
-   DEBUG(VM_DEBUG_ENTRY, "HgfsDelete().\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%s,%d)\n", filename, op);
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return ret;
+      goto out;
    }
 
    /* Initialize the request's contents. */
@@ -2228,11 +2290,10 @@ HgfsDelete(HgfsSuperInfo *sip,          // IN: Superinfo
       goto destroyOut;
    }
 
-   DEBUG(VM_DEBUG_DONE, "done.\n");
-
 destroyOut:
    HgfsKReq_ReleaseRequest(sip->reqs, req);
 out:
+   DEBUG(VM_DEBUG_EXIT, "Exit(%s -> %d)\n", filename, ret);
    return ret;
 }
 
@@ -2275,8 +2336,7 @@ HgfsGetNextDirEntry(HgfsSuperInfo *sip,         // IN: Superinfo pointer
    uint32 repSize;
    int ret;
 
-   DEBUG(VM_DEBUG_ENTRY,
-         "HgfsGetNextDirEntry: handle=%d, offset=%d.\n", handle, offset);
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%u,%u)\n", handle, offset);
 
    ASSERT(sip);
    ASSERT(nameOut);
@@ -2285,7 +2345,7 @@ HgfsGetNextDirEntry(HgfsSuperInfo *sip,         // IN: Superinfo pointer
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
       DEBUG(VM_DEBUG_FAIL, "couldn't get req.\n");
-      return ret;
+      goto out;
    }
 
    /*
@@ -2338,7 +2398,7 @@ HgfsGetNextDirEntry(HgfsSuperInfo *sip,         // IN: Superinfo pointer
 
    /* See if there are no more filenames to read */
    if (dirent->fileName.length <= 0) {
-      DEBUG(VM_DEBUG_DONE, "no more directory entries.\n");
+      DEBUG(VM_DEBUG_LOG, "no more directory entries.\n");
       *done = TRUE;
       ret = 0;         /* return success */
       goto destroyOut;
@@ -2363,10 +2423,10 @@ HgfsGetNextDirEntry(HgfsSuperInfo *sip,         // IN: Superinfo pointer
    *type = dirent->attr.type;
    ret = 0;
 
-   DEBUG(VM_DEBUG_DONE, "done.\n");
 destroyOut:
    HgfsKReq_ReleaseRequest(sip->reqs, req);
 out:
+   DEBUG(VM_DEBUG_EXIT, "Exit(%u -> %d)\n", handle, ret);
    return ret;
 }
 
@@ -2391,60 +2451,73 @@ int
 HgfsReadlinkInt(struct vnode *vp,   // IN : File vnode
                 struct uio *uiop)   // OUT: Attributes from hgfs server
 {
-   HgfsKReqHandle req;
+   HgfsKReqHandle req = NULL;
    int ret = 0;
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(vp));
+   HgfsReplyGetattrV3 *reply;
+   HgfsReply *replyHeader;
+   uint32 outLength;
+   char* outBuffer = NULL;
+
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp));
+
    /* This operation is valid only for symbolic links. */
    if (HGFS_VP_TO_VTYPE(vp) != VLNK) {
       DEBUG(VM_DEBUG_FAIL, "Must be a symbolic link.\n");
-      return EINVAL;
+      ret = EINVAL;
+      goto out;
    }
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
    if (!req) {
-      return ret;
+      goto out;
    }
 
    ret = HgfsQueryAttrInt(HGFS_VP_TO_FILENAME(vp), 0, sip, req);
-   if (ret == 0) {
-      HgfsReplyGetattrV3 *reply;
-      HgfsReply *replyHeader;
-      uint32 outLength;
-      char* outBuffer;
-      outLength = HGFS_UIOP_TO_RESID(uiop);
-      outBuffer = os_malloc(outLength, M_WAITOK);
-      if (outBuffer != NULL) {
-         replyHeader = (HgfsReply *)HgfsKReq_GetPayload(req);
-         reply = (HgfsReplyGetattrV3 *)HGFS_REP_GET_PAYLOAD_V3(replyHeader);
-         if (reply->symlinkTarget.name[reply->symlinkTarget.length - 1] == '\0') {
-            ret = EINVAL; // Not a well formed name
-         } else {
-            ret = HgfsNameFromWireEncoding(reply->symlinkTarget.name,
-                                           reply->symlinkTarget.length,
-                                           outBuffer, outLength);
-            if (ret >= 0) {
-               ret = uiomove(outBuffer, MIN(ret, outLength), uiop);
-               if (ret != 0) {
-                  DEBUG(VM_DEBUG_FAIL, "Failed %d copying into user buffer.\n", ret);
-               }
-            } else {
-               ret = -ret;  // HgfsNameFromWireEncoding returns negative error code
-               DEBUG(VM_DEBUG_FAIL, "Failed %d converting link from wire format.\n", ret);
-               DEBUG(VM_DEBUG_FAIL, "Link length is %d, name is %s\n",
-                     reply->symlinkTarget.length, reply->symlinkTarget.name);
-            }
-         }
-         os_free(outBuffer, outLength);
-      } else {
-         DEBUG(VM_DEBUG_FAIL, "No memory for symlink name.\n");
-         ret = ENOMEM;
-      }
-      HgfsKReq_ReleaseRequest(sip->reqs, req);
-   } else {
+   if (ret != 0) {
       DEBUG(VM_DEBUG_FAIL, "Error %d reading symlink name.\n", ret);
+      goto out;
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(vp));
+
+   outLength = HGFS_UIOP_TO_RESID(uiop);
+   outBuffer = os_malloc(outLength, M_WAITOK);
+   if (outBuffer != NULL) {
+      DEBUG(VM_DEBUG_FAIL, "No memory for symlink name.\n");
+      ret = ENOMEM;
+      goto out;
+   }
+
+   replyHeader = (HgfsReply *)HgfsKReq_GetPayload(req);
+   reply = (HgfsReplyGetattrV3 *)HGFS_REP_GET_PAYLOAD_V3(replyHeader);
+   if (reply->symlinkTarget.name[reply->symlinkTarget.length - 1] == '\0') {
+      ret = EINVAL; // Not a well formed name
+      goto out;
+   }
+
+   ret = HgfsNameFromWireEncoding(reply->symlinkTarget.name,
+                                  reply->symlinkTarget.length,
+                                  outBuffer, outLength);
+   if (ret < 0) {
+      ret = -ret;  // HgfsNameFromWireEncoding returns negative error code
+      DEBUG(VM_DEBUG_FAIL, "Error converting link wire format length is %d, name is %s\n",
+            reply->symlinkTarget.length, reply->symlinkTarget.name);
+      goto out;
+   }
+
+   ret = uiomove(outBuffer, MIN(ret, outLength), uiop);
+   if (ret != 0) {
+      DEBUG(VM_DEBUG_FAIL, "Failed %d copying into user buffer.\n", ret);
+   }
+
+out:
+   if (outBuffer != NULL) {
+      os_free(outBuffer, outLength);
+   }
+   if (req != NULL) {
+      HgfsKReq_ReleaseRequest(sip->reqs, req);
+   }
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d\n", HGFS_VP_TO_FILENAME_LENGTH(vp), HGFS_VP_TO_FILENAME(vp),
+         ret);
    return ret;
 }
 
@@ -2486,10 +2559,10 @@ HgfsSymlinkInt(struct vnode *dvp,         // IN : directory vnode
    HgfsFileNameV3 *fileNameP;
    int nameOffset;
 
-   DEBUG(VM_DEBUG_LOG, "Enter %s.\n",  HGFS_VP_TO_FILENAME(dvp));
-   DEBUG(VM_DEBUG_ENTRY, "dvp=%p (%s), dirname=%s, vpp=%p\n",
-                         dvp, HGFS_VP_TO_FILENAME(dvp), cnp->cn_nameptr,
-                         *vpp);
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s/%.*s,%s)\n",
+                         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+                         (int)cnp->cn_namelen, cnp->cn_nameptr,
+                         targetName);
 
    fullName = os_malloc(MAXPATHLEN, M_WAITOK);
    if (!fullName) {
@@ -2559,14 +2632,14 @@ HgfsSymlinkInt(struct vnode *dvp,         // IN : directory vnode
     * Currently we have different name formats for file names and for symbolic
     * link targets. Flie names are always absolute and on-wire representation does
     * not include leading path separator. HgfsNameToWireEncoding removes
-       * leading path separator from the name. However symbolic link targets may be
-       * either absolute or relative. To distinguish between them the leading path separator
-       * must be preserved for absolute symbolic link target.
-       * In the long term we should fix the protocol and have only one name
-       * format which is suitable for all names.
-       * The following code compensates for this problem before there is such
-       * universal name representation.
-       */
+    * leading path separator from the name. However symbolic link targets may be
+    * either absolute or relative. To distinguish between them the leading path separator
+    * must be preserved for absolute symbolic link target.
+    * In the long term we should fix the protocol and have only one name
+    * format which is suitable for all names.
+    * The following code compensates for this problem before there is such
+    * universal name representation.
+    */
    if (*targetName == '/') {
       fileNameP->length = 1;
       reqSize += 1;
@@ -2627,7 +2700,10 @@ out:
    if (fullName != NULL) {
       os_free(fullName, MAXPATHLEN);
    }
-   DEBUG(VM_DEBUG_LOG, "Exit %s.\n",  HGFS_VP_TO_FILENAME(dvp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s/%.*s -> %d)\n",
+         HGFS_VP_TO_FILENAME_LENGTH(dvp), HGFS_VP_TO_FILENAME(dvp),
+         (int)cnp->cn_namelen, cnp->cn_nameptr,
+         ret);
    return ret;
 }
 
@@ -2655,8 +2731,11 @@ HgfsDoGetattrByName(const char *path,       // IN : Path to get attributes for
                    HgfsSuperInfo *sip,     // IN : SuperInfo block of hgfs mount.
                    HgfsAttrV2 *hgfsAttrV2) // OUT: Attributes from hgfs server
 {
-   DEBUG(VM_DEBUG_LOG, "Trace enter.\n");
-   return HgfsDoGetattrInt(path, 0, sip, hgfsAttrV2);
+   int ret;
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%s)\n", path);
+   ret = HgfsDoGetattrInt(path, 0, sip, hgfsAttrV2);
+   DEBUG(VM_DEBUG_EXIT, "Exit(%s -> %d)\n", path, ret);
+   return ret;
 }
 
 
@@ -2684,7 +2763,10 @@ HgfsDoGetattrByHandle(HgfsHandle handle,      // IN : Hgfs handle for attr reque
                      HgfsSuperInfo *sip,     // IN : SuperInfo block for hgfs mount
                      HgfsAttrV2 *hgfsAttrV2) // OUT: Attributes from hgfs server
 {
-   return HgfsDoGetattrInt(NULL, handle, sip, hgfsAttrV2);
+   int ret;
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%u)\n", handle);
+   ret =  HgfsDoGetattrInt(NULL, handle, sip, hgfsAttrV2);
+   DEBUG(VM_DEBUG_EXIT, "Exit(%u -> %d)\n", handle, ret);
 }
 #endif
 
@@ -2719,7 +2801,7 @@ HgfsDoGetattrInt(const char *path,       // IN : Path to get attributes for
    HgfsKReqHandle req;
    int ret = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Trace enter, %s.\n", path);
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%s,%u)\n", (path != NULL ? path : "null"), handle);
    ASSERT(hgfsAttrV2);
 
    req = HgfsKReq_AllocateRequest(sip->reqs, &ret);
@@ -2738,6 +2820,7 @@ HgfsDoGetattrInt(const char *path,       // IN : Path to get attributes for
       memcpy(hgfsAttrV2, &reply->attr, sizeof *hgfsAttrV2);
       HgfsKReq_ReleaseRequest(sip->reqs, req);
    }
+   DEBUG(VM_DEBUG_EXIT, "Exit(%s,%u -> %d)\n", (path != NULL ? path : "null"), handle, ret);
    return ret;
 }
 
@@ -2779,7 +2862,7 @@ HgfsQueryAttrInt(const char *path,       // IN : Path to get attributes for
    uint32 reqBufferSize;
    int ret = 0;
 
-   DEBUG(VM_DEBUG_LOG, "Trace enter.\n");
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%s,%u)\n", (path != NULL ? path : "null"), handle);
    requestHeader = (HgfsRequest *)HgfsKReq_GetPayload(req);
    request = (HgfsRequestGetattrV3 *)HGFS_REQ_GET_PAYLOAD_V3(requestHeader);
 
@@ -2881,6 +2964,7 @@ destroyOut:
    }
 
 out:
+   DEBUG(VM_DEBUG_EXIT, "Exit(%s,%u -> %d)\n", (path != NULL ? path : "null"), handle, ret);
    return ret;
 }
 
@@ -2966,7 +3050,8 @@ HgfsAccessInt(struct vnode *vp,     // IN: Vnode to check access for
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
    HgfsAttrV2 hgfsAttrV2;
 
-   DEBUG(VM_DEBUG_ENTRY, "HgfsAccessInt is called\n");
+   DEBUG(VM_DEBUG_ENTRY, "HgfsAccessInt(%.*s,%d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), mode);
 
    ret = HgfsDoGetattrByName(HGFS_VP_TO_FILENAME(vp), sip, &hgfsAttrV2);
    if (ret == 0) {
@@ -2993,6 +3078,9 @@ HgfsAccessInt(struct vnode *vp,     // IN: Vnode to check access for
       DEBUG(VM_DEBUG_FAIL, "HgfsAccessInt failed getting attrib: %s (%d)\n",
             HGFS_VP_TO_FILENAME(vp), ret);
    }
+
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), ret);
    return ret;
 }
 
@@ -3026,7 +3114,8 @@ HgfsMmapInt(struct vnode *vp,
 
    ASSERT(fp);
 
-   DEBUG(VM_DEBUG_ENTRY, "mmapping \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s,%d)\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), accessMode);
 
    /*
     *  If the directory is already opened then we are done.
@@ -3036,7 +3125,8 @@ HgfsMmapInt(struct vnode *vp,
 
    ret = HgfsCheckAndReferenceHandle(vp, accessMode, OPENREQ_MMAP);
    os_rw_lock_unlock_exclusive(fp->handleLock);
-   DEBUG(VM_DEBUG_LOG, "Exit (%d) %s.\n", ret,  HGFS_VP_TO_FILENAME(vp));
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d).\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), ret);
    return ret;
 }
 
@@ -3061,19 +3151,23 @@ HgfsMmapInt(struct vnode *vp,
 int
 HgfsMnomapInt(struct vnode *vp)
 {
-   int error = 0;
+   int ret = 0;
    HgfsHandle handleToClose;
    HgfsSuperInfo *sip = HGFS_VP_TO_SIP(vp);
 
    ASSERT(vp);
-   DEBUG(VM_DEBUG_ENTRY, "unmmapping \"%s\"\n", HGFS_VP_TO_FILENAME(vp));
+
+   DEBUG(VM_DEBUG_ENTRY, "Enter(%.*s)\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp));
 
    /*
     * Check to see if we should close the file handle on the host, which happen when
     * the reference count of the current handle become 0.
     */
    if (HgfsReleaseOpenFileHandle(vp, OPENREQ_MMAP, &handleToClose) == 0) {
-      error = HgfsCloseServerFileHandle(sip, handleToClose);
+      ret = HgfsCloseServerFileHandle(sip, handleToClose);
    }
-   return error;
+   DEBUG(VM_DEBUG_EXIT, "Exit(%.*s -> %d).\n", HGFS_VP_TO_FILENAME_LENGTH(vp),
+         HGFS_VP_TO_FILENAME(vp), ret);
+   return ret;
 }