The branch, master has been updated
via 5cab6a9be79 vfs_ceph_new: Enhance logging for improved debugging
and code flow visibility (part 2)
from b5bd36dfd7d lib/krb5_wrap: Fix placement of TALLOC_FREE(frame)
https://git.samba.org/?p=samba.git;a=shortlog;h=master
- Log -----------------------------------------------------------------
commit 5cab6a9be79c846202bfa7c617eb4f956bea0d0b
Author: Shweta Sodani <[email protected]>
Date: Fri Feb 14 20:29:17 2025 +0530
vfs_ceph_new: Enhance logging for improved debugging and code flow
visibility (part 2)
This commit introduces significant enhancements to our logging system to
improve debugging capabilities and provide better visibility into the
code's execution flow.
This is part 2 for logging improvement. There have already been some
logging improvements done in the past.
https://gitlab.com/samba-team/samba/-/merge_requests/3948
This commit includes following key changes.
Expanded a logging message
1) Every function entry and exit point.
2) Error Path / Error handling blocks.
3) Key decision branches (if/else statements).
Consistent logging.
1) Logging message to print either the file/dir name its
feasible.
2) Standardized log message formatting to ensure consistency and
readability. This makes it easier to scan and understand log
output.
Impact
This enhancement will reduce the time required to diagnose and resolve
issues. It will provide valuable insights into the system's behavior,
enabling us to optimize performance and improve user experience.
Signed-off-by: Shweta Sodani <[email protected]>
Reviewed-by: Anoop C S <[email protected]>
Reviewed-by: Guenther Deschner <[email protected]>
Autobuild-User(master): Anoop C S <[email protected]>
Autobuild-Date(master): Mon Apr 28 07:04:15 UTC 2025 on atb-devel-224
-----------------------------------------------------------------------
Summary of changes:
source3/modules/vfs_ceph_new.c | 265 +++++++++++++++++++++++------------------
1 file changed, 151 insertions(+), 114 deletions(-)
Changeset truncated at 500 lines:
diff --git a/source3/modules/vfs_ceph_new.c b/source3/modules/vfs_ceph_new.c
index 65a43b310ca..17f20ed2d6b 100644
--- a/source3/modules/vfs_ceph_new.c
+++ b/source3/modules/vfs_ceph_new.c
@@ -742,6 +742,7 @@ static int vfs_ceph_add_fh(struct vfs_handle_struct *handle,
struct cephmount_cached *cme = NULL;
struct UserPerm *uperm = NULL;
struct vfs_ceph_config *config = NULL;
+ int ret = 0;
SMB_VFS_HANDLE_GET_DATA(handle, config, struct vfs_ceph_config,
return -ENOMEM);
@@ -750,7 +751,8 @@ static int vfs_ceph_add_fh(struct vfs_handle_struct *handle,
uperm = vfs_ceph_userperm_new(config, handle->conn);
if (uperm == NULL) {
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
*out_cfh = VFS_ADD_FSP_EXTENSION(handle,
@@ -759,14 +761,18 @@ static int vfs_ceph_add_fh(struct vfs_handle_struct
*handle,
vfs_ceph_fsp_ext_destroy_cb);
if (*out_cfh == NULL) {
vfs_ceph_userperm_del(config, uperm);
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
(*out_cfh)->cme = cme;
(*out_cfh)->uperm = uperm;
(*out_cfh)->fsp = fsp;
(*out_cfh)->config = config;
(*out_cfh)->fd = -1;
- return 0;
+out:
+ DBG_DEBUG("[CEPH] vfs_ceph_add_fh: name = %s ret = %d\n",
+ fsp->fsp_name->base_name, ret);
+ return ret;
}
static void vfs_ceph_remove_fh(struct vfs_handle_struct *handle,
@@ -779,16 +785,24 @@ static int vfs_ceph_fetch_fh(struct vfs_handle_struct
*handle,
const struct files_struct *fsp,
struct vfs_ceph_fh **out_cfh)
{
+ int ret = 0;
*out_cfh = VFS_FETCH_FSP_EXTENSION(handle, fsp);
- return (*out_cfh == NULL) ? -EBADF : 0;
+ ret = (*out_cfh == NULL) ? -EBADF : 0;
+ DBG_DEBUG("[CEPH] vfs_ceph_fetch_fh: name = %s ret = %d\n",
+ fsp->fsp_name->base_name, ret);
+ return ret;
}
static int vfs_ceph_fetch_io_fh(struct vfs_handle_struct *handle,
const struct files_struct *fsp,
struct vfs_ceph_fh **out_cfh)
{
+ int ret = 0;
*out_cfh = VFS_FETCH_FSP_EXTENSION(handle, fsp);
- return (*out_cfh == NULL) || ((*out_cfh)->fh == NULL) ? -EBADF : 0;
+ ret = (*out_cfh == NULL) || ((*out_cfh)->fh == NULL) ? -EBADF : 0;
+ DBG_DEBUG("[CEPH] vfs_ceph_fetch_io_fh: name = %s ret = %d\n",
+ fsp->fsp_name->base_name, ret);
+ return ret;
}
static void vfs_ceph_assign_fh_fd(struct vfs_ceph_fh *cfh)
@@ -891,7 +905,7 @@ static int vfs_ceph_ll_getattr2(const struct
vfs_handle_struct *handle,
smb_stat_from_ceph_statx(st, &stx);
}
DBG_DEBUG("[CEPH] ceph_ll_getattr: ino=%" PRIu64 "ret=%d\n",
- iref->ino, ret);
+ iref->ino, ret);
return ret;
}
@@ -942,7 +956,7 @@ static int vfs_ceph_ll_chown(struct vfs_handle_struct
*handle,
CEPH_STATX_UID | CEPH_STATX_GID,
uperm);
vfs_ceph_userperm_del(config, uperm);
- DBG_DEBUG("[CEPH] ceph_ll_setattr: ret=%d\n", ret);
+ DBG_DEBUG("[CEPH] ceph_ll_setattr: ino=%" PRIu64 " ret=%d\n",
iref->ino, ret);
return ret;
}
@@ -1154,10 +1168,7 @@ static int vfs_ceph_ll_create(const struct
vfs_handle_struct *handle,
0,
cfh->uperm);
if (ret != 0) {
- DBG_ERR("[CEPH] Error occurred while creating a file:"
- " name=%s mode=%o ret=%d\n",
- name, mode, ret);
- return ret;
+ goto out;
}
cfh->iref.inode = inode;
@@ -1167,7 +1178,12 @@ static int vfs_ceph_ll_create(const struct
vfs_handle_struct *handle,
cfh->o_flags = oflags;
vfs_ceph_assign_fh_fd(cfh);
- return 0;
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_create: parent-ino=%" PRIu64
+ " ino=%" PRIu64 " name=%s mode=%o ret=%d",
+ parent->ino, cfh->iref.ino, name, mode, ret);
+
+ return ret;
}
static int vfs_ceph_ll_lookup(const struct vfs_handle_struct *handle,
@@ -1211,7 +1227,7 @@ static int vfs_ceph_ll_lookup(const struct
vfs_handle_struct *handle,
iref->owner = true;
out:
DBG_DEBUG("[CEPH] ceph_ll_lookup: parent-ino=%" PRIu64 " name=%s
ret=%d\n",
- parent->ino, name, ret);
+ parent->ino, name, ret);
return ret;
}
@@ -1241,12 +1257,15 @@ static int vfs_ceph_ll_lookup2(const struct
vfs_handle_struct *handle,
0,
parent_fh->uperm);
if (ret != 0) {
- return ret;
+ goto out;
}
iref->inode = inode;
iref->ino = stx->stx_ino;
iref->owner = true;
- return 0;
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_lookup: parent-ino=%" PRIu64 " name=%s
ret=%d\n",
+ parent_fh->iref.ino, name, ret);
+ return ret;
}
static int vfs_ceph_ll_lookupat(const struct vfs_handle_struct *handle,
@@ -1307,6 +1326,8 @@ static int vfs_ceph_ll_open(const struct
vfs_handle_struct *handle,
cfh->o_flags = flags;
vfs_ceph_assign_fh_fd(cfh);
}
+ DBG_DEBUG("[CEPH] ceph_ll_open: ino=%" PRIu64 " flags=0x%x ret=%d\n",
+ cfh->iref.ino, flags, ret);
return ret;
}
@@ -1382,13 +1403,15 @@ static int vfs_ceph_ll_mkdirat(const struct
vfs_handle_struct *handle,
0,
dircfh->uperm);
if (ret != 0) {
- DBG_ERR("[CEPH] error occurred while creating dir: "
- "name=%s mode=%o ret=%d\n", name, mode, ret);
- return ret;
+ goto out;
}
iref->inode = inode;
iref->ino = stx.stx_ino;
iref->owner = true;
+
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_mkdir: parent-ino=%" PRIu64 " name=%s "
+ "mode=%o ret=%d\n", dircfh->iref.ino, name, mode, ret);
return ret;
}
@@ -1455,12 +1478,15 @@ static int vfs_ceph_ll_symlinkat(const struct
vfs_handle_struct *handle,
0,
dircfh->uperm);
if (ret != 0) {
- return ret;
+ goto out;
}
out_iref->inode = inode;
out_iref->ino = stx.stx_ino;
out_iref->owner = true;
- return 0;
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_symlink: parent-ino=%" PRIu64 " name=%s\n",
+ dircfh->iref.ino, name);
+ return ret;
}
static int vfs_ceph_ll_readlinkat(const struct vfs_handle_struct *handle,
@@ -1683,7 +1709,8 @@ static int vfs_ceph_ll_getxattr(const struct
vfs_handle_struct *handle,
uperm = vfs_ceph_userperm_new(config, handle->conn);
if (uperm == NULL) {
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
ret = config->ceph_ll_getxattr_fn(config->mount,
@@ -1695,6 +1722,9 @@ static int vfs_ceph_ll_getxattr(const struct
vfs_handle_struct *handle,
vfs_ceph_userperm_del(config, uperm);
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_getxattr: ino=%" PRIu64 " name=%s ret=%d\n",
+ iref->ino, name, ret);
return ret;
}
@@ -1739,7 +1769,8 @@ static int vfs_ceph_ll_setxattr(const struct
vfs_handle_struct *handle,
uperm = vfs_ceph_userperm_new(config, handle->conn);
if (uperm == NULL) {
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
ret = config->ceph_ll_setxattr_fn(config->mount,
@@ -1751,6 +1782,9 @@ static int vfs_ceph_ll_setxattr(const struct
vfs_handle_struct *handle,
uperm);
vfs_ceph_userperm_del(config, uperm);
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_setxattr: ino=%" PRIu64 " name=%s "
+ "size=%zu ret=%d\n", iref->ino, name, size, ret);
return ret;
}
@@ -1796,7 +1830,8 @@ static int vfs_ceph_ll_listxattr(const struct
vfs_handle_struct *handle,
uperm = vfs_ceph_userperm_new(config, handle->conn);
if (uperm == NULL) {
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
ret = config->ceph_ll_listxattr_fn(config->mount,
@@ -1807,7 +1842,8 @@ static int vfs_ceph_ll_listxattr(const struct
vfs_handle_struct *handle,
uperm);
vfs_ceph_userperm_del(config, uperm);
-
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_listxattr: ino=%" PRIu64 " ret=%d\n",
iref->ino, ret);
return ret;
}
@@ -1848,14 +1884,17 @@ static int vfs_ceph_ll_removexattr(const struct
vfs_handle_struct *handle,
uperm = vfs_ceph_userperm_new(config, handle->conn);
if (uperm == NULL) {
- return -ENOMEM;
+ ret = -ENOMEM;
+ goto out;
}
ret = config->ceph_ll_removexattr_fn(config->mount, iref->inode,
name, uperm);
vfs_ceph_userperm_del(config, uperm);
-
+out:
+ DBG_DEBUG("[CEPH] ceph_ll_removexattr: ino=%" PRIu64 " name=%s
ret=%d\n",
+ iref->ino, name, ret);
return ret;
}
@@ -1918,13 +1957,14 @@ static int vfs_ceph_iget(const struct vfs_handle_struct
*handle,
CEPH_STATX_INO,
flags);
if (ret != 0) {
- return ret;
+ goto out;
}
iref->inode = inode;
iref->ino = stx.stx_ino;
iref->owner = true;
- DBG_DEBUG("[CEPH] iget: %s ino=%" PRIu64 "\n", name, iref->ino);
- return 0;
+out:
+ DBG_DEBUG("[CEPH] iget: %s ino=%" PRIu64 " ret=%d\n", name, iref->ino,
ret);
+ return ret;
}
static int vfs_ceph_igetd(struct vfs_handle_struct *handle,
@@ -1989,14 +2029,16 @@ static uint64_t vfs_ceph_disk_free(struct
vfs_handle_struct *handle,
ret = config->ceph_ll_lookup_root_fn(config->mount, &inode);
if (ret != 0) {
- DBG_DEBUG("[CEPH] ceph_ll_lookup_root returned %d\n", ret);
+ DBG_DEBUG("[CEPH] disk_free: ceph_ll_lookup_root returned
ret=%d\n",
+ ret);
errno = -ret;
return (uint64_t)(-1);
}
ret = config->ceph_ll_statfs_fn(config->mount, inode, &statvfs_buf);
config->ceph_ll_put_fn(config->mount, inode);
if (ret != 0) {
- DBG_DEBUG("[CEPH] ceph_ll_statfs returned %d\n", ret);
+ DBG_DEBUG("[CEPH] disk_free: ceph_ll_statfs returned ino=%p"
+ " ret=%d\n", inode, ret);
errno = -ret;
return (uint64_t)(-1);
}
@@ -2112,8 +2154,9 @@ static int vfs_ceph_statvfs(struct vfs_handle_struct
*handle,
statbuf->FsIdentifier = statvfs_buf.f_fsid;
statbuf->FsCapabilities = caps;
- DBG_DEBUG("[CEPH] f_bsize: %ld, f_blocks: %ld, f_bfree: %ld, "
+ DBG_DEBUG("[CEPH] name: %s f_bsize: %ld, f_blocks: %ld, f_bfree: %ld, "
"f_bavail: %ld\n",
+ smb_fname->base_name,
(long int)statvfs_buf.f_bsize,
(long int)statvfs_buf.f_blocks,
(long int)statvfs_buf.f_bfree,
@@ -2144,7 +2187,7 @@ static DIR *vfs_ceph_fdopendir(struct vfs_handle_struct
*handle,
struct vfs_ceph_fh *cfh = NULL;
START_PROFILE(syscall_fdopendir);
- DBG_DEBUG("[CEPH] fdopendir(%p, %p)\n", handle, fsp);
+ DBG_DEBUG("[CEPH] fdopendir: name=%s\n", fsp->fsp_name->base_name);
ret = vfs_ceph_fetch_fh(handle, fsp, &cfh);
if (ret != 0) {
goto out;
@@ -2156,7 +2199,8 @@ static DIR *vfs_ceph_fdopendir(struct vfs_handle_struct
*handle,
}
result = &cfh->dirp;
out:
- DBG_DEBUG("[CEPH] fdopendir(...) = %d\n", ret);
+ DBG_DEBUG("[CEPH] fdopendir: handle=%p name=%s ret=%d\n",
+ handle, fsp->fsp_name->base_name, ret);
if (ret != 0) {
errno = -ret;
}
@@ -2174,7 +2218,7 @@ static struct dirent *vfs_ceph_readdir(struct
vfs_handle_struct *handle,
int ret = -1;
START_PROFILE(syscall_readdir);
- DBG_DEBUG("[CEPH] readdir(%p, %p)\n", handle, dirp);
+ DBG_DEBUG("[CEPH] readdir: name=%s\n", dirfsp->fsp_name->base_name);
result = vfs_ceph_get_fh_dirent(dircfh);
if (result == NULL) {
@@ -2186,7 +2230,6 @@ static struct dirent *vfs_ceph_readdir(struct
vfs_handle_struct *handle,
ret = vfs_ceph_ll_readdir(handle, dircfh);
if (ret < 0) {
/* Error case */
- DBG_DEBUG("[CEPH] readdir(...) = %d\n", ret);
vfs_ceph_put_fh_dirent(dircfh);
result = NULL;
saved_errno = ret;
@@ -2196,10 +2239,12 @@ static struct dirent *vfs_ceph_readdir(struct
vfs_handle_struct *handle,
result = NULL;
} else {
/* Normal case */
- DBG_DEBUG("[CEPH] readdir(...) = %p\n", result);
+ DBG_DEBUG("[CEPH] readdir: dirp=%p result=%p\n", dirp, result);
}
errno = saved_errno;
out:
+ DBG_DEBUG("[CEPH] readdir: handle=%p name=%s ret=%d\n",
+ handle, dirfsp->fsp_name->base_name, ret);
END_PROFILE(syscall_readdir);
return result;
}
@@ -2209,7 +2254,7 @@ static void vfs_ceph_rewinddir(struct vfs_handle_struct
*handle, DIR *dirp)
const struct vfs_ceph_fh *dircfh = (const struct vfs_ceph_fh *)dirp;
START_PROFILE(syscall_rewinddir);
- DBG_DEBUG("[CEPH] rewinddir(%p, %p)\n", handle, dirp);
+ DBG_DEBUG("[CEPH] rewinddir: handle=%p dirp=%p\n", handle, dirp);
vfs_ceph_ll_rewinddir(handle, dircfh);
END_PROFILE(syscall_rewinddir);
}
@@ -2225,7 +2270,7 @@ static int vfs_ceph_mkdirat(struct vfs_handle_struct
*handle,
struct vfs_ceph_iref iref = {0};
START_PROFILE(syscall_mkdirat);
- DBG_DEBUG("[CEPH] mkdirat(%p, %s)\n", handle, name);
+ DBG_DEBUG("[CEPH] mkdirat: handle=%p name=%s\n", handle, name);
result = vfs_ceph_fetch_fh(handle, dirfsp, &dircfh);
if (result != 0) {
goto out;
@@ -2234,7 +2279,7 @@ static int vfs_ceph_mkdirat(struct vfs_handle_struct
*handle,
result = vfs_ceph_ll_mkdirat(handle, dircfh, name, mode, &iref);
vfs_ceph_iput(handle, &iref);
out:
- DBG_DEBUG("[CEPH] mkdirat(...) = %d\n", result);
+ DBG_DEBUG("[CEPH] mkdirat: name=%s result=%d\n", name, result);
END_PROFILE(syscall_mkdirat);
return status_code(result);
}
@@ -2245,11 +2290,11 @@ static int vfs_ceph_closedir(struct vfs_handle_struct
*handle, DIR *dirp)
struct vfs_ceph_fh *cfh = (struct vfs_ceph_fh *)dirp;
START_PROFILE(syscall_closedir);
- DBG_DEBUG("[CEPH] closedir(%p, %p)\n", handle, dirp);
+ DBG_DEBUG("[CEPH] closedir: handle=%p dirp=%p\n", handle, dirp);
result = vfs_ceph_ll_releasedir(handle, cfh);
vfs_ceph_release_fh(cfh);
vfs_ceph_remove_fh(handle, cfh->fsp);
- DBG_DEBUG("[CEPH] closedir(...) = %d\n", result);
+ DBG_DEBUG("[CEPH] closedir: dirp=%p result=%d\n", dirp, result);
END_PROFILE(syscall_closedir);
return status_code(result);
}
@@ -2284,8 +2329,7 @@ static int vfs_ceph_openat(struct vfs_handle_struct
*handle,
flags |= O_PATH;
}
#endif
-
- DBG_DEBUG("[CEPH] openat(%p, %p, %d, %d)\n", handle, fsp, flags, mode);
+ DBG_DEBUG("[CEPH] openat: handle=%p fsp=%p flags=%d mode=%d\n", handle,
fsp, flags, mode);
result = vfs_ceph_igetd(handle, dirfsp, &diref);
if (result != 0) {
@@ -2342,7 +2386,8 @@ out:
vfs_ceph_iput(handle, &diref);
fsp->fsp_flags.have_proc_fds = false;
err_out:
- DBG_DEBUG("[CEPH] open(...) = %d\n", result);
+ DBG_DEBUG("[CEPH] openat: name=%s result=%d",
+ fsp->fsp_name->base_name, result);
END_PROFILE(syscall_openat);
return status_code(result);
}
@@ -2353,7 +2398,6 @@ static int vfs_ceph_close(struct vfs_handle_struct
*handle, files_struct *fsp)
struct vfs_ceph_fh *cfh = NULL;
START_PROFILE(syscall_close);
- DBG_DEBUG("[CEPH] close(%p, %p)\n", handle, fsp);
result = vfs_ceph_fetch_fh(handle, fsp, &cfh);
if (result != 0) {
goto out;
@@ -2362,7 +2406,8 @@ static int vfs_ceph_close(struct vfs_handle_struct
*handle, files_struct *fsp)
result = vfs_ceph_release_fh(cfh);
vfs_ceph_remove_fh(handle, fsp);
out:
- DBG_DEBUG("[CEPH] close(...) = %d\n", result);
+ DBG_DEBUG("[CEPH] close: handle=%p name=%s result=%d\n",
+ handle, fsp->fsp_name->base_name, result);
END_PROFILE(syscall_close);
return status_code(result);
}
@@ -2377,13 +2422,6 @@ static ssize_t vfs_ceph_pread(struct vfs_handle_struct
*handle,
ssize_t result;
START_PROFILE_BYTES(syscall_pread, n);
- DBG_DEBUG("[CEPH] pread(%p, %p, %p, %zu, %jd)\n",
- handle,
- fsp,
- data,
- n,
- (intmax_t)offset);
-
result = vfs_ceph_fetch_io_fh(handle, fsp, &cfh);
if (result != 0) {
goto out;
@@ -2391,7 +2429,13 @@ static ssize_t vfs_ceph_pread(struct vfs_handle_struct
*handle,
result = vfs_ceph_ll_read(handle, cfh, offset, n, data);
out:
- DBG_DEBUG("[CEPH] pread(...) = %zd\n", result);
+ DBG_DEBUG("[CEPH] pread: handle=%p name=%s n=%" PRIu64 "offset=%" PRIu64
+ " result=%" PRIu64 "\n",
+ handle,
+ fsp->fsp_name->base_name,
+ n,
+ (intmax_t)offset,
+ result);
END_PROFILE_BYTES(syscall_pread);
return lstatus_code(result);
}
@@ -2508,7 +2552,7 @@ static void vfs_ceph_aio_submit(struct vfs_handle_struct
*handle,
req, struct vfs_ceph_aio_state);
int64_t res;
- DBG_DEBUG("[CEPH] aio_send: ino=%" PRIu64 "fd=%d off=%jd len=%ju\n",
+ DBG_DEBUG("[CEPH] aio_send: ino=%" PRIu64 " fd=%d off=%jd len=%ju\n",
state->cfh->iref.ino,
state->cfh->fd,
state->off,
@@ -2648,9 +2692,9 @@ static struct tevent_req *vfs_ceph_pread_send(struct
vfs_handle_struct *handle,
struct vfs_ceph_aio_state *state = NULL;
int ret = -1;
- DBG_DEBUG("[CEPH] pread_send(%p, %p, %p, %zu, %zd)\n",
+ DBG_DEBUG("[CEPH] pread_send: handle=%p name=%s data=%p n=%zu
offset=%zd\n",
handle,
- fsp,
+ fsp->fsp_name->base_name,
data,
n,
offset);
@@ -2724,20 +2768,17 @@ static ssize_t vfs_ceph_pwrite(struct vfs_handle_struct
*handle,
ssize_t result;
START_PROFILE_BYTES(syscall_pwrite, n);
- DBG_DEBUG("[CEPH] pwrite(%p, %p, %p, %zu, %jd)\n",
- handle,
--
Samba Shared Repository
