From: VMware, Inc <> Date: Wed, 18 Sep 2013 03:31:10 +0000 (-0700) Subject: HGFS: Improve the Linux kernel client logging X-Git-Tag: 2013.09.16-1328054~51 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e6117c29424490908f1abbbe135cbdaef66258af;p=thirdparty%2Fopen-vm-tools.git 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 --- diff --git a/open-vm-tools/modules/linux/vmhgfs/file.c b/open-vm-tools/modules/linux/vmhgfs/file.c index 06337b274..0b69be1a7 100644 --- 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 ecedb8dd6..65a3647d0 100644 --- 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 9fb95a542..8434813cd 100644 --- 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 6d8b50f2d..4aec48830 100644 --- 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;