HGFS: Improve the Linux kernel client logging

Add more logging to make tracking requests and their respective arguments
to aid debugging.

Signed-off-by: Dmitry Torokhov <dtor@vmware.com>

diff --git a/open-vm-tools/modules/linux/vmhgfs/file.c b/open-vm-tools/modules/linux/vmhgfs/file.c
index 06337b274886bd0726a5b5e27f0ffcf1d5963896..0b69be1a71892c1e8585e0929f6f7b4c685530ea 100644 (file)
--- a/open-vm-tools/modules/linux/vmhgfs/file.c
+++ b/open-vm-tools/modules/linux/vmhgfs/file.c
@@ -50,7 +50,7 @@
 /* Private functions. */
 static int HgfsPackOpenRequest(struct inode *inode,
                                struct file *file,
-                              HgfsOp opUsed,
+                               HgfsOp opUsed,
                                HgfsReq *req);
 static int HgfsUnpackOpenReply(HgfsReq *req,
                                HgfsOp opUsed,
@@ -178,7 +178,7 @@ struct file_operations HgfsFileFileOperations = {
 static int
 HgfsPackOpenRequest(struct inode *inode, // IN: Inode of the file to open
                     struct file *file,   // IN: File pointer for this open
-                   HgfsOp opUsed,       // IN: Op to use
+                    HgfsOp opUsed,       // IN: Op to use
                     HgfsReq *req)        // IN/OUT: Packet to write into
 {
    char *name;
@@ -231,6 +231,8 @@ HgfsPackOpenRequest(struct inode *inode, // IN: Inode of the file to open
       }
       requestV3->flags = result;
 
+      LOG(4, (KERN_DEBUG "VMware hgfs: %s: mode file %o inode %o -> user %o\n",
+              __func__, file->f_mode, inode->i_mode, (inode->i_mode & S_IRWXU) >> 6));
       /* Set permissions. */
       requestV3->specialPerms = (inode->i_mode & (S_ISUID | S_ISGID | S_ISVTX))
                                 >> 9;
@@ -564,6 +566,10 @@ HgfsOpen(struct inode *inode,  // IN: Inode of the file to open
 
    iinfo = INODE_GET_II_P(inode);
 
+   LOG(4, (KERN_DEBUG "VMware hgfs: %s: open file(%s/%s)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name));
+
    req = HgfsGetNewRequest();
    if (!req) {
       LOG(4, (KERN_DEBUG "VMware hgfs: HgfsOpen: out of memory while "
@@ -748,15 +754,21 @@ HgfsAioRead(struct kiocb *iocb,      // IN:  I/O control block
             loff_t offset)           // IN:  Offset at which to read
 {
    int result;
+   struct dentry *readDentry;
 
    ASSERT(iocb);
    ASSERT(iocb->ki_filp);
    ASSERT(iocb->ki_filp->f_dentry);
    ASSERT(iov);
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsAioRead: was called\n"));
+   readDentry = iocb->ki_filp->f_dentry;
 
-   result = HgfsRevalidate(iocb->ki_filp->f_dentry);
+   LOG(4, (KERN_DEBUG "VMware hgfs: %s: (%s/%s, %lu@%lu)\n",
+           __func__, readDentry->d_parent->d_name.name,
+           readDentry->d_name.name,
+           (unsigned long) iov_length(iov, numSegs), (unsigned long) offset));
+
+   result = HgfsRevalidate(readDentry);
    if (result) {
       LOG(4, (KERN_DEBUG "VMware hgfs: HgfsAioRead: invalid dentry\n"));
       goto out;
@@ -797,15 +809,21 @@ HgfsAioWrite(struct kiocb *iocb,      // IN:  I/O control block
              loff_t offset)           // IN:  Offset at which to read
 {
    int result;
+   struct dentry *writeDentry;
 
    ASSERT(iocb);
    ASSERT(iocb->ki_filp);
    ASSERT(iocb->ki_filp->f_dentry);
    ASSERT(iov);
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsAioWrite: was called\n"));
+   writeDentry = iocb->ki_filp->f_dentry;
+
+   LOG(4, (KERN_DEBUG "VMware hgfs: %s: (%s/%s, %lu@%Ld)\n",
+          __func__, writeDentry->d_parent->d_name.name,
+          writeDentry->d_name.name,
+          (unsigned long) iov_length(iov, numSegs), (long long) offset));
 
-   result = HgfsRevalidate(iocb->ki_filp->f_dentry);
+   result = HgfsRevalidate(writeDentry);
    if (result) {
       LOG(4, (KERN_DEBUG "VMware hgfs: HgfsAioWrite: invalid dentry\n"));
       goto out;
@@ -850,8 +868,9 @@ HgfsRead(struct file *file,  // IN:  File to read from
    ASSERT(buf);
    ASSERT(offset);
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsRead: read %Zu bytes from fh %u "
-           "at offset %Lu\n", count, FILE_GET_FI_P(file)->handle, *offset));
+   LOG(4, (KERN_DEBUG "VMware hgfs: %s: (%s/%s,%Zu@%lld)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name, count, (long long) *offset));
 
    result = HgfsRevalidate(file->f_dentry);
    if (result) {
@@ -901,8 +920,9 @@ HgfsWrite(struct file *file,      // IN: File to write to
    ASSERT(buf);
    ASSERT(offset);
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsWrite: write %Zu bytes to fh %u "
-           "at offset %Lu\n", count, FILE_GET_FI_P(file)->handle, *offset));
+   LOG(4, (KERN_DEBUG "VMware hgfs: %s: (%s/%s,%Zu@%lld)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name, count, (long long) *offset));
 
    result = HgfsRevalidate(file->f_dentry);
    if (result) {
@@ -994,14 +1014,14 @@ HgfsSeek(struct file *file,  // IN:  File to seek
  */
 
 static int
-HgfsFsync(struct file *file,           // IN: File we operate on
+HgfsFsync(struct file *file,            // IN: File we operate on
 #if defined VMW_FSYNC_OLD
           struct dentry *dentry,        // IN: Dentry for this file
 #elif defined VMW_FSYNC_31
           loff_t start,                 // IN: start of range to sync
           loff_t end,                   // IN: end of range to sync
 #endif
-          int datasync)                        // IN: fdatasync or fsync
+          int datasync)                 // IN: fdatasync or fsync
 {
    LOG(6, (KERN_DEBUG "VMware hgfs: HgfsFsync: was called\n"));
 
@@ -1029,8 +1049,8 @@ HgfsFsync(struct file *file,              // IN: File we operate on
  */
 
 static int
-HgfsMmap(struct file *file,            // IN: File we operate on
-         struct vm_area_struct *vma)   // IN/OUT: VM area information
+HgfsMmap(struct file *file,            // IN: File we operate on
+         struct vm_area_struct *vma)   // IN/OUT: VM area information
 {
    int result;
 

diff --git a/open-vm-tools/modules/linux/vmhgfs/fsutil.c b/open-vm-tools/modules/linux/vmhgfs/fsutil.c
index ecedb8dd62f79e8e9921cb6a8d2fb9a2822dd142..65a3647d0751974c0cf5fe04fb86b655c6fe78c3 100644 (file)
--- a/open-vm-tools/modules/linux/vmhgfs/fsutil.c
+++ b/open-vm-tools/modules/linux/vmhgfs/fsutil.c
@@ -222,6 +222,8 @@ HgfsUnpackGetattrReply(HgfsReq *req,        // IN: Reply packet
          memcpy(*fileName, name, length);
          CPNameLite_ConvertFrom(*fileName, length, '/');
          (*fileName)[length] = '\0';
+         LOG(4, (KERN_DEBUG "VMware hgfs: %s: symlink name %s\n",
+                 __func__, *fileName));
       } else {
          *fileName = NULL;
       }
@@ -782,9 +784,10 @@ HgfsPrivateGetattr(struct dentry *dentry,  // IN: Dentry containing name
 
    result = HgfsSendRequest(req);
    if (result == 0) {
-      LOG(6, (KERN_DEBUG "VMware hgfs: HgfsPrivateGetattr: got reply\n"));
       replyStatus = HgfsReplyStatus(req);
       result = HgfsStatusConvertToLinux(replyStatus);
+      LOG(6, (KERN_DEBUG "VMware hgfs: %s: reply status %d -> %d\n",
+              __func__, replyStatus, result));
 
       /*
        * If the getattr succeeded on the server, copy the stats

diff --git a/open-vm-tools/modules/linux/vmhgfs/link.c b/open-vm-tools/modules/linux/vmhgfs/link.c
index 9fb95a542d14ac765576a09e1b42bc9a1725cf5b..8434813cd69261eb88cb6cbe0c1c4cb9d0ab2f63 100644 (file)
--- a/open-vm-tools/modules/linux/vmhgfs/link.c
+++ b/open-vm-tools/modules/linux/vmhgfs/link.c
@@ -99,9 +99,11 @@ HgfsFollowlink(struct dentry *dentry, // IN: Dentry containing link
       goto out;
    }
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsFollowlink: calling "
-           "HgfsPrivateGetattr\n"));
+   LOG(6, (KERN_DEBUG "VMware hgfs: %s: calling HgfsPrivateGetattr %s\n",
+           __func__, dentry->d_name.name));
    error = HgfsPrivateGetattr(dentry, &attr, &fileName);
+   LOG(6, (KERN_DEBUG "VMware hgfs: %s: HgfsPrivateGetattr %s ret %d\n",
+           __func__, dentry->d_name.name, error));
    if (!error) {
 
       /* Let's make sure we got called on a symlink. */
@@ -110,9 +112,11 @@ HgfsFollowlink(struct dentry *dentry, // IN: Dentry containing link
                  "on something that wasn't a symlink\n"));
          error = -EINVAL;
       } else {
-         LOG(6, (KERN_DEBUG "VMware hgfs: HgfsFollowlink: calling "
-                 "vfs_follow_link\n"));
+         LOG(6, (KERN_DEBUG "VMware hgfs: %s: calling vfs_follow_link %s\n",
+                 __func__, fileName));
          error = vfs_follow_link(nd, fileName);
+         LOG(6, (KERN_DEBUG "VMware hgfs: %s: vfs_follow_link %s ret %d\n",
+                 __func__, fileName, error));
       }
       kfree(fileName);
    }
@@ -161,8 +165,8 @@ HgfsReadlink(struct dentry *dentry,  // IN:  Dentry containing link
       return -EINVAL;
    }
 
-   LOG(6, (KERN_DEBUG "VMware hgfs: HgfsReadlink: calling "
-           "HgfsPrivateGetattr\n"));
+   LOG(6, (KERN_DEBUG "VMware hgfs: %s: calling HgfsPrivateGetattr %s\n",
+           __func__, dentry->d_name.name));
    error = HgfsPrivateGetattr(dentry, &attr, &fileName);
    if (!error) {
 
@@ -172,9 +176,11 @@ HgfsReadlink(struct dentry *dentry,  // IN:  Dentry containing link
                  "on something that wasn't a symlink\n"));
          error = -EINVAL;
       } else {
-         LOG(6, (KERN_DEBUG "VMware hgfs: HgfsReadlink: calling "
-                 "vfs_readlink\n"));
+         LOG(6, (KERN_DEBUG "VMware hgfs: %s: calling vfs_readlink %s\n",
+                 __func__, fileName));
          error = vfs_readlink(dentry, buffer, buflen, fileName);
+         LOG(6, (KERN_DEBUG "VMware hgfs: %s: vfs_readlink %s ret %dn",
+                 __func__, fileName, error));
       }
       kfree(fileName);
    }

diff --git a/open-vm-tools/modules/linux/vmhgfs/page.c b/open-vm-tools/modules/linux/vmhgfs/page.c
index 6d8b50f2dda9fe670ded2c38153d560ec9abbbaf..4aec48830c4b052bca9915033052206d16349488 100644 (file)
--- a/open-vm-tools/modules/linux/vmhgfs/page.c
+++ b/open-vm-tools/modules/linux/vmhgfs/page.c
@@ -667,6 +667,8 @@ HgfsDoWritepage(HgfsHandle handle,  // IN: Handle to use for writing
    ASSERT(page->mapping->host);
    inode = page->mapping->host;
 
+   LOG(4, (KERN_WARNING "VMware hgfs: %s: start writes at %Lu\n",
+           __func__, curOffset));
    /*
     * Call HgfsDoWrite repeatedly until either
     * - HgfsDoWrite returns an error, or
@@ -681,8 +683,8 @@ HgfsDoWritepage(HgfsHandle handle,  // IN: Handle to use for writing
       dataPacket[0].len = nextCount;
       result = HgfsDoWrite(handle, dataPacket, 1, curOffset);
       if (result < 0) {
-         LOG(4, (KERN_WARNING "VMware hgfs: HgfsDoWritepage: write error %d\n",
-                 result));
+         LOG(4, (KERN_WARNING "VMware hgfs: %s: write error %d\n",
+                 __func__, result));
          goto out;
       }
       remainingCount -= result;
@@ -696,6 +698,8 @@ HgfsDoWritepage(HgfsHandle handle,  // IN: Handle to use for writing
    } while ((result > 0) && (remainingCount > 0));
 
    result = 0;
+   LOG(4, (KERN_WARNING "VMware hgfs: %s: end writes at %Lu rem %zu\n",
+           __func__, curOffset, remainingCount));
 
   out:
    return result;
@@ -887,6 +891,8 @@ HgfsDoWriteBegin(struct page *page,         // IN: Page to be written
    offset = (loff_t)page->index << PAGE_CACHE_SHIFT;
    currentFileSize = compat_i_size_read(page->mapping->host);
 
+   LOG(6, (KERN_DEBUG "VMware hgfs: %s: file size %Lu off %Lu: %u to %u\n", __func__,
+           currentFileSize, offset, pageFrom, pageTo));
    /*
     * If we are doing a partial write into a new page (beyond end of
     * file), then intialize it. This allows other writes to this page
@@ -975,6 +981,11 @@ HgfsWriteBegin(struct file *file,             // IN: File to be written
    unsigned pageTo = pos + len;
    struct page *page;
 
+   LOG(6, (KERN_WARNING "VMware hgfs: %s: (%s/%s(%ld), %u@%lld)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name,
+           mapping->host->i_ino, len, (long long) pos));
+
    page = compat_grab_cache_page_write_begin(mapping, index, flags);
    if (page == NULL) {
       return -ENOMEM;
@@ -1025,6 +1036,11 @@ HgfsDoWriteEnd(struct file *file, // IN: File we're writing to
    currentFileSize = compat_i_size_read(inode);
    offset = (loff_t)page->index << PAGE_CACHE_SHIFT;
 
+   LOG(6, (KERN_WARNING "VMware hgfs: %s: (%s/%s(%ld), from %u to %u@%lld => %u)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name,
+           page->mapping->host->i_ino, pageFrom, pageTo, (long long) writeTo, copied));
+
    if (writeTo > currentFileSize) {
       compat_i_size_write(inode, writeTo);
    }
@@ -1151,6 +1167,12 @@ HgfsWriteEnd(struct file *file,              // IN: File to write
    ASSERT(mapping);
    ASSERT(page);
 
+
+   LOG(6, (KERN_WARNING "VMware hgfs: %s: (%s/%s(%ld), %u@%lld,=>%u)\n",
+           __func__, file->f_dentry->d_parent->d_name.name,
+           file->f_dentry->d_name.name,
+           mapping->host->i_ino, len, (long long) pos, copied));
+
    ret = HgfsDoWriteEnd(file, page, pageFrom, pageTo, writeTo, copied);
    if (ret == 0) {
       ret = copied;