Re: [PATCH v2 1/4] afs: Fix tracepoint string placement with built-in AFS

From: Marc Dionne
Date: Mon Jul 12 2021 - 15:27:24 EST

Next message: Linus Torvalds: "Re: Linux 5.14-rc1"
Previous message: Alexander Mihalicyn: "Re: [PATCH 0/2] shm: omit forced shm destroy if task IPC namespace was changed"
In reply to: David Howells: "[PATCH v2 1/4] afs: Fix tracepoint string placement with built-in AFS"
Next in thread: David Howells: "[PATCH v2 2/4] afs: check function return"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Mon, Jul 12, 2021 at 1:28 PM David Howells <dhowells@xxxxxxxxxx> wrote:
>
> To quote Alexey[1]:
>
> I was adding custom tracepoint to the kernel, grabbed full F34 kernel
> .config, disabled modules and booted whole shebang as VM kernel.
>
> Then did
>
> perf record -a -e ...
>
> It crashed:
>
> general protection fault, probably for non-canonical address 0x435f5346592e4243: 0000 [#1] SMP PTI
> CPU: 1 PID: 842 Comm: cat Not tainted 5.12.6+ #26
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-1.fc33 04/01/2014
> RIP: 0010:t_show+0x22/0xd0
>
> Then reproducer was narrowed to
>
> # cat /sys/kernel/tracing/printk_formats
>
> Original F34 kernel with modules didn't crash.
>
> So I started to disable options and after disabling AFS everything
> started working again.
>
> The root cause is that AFS was placing char arrays content into a
> section full of _pointers_ to strings with predictable consequences.
>
> Non canonical address 435f5346592e4243 is "CB.YFS_" which came from
> CM_NAME macro.
>
> Steps to reproduce:
>
> CONFIG_AFS=y
> CONFIG_TRACING=y
>
> # cat /sys/kernel/tracing/printk_formats
>
> Fix this by the following means:
>
> (1) Add enum->string translation tables in the event header with the AFS
> and YFS cache/callback manager operations listed by RPC operation ID.
>
> (2) Modify the afs_cb_call tracepoint to print the string from the
> translation table rather than using the string at the afs_call name
> pointer.
>
> (3) Switch translation table depending on the service we're being accessed
> as (AFS or YFS) in the tracepoint print clause. Will this cause
> problems to userspace utilities?
>
> Note that the symbolic representation of the YFS service ID isn't
> available to this header, so I've put it in as a number. I'm not sure
> if this is the best way to do this.
>
> (4) Remove the name wrangling (CM_NAME) macro and put the names directly
> into the afs_call_type structs in cmservice.c.
>
> Fixes: 8e8d7f13b6d5a9 ("afs: Add some tracepoints")
> Reported-by: Alexey Dobriyan (SK hynix) <adobriyan@xxxxxxxxx>
> Signed-off-by: David Howells <dhowells@xxxxxxxxxx>
> Reviewed-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx>
> cc: Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx>
> cc: linux-afs@xxxxxxxxxxxxxxxxxxx
> Link: https://lore.kernel.org/r/YLAXfvZ+rObEOdc%2F@localhost.localdomain/ [1]
> Link: https://lore.kernel.org/r/643721.1623754699@xxxxxxxxxxxxxxxxxxxxxx/
> Link: https://lore.kernel.org/r/162430903582.2896199.6098150063997983353.stgit@xxxxxxxxxxxxxxxxxxxxxx/ # v1
> Link: https://lore.kernel.org/r/162609463957.3133237.15916579353149746363.stgit@xxxxxxxxxxxxxxxxxxxxxx/ # v1 (repost)
> ---
>
> fs/afs/cmservice.c | 25 +++++-----------
> include/trace/events/afs.h | 67 +++++++++++++++++++++++++++++++++++++++++---
> 2 files changed, 69 insertions(+), 23 deletions(-)
>
> diff --git a/fs/afs/cmservice.c b/fs/afs/cmservice.c
> index d3c6bb22c5f4..a3f5de28be79 100644
> --- a/fs/afs/cmservice.c
> +++ b/fs/afs/cmservice.c
> @@ -29,16 +29,11 @@ static void SRXAFSCB_TellMeAboutYourself(struct work_struct *);
>
> static int afs_deliver_yfs_cb_callback(struct afs_call *);
>
> -#define CM_NAME(name) \
> - char afs_SRXCB##name##_name[] __tracepoint_string = \
> - "CB." #name
> -
> /*
> * CB.CallBack operation type
> */
> -static CM_NAME(CallBack);
> static const struct afs_call_type afs_SRXCBCallBack = {
> - .name = afs_SRXCBCallBack_name,
> + .name = "CB.CallBack",
> .deliver = afs_deliver_cb_callback,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_CallBack,
> @@ -47,9 +42,8 @@ static const struct afs_call_type afs_SRXCBCallBack = {
> /*
> * CB.InitCallBackState operation type
> */
> -static CM_NAME(InitCallBackState);
> static const struct afs_call_type afs_SRXCBInitCallBackState = {
> - .name = afs_SRXCBInitCallBackState_name,
> + .name = "CB.InitCallBackState",
> .deliver = afs_deliver_cb_init_call_back_state,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_InitCallBackState,
> @@ -58,9 +52,8 @@ static const struct afs_call_type afs_SRXCBInitCallBackState = {
> /*
> * CB.InitCallBackState3 operation type
> */
> -static CM_NAME(InitCallBackState3);
> static const struct afs_call_type afs_SRXCBInitCallBackState3 = {
> - .name = afs_SRXCBInitCallBackState3_name,
> + .name = "CB.InitCallBackState3",
> .deliver = afs_deliver_cb_init_call_back_state3,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_InitCallBackState,
> @@ -69,9 +62,8 @@ static const struct afs_call_type afs_SRXCBInitCallBackState3 = {
> /*
> * CB.Probe operation type
> */
> -static CM_NAME(Probe);
> static const struct afs_call_type afs_SRXCBProbe = {
> - .name = afs_SRXCBProbe_name,
> + .name = "CB.Probe",
> .deliver = afs_deliver_cb_probe,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_Probe,
> @@ -80,9 +72,8 @@ static const struct afs_call_type afs_SRXCBProbe = {
> /*
> * CB.ProbeUuid operation type
> */
> -static CM_NAME(ProbeUuid);
> static const struct afs_call_type afs_SRXCBProbeUuid = {
> - .name = afs_SRXCBProbeUuid_name,
> + .name = "CB.ProbeUuid",
> .deliver = afs_deliver_cb_probe_uuid,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_ProbeUuid,
> @@ -91,9 +82,8 @@ static const struct afs_call_type afs_SRXCBProbeUuid = {
> /*
> * CB.TellMeAboutYourself operation type
> */
> -static CM_NAME(TellMeAboutYourself);
> static const struct afs_call_type afs_SRXCBTellMeAboutYourself = {
> - .name = afs_SRXCBTellMeAboutYourself_name,
> + .name = "CB.TellMeAboutYourself",
> .deliver = afs_deliver_cb_tell_me_about_yourself,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_TellMeAboutYourself,
> @@ -102,9 +92,8 @@ static const struct afs_call_type afs_SRXCBTellMeAboutYourself = {
> /*
> * YFS CB.CallBack operation type
> */
> -static CM_NAME(YFS_CallBack);
> static const struct afs_call_type afs_SRXYFSCB_CallBack = {
> - .name = afs_SRXCBYFS_CallBack_name,
> + .name = "YFSCB.CallBack",
> .deliver = afs_deliver_yfs_cb_callback,
> .destructor = afs_cm_destructor,
> .work = SRXAFSCB_CallBack,
> diff --git a/include/trace/events/afs.h b/include/trace/events/afs.h
> index 3ccf591b2374..9f73ed2cf061 100644
> --- a/include/trace/events/afs.h
> +++ b/include/trace/events/afs.h
> @@ -174,6 +174,34 @@ enum afs_vl_operation {
> afs_VL_GetCapabilities = 65537, /* AFS Get VL server capabilities */
> };
>
> +enum afs_cm_operation {
> + afs_CB_CallBack = 204, /* AFS break callback promises */
> + afs_CB_InitCallBackState = 205, /* AFS initialise callback state */
> + afs_CB_Probe = 206, /* AFS probe client */
> + afs_CB_GetLock = 207, /* AFS get contents of CM lock table */
> + afs_CB_GetCE = 208, /* AFS get cache file description */
> + afs_CB_GetXStatsVersion = 209, /* AFS get version of extended statistics */
> + afs_CB_GetXStats = 210, /* AFS get contents of extended statistics data */
> + afs_CB_InitCallBackState3 = 213, /* AFS initialise callback state, version 3 */
> + afs_CB_ProbeUuid = 214, /* AFS check the client hasn't rebooted */
> +};
> +
> +enum yfs_cm_operation {
> + yfs_CB_Probe = 206, /* YFS probe client */
> + yfs_CB_GetLock = 207, /* YFS get contents of CM lock table */
> + yfs_CB_XStatsVersion = 209, /* YFS get version of extended statistics */
> + yfs_CB_GetXStats = 210, /* YFS get contents of extended statistics data */
> + yfs_CB_InitCallBackState3 = 213, /* YFS initialise callback state, version 3 */
> + yfs_CB_ProbeUuid = 214, /* YFS check the client hasn't rebooted */
> + yfs_CB_GetServerPrefs = 215,
> + yfs_CB_GetCellServDV = 216,
> + yfs_CB_GetLocalCell = 217,
> + yfs_CB_GetCacheConfig = 218,
> + yfs_CB_GetCellByNum = 65537,
> + yfs_CB_TellMeAboutYourself = 65538, /* get client capabilities */
> + yfs_CB_CallBack = 64204,
> +};
> +
> enum afs_edit_dir_op {
> afs_edit_dir_create,
> afs_edit_dir_create_error,
> @@ -436,6 +464,32 @@ enum afs_cb_break_reason {
> EM(afs_YFSVL_GetCellName, "YFSVL.GetCellName") \
> E_(afs_VL_GetCapabilities, "VL.GetCapabilities")
>
> +#define afs_cm_operations \
> + EM(afs_CB_CallBack, "CB.CallBack") \
> + EM(afs_CB_InitCallBackState, "CB.InitCallBackState") \
> + EM(afs_CB_Probe, "CB.Probe") \
> + EM(afs_CB_GetLock, "CB.GetLock") \
> + EM(afs_CB_GetCE, "CB.GetCE") \
> + EM(afs_CB_GetXStatsVersion, "CB.GetXStatsVersion") \
> + EM(afs_CB_GetXStats, "CB.GetXStats") \
> + EM(afs_CB_InitCallBackState3, "CB.InitCallBackState3") \
> + E_(afs_CB_ProbeUuid, "CB.ProbeUuid")
> +
> +#define yfs_cm_operations \
> + EM(yfs_CB_Probe, "YFSCB.Probe") \
> + EM(yfs_CB_GetLock, "YFSCB.GetLock") \
> + EM(yfs_CB_XStatsVersion, "YFSCB.XStatsVersion") \
> + EM(yfs_CB_GetXStats, "YFSCB.GetXStats") \
> + EM(yfs_CB_InitCallBackState3, "YFSCB.InitCallBackState3") \
> + EM(yfs_CB_ProbeUuid, "YFSCB.ProbeUuid") \
> + EM(yfs_CB_GetServerPrefs, "YFSCB.GetServerPrefs") \
> + EM(yfs_CB_GetCellServDV, "YFSCB.GetCellServDV") \
> + EM(yfs_CB_GetLocalCell, "YFSCB.GetLocalCell") \
> + EM(yfs_CB_GetCacheConfig, "YFSCB.GetCacheConfig") \
> + EM(yfs_CB_GetCellByNum, "YFSCB.GetCellByNum") \
> + EM(yfs_CB_TellMeAboutYourself, "YFSCB.TellMeAboutYourself") \
> + E_(yfs_CB_CallBack, "YFSCB.CallBack")
> +
> #define afs_edit_dir_ops \
> EM(afs_edit_dir_create, "create") \
> EM(afs_edit_dir_create_error, "c_fail") \
> @@ -569,6 +623,8 @@ afs_server_traces;
> afs_cell_traces;
> afs_fs_operations;
> afs_vl_operations;
> +afs_cm_operations;
> +yfs_cm_operations;
> afs_edit_dir_ops;
> afs_edit_dir_reasons;
> afs_eproto_causes;
> @@ -649,20 +705,21 @@ TRACE_EVENT(afs_cb_call,
>
> TP_STRUCT__entry(
> __field(unsigned int, call )
> - __field(const char *, name )
> __field(u32, op )
> + __field(u16, service_id )
> ),
>
> TP_fast_assign(
> __entry->call = call->debug_id;
> - __entry->name = call->type->name;
> __entry->op = call->operation_ID;
> + __entry->service_id = call->service_id;
> ),
>
> - TP_printk("c=%08x %s o=%u",
> + TP_printk("c=%08x %s",
> __entry->call,
> - __entry->name,
> - __entry->op)
> + __entry->service_id == 2501 ?
> + __print_symbolic(__entry->op, yfs_cm_operations) :
> + __print_symbolic(__entry->op, afs_cm_operations))
> );
>
> TRACE_EVENT(afs_call,
>
>

Reviewed-by: Marc Dionne <marc.dionne@xxxxxxxxxxxx>

If you wanted to avoid having the hard coded yfs service ID there, you
could pass in a boolean "is yfs" value and let the caller set it based
on the service ID, or even have two separate trace events. But seems
fine as is.

Marc

Next message: Linus Torvalds: "Re: Linux 5.14-rc1"
Previous message: Alexander Mihalicyn: "Re: [PATCH 0/2] shm: omit forced shm destroy if task IPC namespace was changed"
In reply to: David Howells: "[PATCH v2 1/4] afs: Fix tracepoint string placement with built-in AFS"
Next in thread: David Howells: "[PATCH v2 2/4] afs: check function return"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]