XFS tracepoint warning due to NULL string

XFS tracepoint warning due to NULL string

[Brian Foster]

Hi Steven,

I'm seeing the warning below [1] on recent kernels via the
xfs_dir2_sf_create tracepoint. This appears to be associated with commit
9a6944fee68e ("tracing: Add a verifier to check string pointers for
trace events") checking for valid string usage in the tracepoint hooks.
It looks to me that the memory usage is correct, we've just open coded
it via __dynamic_array and memcpy() as opposed to using the various more
friendly __string() variants (perhaps due to the format width
specifier).

In any event, playing around with this suggests that the cause is
passing the NULL pointer when no name string is available. The resulting
trace output associated with the warning is here [2]. This particular
tracepoint logic looks to have been in place for some time. The
historical output prior to the above commit is here [3].

What's the best way to address this going forward with the memory usage
verification in place? ISTM we could perhaps consider dropping the
custom %.*s thing in favor of using %s with __string_len() and friends,
or perhaps just replace the open-coded NULL parameter with the "(null)"
string that the trace subsystem code seems to use on NULL pointer
checks. The latter seems pretty simple and straightforward of a change
to me, but I want to make sure I'm not missing something more obvious.
Thoughts?

Brian

[1]

------------[ cut here ]------------
fmt: 'dev %d:%d ino 0x%llx name %.*s namelen %d hashval 0x%x inumber 0x%llx op_flags %s
' current_buffer: '           mkdir-3922    [060] .....  2591.032755: xfs_dir2_sf_create: dev 253:3 ino 0x985 name '
WARNING: CPU: 6 PID: 2683 at kernel/trace/trace.c:3859 trace_check_vprintf+0x4ac/0x4d0
Modules linked in: rpcrdma sunrpc rdma_ucm ib_srpt ib_isert iscsi_target_mod target_core_mod ib_iser libiscsi scsi_transport_iscsi ib_umad rdma_cm ib_ipoib iw_cm ib_cm intel_rapl_msr iTCO_wdt iTCO_vendor_support intel_rapl_common ipmi_ssif i10nm_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel rfkill kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel rapl intel_cstate intel_uncore acpi_ipmi bnxt_re mlx5_ib ipmi_si mei_me ib_uverbs isst_if_mmio isst_if_mbox_pci ipmi_devintf i2c_i801 nd_pmem pcspkr wmi_bmof ib_core mei intel_pch_thermal isst_if_common i2c_smbus ipmi_msghandler nd_btt dax_pmem acpi_power_meter xfs libcrc32c sd_mod sg lpfc nvmet_fc mgag200 nvmet i2c_algo_bit mlx5_core drm_shmem_helper nvme_fc mlxfw drm_kms_helper syscopyarea pci_hyperv_intf nvme_fabrics sysfillrect nvme_core sysimgblt fb_sys_fops t10_pi ahci tls crc32c_intel libahci psample scsi_transport_fc megaraid_sas bnxt_en drm tg3 libata wmi nfit libnvdimm dm_mirror dm_region_hash
 dm_log dm_mod
CPU: 6 PID: 2683 Comm: cat Tainted: G S                5.17.0-rc6+ #29
Hardware name: Dell Inc. PowerEdge R750/06V45N, BIOS 1.2.4 05/28/2021
RIP: 0010:trace_check_vprintf+0x4ac/0x4d0
Code: 3a 39 f0 74 36 c6 04 32 00 49 8b 95 b0 20 00 00 48 8b 74 24 08 48 c7 c7 60 5a e0 87 44 89 44 24 28 88 4c 24 20 e8 46 ea 80 00 <0f> 0b 0f b6 4c 24 20 44 8b 44 24 28 e9 4e fe ff ff c6 44 02 ff 00
RSP: 0018:ff5f059ca0f23d20 EFLAGS: 00010282
RAX: 0000000000000000 RBX: 000000000000001b RCX: 0000000000000027
RDX: 0000000000000027 RSI: ff173cacffcdf8c0 RDI: ff173cacffcdf8c8
RBP: 0000000000000000 R08: 0000000000000000 R09: c0000000ffff7fff
R10: 0000000000000001 R11: ff5f059ca0f23b48 R12: ffffffffc0b04ffa
R13: ff173c6ed005c000 R14: 0000000000000000 R15: ffffffffc0b04fe0
FS:  00007ff5d157d680(0000) GS:ff173cacffcc0000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fd6c036a0c0 CR3: 000000010fcfc001 CR4: 0000000000771ee0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
PKRU: 55555554
Call Trace:
 <TASK>
 trace_event_printf+0x5d/0x80
 trace_raw_output_xfs_da_class+0x78/0x90 [xfs]
 print_trace_line+0x1da/0x4d0
 tracing_read_pipe+0x1cd/0x350
 vfs_read+0x95/0x190
 ksys_read+0x59/0xd0
 do_syscall_64+0x37/0x80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7ff5d107a5a5
Code: fe ff ff 50 48 8d 3d 92 f7 09 00 e8 85 fe 01 00 0f 1f 44 00 00 f3 0f 1e fa 48 8d 05 f5 6f 2d 00 8b 00 85 c0 75 0f 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 53 c3 66 90 41 54 49 89 d4 55 48 89 f5 53 89
RSP: 002b:00007ffd47158d88 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007ff5d107a5a5
RDX: 0000000000020000 RSI: 00007ff5d14f5000 RDI: 0000000000000003
RBP: 00007ff5d14f5000 R08: 00000000ffffffff R09: 0000000000000000
R10: 0000000000000022 R11: 0000000000000246 R12: 00007ff5d14f5000
R13: 0000000000000003 R14: 00000000000000ab R15: 0000000000020000
 </TASK>
---[ end trace 0000000000000000 ]---

[2] 

mkdir-3922    [060] .....  2591.032755: xfs_dir2_sf_create: dev 253:3 ino 0x985 name (0x0000000000000000)[UNSAFE-MEMORY] namelen 0 hashval 0x0 inumber 0x0 op_flags

[3]

mkdir-3783    [006] ....   406.453838: xfs_dir2_sf_create: dev 253:3 ino 0x985 name  namelen 0 hashval 0x0 inumber 0x0 op_flags

Re: XFS tracepoint warning due to NULL string

[Steven Rostedt]

On Wed, 23 Mar 2022 08:47:10 -0400
Brian Foster <bfoster@redhat.com> wrote:

> What's the best way to address this going forward with the memory usage
> verification in place? ISTM we could perhaps consider dropping the
> custom %.*s thing in favor of using %s with __string_len() and friends,
> or perhaps just replace the open-coded NULL parameter with the "(null)"
> string that the trace subsystem code seems to use on NULL pointer
> checks. The latter seems pretty simple and straightforward of a change
> to me, but I want to make sure I'm not missing something more obvious.
> Thoughts?

Can you see if the following (totally untested) patch fixes your issue?

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 08ea781540b5..f4de111fa18f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3673,12 +3673,17 @@ static char *trace_iter_expand_format(struct trace_iterator *iter)
 }
 
 /* Returns true if the string is safe to dereference from an event */
