Bug #61590
openadd more context for log messages
0%
Description
2023-05-28T19:57:05.527684+00:00 smithi062 kernel: libceph: mon0 (1)172.21.15.62:6789 session established 2023-05-28T19:57:05.527774+00:00 smithi062 kernel: libceph: client15495 fsid 7e93fa48-fd90-11ed-9b1d-001a4aab830c 2023-05-28T19:57:05.543697+00:00 smithi062 kernel: ceph: mds3 session blocklisted 2023-05-28T19:57:05.561687+00:00 smithi062 kernel: ceph: mds0 session blocklisted 2023-05-28T19:57:17.951686+00:00 smithi062 kernel: ceph: mds1 session blocklisted 2023-05-28T19:57:17.975685+00:00 smithi062 kernel: ceph: mds4 session blocklisted 2023-05-28T19:58:01.123723+00:00 smithi062 kernel: ceph: mds2 session blocklisted
From: /teuthology/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7288964/remote/smithi062/syslog/kern.log.gz
There's a few problems from this but the one this ticket is about: please add session context for related debug messages. Specifically, "client15495: ". Multiple cephfs mounts on a host is increasingly common so disambiguating messages like this is necessary.
Updated by Patrick Donnelly 12 months ago
Xiubo, I lost my subscription somehow to ceph-devel so I can't comment on the patch in the normal way. I think this ticket is more concerned with general dout messages across fs/ceph. I think any dout() message should include this context information.
Updated by Xiubo Li 11 months ago
Patrick Donnelly wrote:
Xiubo, I lost my subscription somehow to ceph-devel so I can't comment on the patch in the normal way. I think this ticket is more concerned with general dout messages across fs/ceph. I think any dout() message should include this context information.
Okay, yesterday I added this in many other places, but thought that may not much neccessary and removed them before sending out the patch.
But with that really could help much. Let me try how to improve that.
Updated by Xiubo Li 11 months ago
The v2 ceph patchwork link: https://patchwork.kernel.org/project/ceph-devel/list/?series=756269
And the output will be something like:
<7>[33404.475305] ceph: [client.4236] caps reclaim work queued <7>[33409.591736] ceph: [client.4236] mdsc delayed_work <7>[33409.591770] ceph: [client.4236] ceph_check_delayed_caps <7>[33409.591789] ceph: [client.4236] caps reclaim work queued <7>[33414.711970] ceph: [client.4236] mdsc delayed_work <7>[33414.711993] ceph: [client.4236] send_renew_caps to mds0 (up:active) <7>[33414.712122] ceph: [client.4236] ceph_check_delayed_caps <7>[33414.712151] ceph: [client.4236] caps reclaim work queued <7>[33414.715517] ceph: [client.4236] handle_session mds0 renewcaps 000000005e065e1d state open seq 27 <7>[33414.715551] ceph: [client.4236] renewed_caps mds0 ttl now 4328139360, was fresh, now stale <7>[33420.344833] ceph: [client.4236] mdsc delayed_work <7>[33420.344870] ceph: [client.4236] ceph_check_delayed_caps <7>[33420.344889] ceph: [client.4236] caps reclaim work queued <7>[33425.463922] ceph: [client.4236] mdsc delayed_work <7>[33425.463976] ceph: [client.4236] ceph_check_delayed_caps <7>[33425.464008] ceph: [client.4236] caps reclaim work queued <7>[33430.585101] ceph: [client.4236] mdsc delayed_work <7>[33430.585127] ceph: [client.4236] send_renew_caps to mds0 (up:active) <7>[33430.585256] ceph: [client.4236] ceph_check_delayed_caps <7>[33430.585286] ceph: [client.4236] caps reclaim work queued <7>[33430.591074] ceph: [client.4236] handle_session mds0 renewcaps 000000005e065e1d state open seq 28 <7>[33430.591104] ceph: [client.4236] renewed_caps mds0 ttl now 4328155233, was fresh, now stale <7>[33435.705243] ceph: [client.4236] mdsc delayed_work <7>[33435.705300] ceph: [client.4236] ceph_check_delayed_caps <7>[33435.705329] ceph: [client.4236] caps reclaim work queued <7>[33441.848145] ceph: [client.4236] mdsc delayed_work <7>[33441.848195] ceph: [client.4236] ceph_check_delayed_caps <7>[33441.848224] ceph: [client.4236] caps reclaim work queued <7>[33447.479776] ceph: [client.4236] mdsc delayed_work <7>[33447.479794] ceph: [client.4236] send_renew_caps to mds0 (up:active) <7>[33447.479872] ceph: [client.4236] ceph_check_delayed_caps <7>[33447.479890] ceph: [client.4236] caps reclaim work queued <7>[33447.480641] ceph: [client.4236] handle_session mds0 renewcaps 000000005e065e1d state open seq 29 <7>[33447.480662] ceph: [client.4236] renewed_caps mds0 ttl now 4328172128, was fresh, now stale <7>[33452.605961] ceph: [client.4236] mdsc delayed_work <7>[33452.606012] ceph: [client.4236] caps reclaim work queued <7>[33458.751031] ceph: [client.4236] mdsc delayed_work <7>[33458.751096] ceph: [client.4236] caps reclaim work queued <7>[33464.375799] ceph: [client.4236] mdsc delayed_work <7>[33464.375817] ceph: [client.4236] send_renew_caps to mds0 (up:active) <7>[33464.375913] ceph: [client.4236] caps reclaim work queued