-static bool trace_safe_str(struct trace_iterator *iter, const char *str)
+static bool trace_safe_str(struct trace_iterator *iter, const char *str,
+			   bool star, int len)
 {
 	unsigned long addr = (unsigned long)str;
 	struct trace_event *trace_event;
 	struct trace_event_call *event;
 
+	/* Ignore strings with no length */
+	if (star && !len)
+		return true;
+
 	/* OK if part of the event data */
 	if ((addr >= (unsigned long)iter->ent) &&
 	    (addr < (unsigned long)iter->ent + iter->ent_size))
@@ -3864,7 +3869,7 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		 * instead. See samples/trace_events/trace-events-sample.h
 		 * for reference.
 		 */
-		if (WARN_ONCE(!trace_safe_str(iter, str),
+		if (WARN_ONCE(!trace_safe_str(iter, str, star, len),
 			      "fmt: '%s' current_buffer: '%s'",
 			      fmt, show_buffer(&iter->seq))) {
 			int ret;

Re: XFS tracepoint warning due to NULL string

[Brian Foster]

On Wed, Mar 23, 2022 at 10:02:00AM -0400, Steven Rostedt wrote:
> On Wed, 23 Mar 2022 08:47:10 -0400
> Brian Foster <bfoster@redhat.com> wrote:
> 
> > What's the best way to address this going forward with the memory usage
> > verification in place? ISTM we could perhaps consider dropping the
> > custom %.*s thing in favor of using %s with __string_len() and friends,
> > or perhaps just replace the open-coded NULL parameter with the "(null)"
> > string that the trace subsystem code seems to use on NULL pointer
> > checks. The latter seems pretty simple and straightforward of a change
> > to me, but I want to make sure I'm not missing something more obvious.
> > Thoughts?
> 
> Can you see if the following (totally untested) patch fixes your issue?
> 

Yup, that restores historical behavior. Thanks!

Brian

> -- Steve
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 08ea781540b5..f4de111fa18f 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3673,12 +3673,17 @@ static char *trace_iter_expand_format(struct trace_iterator *iter)
>  }
>  
>  /* Returns true if the string is safe to dereference from an event */
> -static bool trace_safe_str(struct trace_iterator *iter, const char *str)
> +static bool trace_safe_str(struct trace_iterator *iter, const char *str,
> +			   bool star, int len)
>  {
>  	unsigned long addr = (unsigned long)str;
>  	struct trace_event *trace_event;
>  	struct trace_event_call *event;
>  
> +	/* Ignore strings with no length */
> +	if (star && !len)
> +		return true;
> +
>  	/* OK if part of the event data */
>  	if ((addr >= (unsigned long)iter->ent) &&
>  	    (addr < (unsigned long)iter->ent + iter->ent_size))
> @@ -3864,7 +3869,7 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
>  		 * instead. See samples/trace_events/trace-events-sample.h
>  		 * for reference.
>  		 */
> -		if (WARN_ONCE(!trace_safe_str(iter, str),
> +		if (WARN_ONCE(!trace_safe_str(iter, str, star, len),
>  			      "fmt: '%s' current_buffer: '%s'",
>  			      fmt, show_buffer(&iter->seq))) {
>  			int ret;
>