tracing: Fix adding some modifiers to histogram values

Mark Rutland reported to me on IRC that he accidentally added the ".buckets=8" modifier to hitcount. This should not be allowed, but it did not error. Worse yet, when reading the hist file, it would crash as there was a NULL pointer dereference due to the values not having fields assigned to them.

The first fix is to make sure that histogram values do not get assigned modifiers that they can't use.

The the second patch is to not crash if a NULL pointer is passed to hist_field_name() (which is what happens if you allow some of these modifiers to be used by values).

Steven Rostedt (Google) (2):
tracing: Do not let histogram values have some modifiers
tracing: Check field value in hist_field_name()

----

 kernel/trace/trace_events_hist.c | 12 ++++++++++++
 1 file changed, 12 insertions(+)

From: "Steven Rostedt (Google)" <[email protected]>

Histogram values can not be strings, stacktraces, graphs, symbols, syscalls, or grouped in buckets or log. Give an error if a value is set to do so.

Note, the histogram code was not prepared to handle these modifiers for histograms and caused a bug.

Mark Rutland reported:

 # echo 'p:copy_to_user __arch_copy_to_user n=$arg2' >> /sys/kernel/tracing/kprobe_events
 # echo 'hist:keys=n:vals=hitcount.buckets=8:sort=hitcount' > /sys/kernel/tracing/events/kprobes/copy_to_user/trigger
 # cat /sys/kernel/tracing/events/kprobes/copy_to_user/hist
[  143.694628] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
[  143.695190] Mem abort info:
[  143.695362]   ESR = 0x0000000096000004
[  143.695604]   EC = 0x25: DABT (current EL), IL = 32 bits
[  143.695889]   SET = 0, FnV = 0
[  143.696077]   EA = 0, S1PTW = 0
[  143.696302]   FSC = 0x04: level 0 translation fault
[  143.702381] Data abort info:
[  143.702614]   ISV = 0, ISS = 0x00000004
[  143.702832]   CM = 0, WnR = 0
[  143.703087] user pgtable: 4k pages, 48-bit VAs, pgdp=00000000448f9000
[  143.703407] [0000000000000000] pgd=0000000000000000, p4d=0000000000000000
[  143.704137] Internal error: Oops: 0000000096000004 [#1] PREEMPT SMP
[  143.704714] Modules linked in:
[  143.705273] CPU: 0 PID: 133 Comm: cat Not tainted 6.2.0-00003-g6fc512c10a7c #3
[  143.706138] Hardware name: linux,dummy-virt (DT)
[  143.706723] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[  143.707120] pc : hist_field_name.part.0+0x14/0x140
[  143.707504] lr : hist_field_name.part.0+0x104/0x140
[  143.707774] sp : ffff800008333a30
[  143.707952] x29: ffff800008333a30 x28: 0000000000000001 x27: 0000000000400cc0
[  143.708429] x26: ffffd7a653b20260 x25: 0000000000000000 x24: ffff10d303ee5800
[  143.708776] x23: ffffd7a6539b27b0 x22: ffff10d303fb8c00 x21: 0000000000000001
[  143.709127] x20: ffff10d303ec2000 x19: 0000000000000000 x18: 0000000000000000
[  143.709478] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[  143.709824] x14: 0000000000000000 x13: 203a6f666e692072 x12: 6567676972742023
[  143.710179] x11: 0a230a6d6172676f x10: 000000000000002c x9 : ffffd7a6521e018c
[  143.710584] x8 : 000000000000002c x7 : 7f7f7f7f7f7f7f7f x6 : 000000000000002c
[  143.710915] x5 : ffff10d303b0103e x4 : ffffd7a653b20261 x3 : 000000000000003d
[  143.711239] x2 : 0000000000020001 x1 : 0000000000000001 x0 : 0000000000000000
[  143.711746] Call trace:
[  143.712115]  hist_field_name.part.0+0x14/0x140
[  143.712642]  hist_field_name.part.0+0x104/0x140
[  143.712925]  hist_field_print+0x28/0x140
[  143.713125]  event_hist_trigger_print+0x174/0x4d0
[  143.713348]  hist_show+0xf8/0x980
[  143.713521]  seq_read_iter+0x1bc/0x4b0
[  143.713711]  seq_read+0x8c/0xc4
[  143.713876]  vfs_read+0xc8/0x2a4
[  143.714043]  ksys_read+0x70/0xfc
[  143.714218]  __arm64_sys_read+0x24/0x30
[  143.714400]  invoke_syscall+0x50/0x120
[  143.714587]  el0_svc_common.constprop.0+0x4c/0x100
[  143.714807]  do_el0_svc+0x44/0xd0
[  143.714970]  el0_svc+0x2c/0x84
[  143.715134]  el0t_64_sync_handler+0xbc/0x140
[  143.715334]  el0t_64_sync+0x190/0x194
[  143.715742] Code: a9bd7bfd 910003fd a90153f3 aa0003f3 (f9400000)
[  143.716510] ---[ end trace 0000000000000000 ]---
Segmentation fault

---
 kernel/trace/trace_events_hist.c | 9 +++++++++
 1 file changed, 9 insertions(+)

index 89877a18f933..6e8ab726a7b5 100644
@@ -4235,6 +4235,15 @@ static int __create_val_field(struct hist_trigger_data *hist_data,
 		goto out;
 	}
 
+	/* Some types cannot be a value */
+	if (hist_field->flags & (HIST_FIELD_FL_GRAPH | HIST_FIELD_FL_PERCENT |
+				 HIST_FIELD_FL_BUCKET | HIST_FIELD_FL_LOG2 |
+				 HIST_FIELD_FL_SYM | HIST_FIELD_FL_SYM_OFFSET |
+				 HIST_FIELD_FL_SYSCALL | HIST_FIELD_FL_STACKTRACE)) {
+		hist_err(file->tr, HIST_ERR_BAD_FIELD_MODIFIER, errpos(field_str));
+		ret = -EINVAL;
+	}
+
 	hist_data->fields[val_idx] = hist_field;
 
 	++hist_data->n_vals;

2.39.1

I gave this a spin, and I see that the buckets modifier gerts rejected for hitcount, but is usable for other values as it should be:

| # echo 'p:copy_to_user __arch_copy_to_user n=$arg3' >> /sys/kernel/tracing/kprobe_events
| # echo 'hist:keys=n:vals=hitcount.buckets=8:sort=hitcount' > /sys/kernel/tracing/events/kprobes/copy_to_user/trigger
| sh: write error: Invalid argument
| # echo 'hist:keys=n.buckets=8:vals=hitcount:sort=hitcount' > /sys/kernel/tracing/events/kprobes/copy_to_user/trigger
| # cat /sys/kernel/tracing/events/kprobes/copy_to_user/hist
| # event histogram
| #
| # trigger info: hist:keys=n.buckets=8:vals=hitcount:sort=hitcount:size=2048 [active]
| #
| 
| { n: ~ 336-343 } hitcount:          1
| { n: ~ 16-23 } hitcount:          2
| { n: ~ 32-39 } hitcount:          2
| { n: ~ 832-839 } hitcount:          3
| { n: ~ 8-15 } hitcount:          3
| { n: ~ 128-135 } hitcount:          5
| { n: ~ 0-7 } hitcount:         57
| 
| Totals:
|     Hits: 73
|     Entries: 7
|     Dropped: 0

Thanks,
Mark.

From: "Steven Rostedt (Google)" <[email protected]>

The function hist_field_name() cannot handle being passed a NULL field parameter. It should never be NULL, but due to a previous bug, NULL was passed to the function and the kernel crashed due to a NULL dereference. Mark Rutland reported this to me on IRC.

The bug was fixed, but to prevent future bugs from crashing the kernel, check the field and add a WARN_ON() if it is NULL.

---
 kernel/trace/trace_events_hist.c | 3 +++
 1 file changed, 3 insertions(+)

index 6e8ab726a7b5..486cca3c2b75 100644
@@ -1331,6 +1331,9 @@ static const char *hist_field_name(struct hist_field *field,
 {
 	const char *field_name = "";
 
+	if (WARN_ON_ONCE(!field))
+		return field_name;
+
 	if (level > 1)
 		return field_name;
 

2.39.1

I gave this patch a spin on its own (without the prior patch), and it behaves as expected. When deliberately triggering the aforementioned bug I hit the WARN_ON_ONCE() without crashing the kernel:

| # echo 'p:copy_to_user __arch_copy_to_user n=$arg2' >> /sys/kernel/tracing/kprobe_events
| # echo 'hist:keys=n:vals=hitcount.buckets=8:sort=hitcount' > /sys/kernel/tracing/events/kprobes/copy_to_user/trigger
| # cat /sys/kernel/tracing/events/kprobes/copy_to_user/hist 
| ------------[ cut here ]------------
| WARNING: CPU: 0 PID: 133 at kernel/trace/trace_events_hist.c:1337 hist_field_name+0x94/0x144
| Modules linked in:
| CPU: 0 PID: 133 Comm: cat Not tainted 6.2.0-00003-g785bb684c534 #2
| Hardware name: linux,dummy-virt (DT)
| pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
| pc : hist_field_name+0x94/0x144
| lr : hist_field_name+0xbc/0x144
| sp : ffff800008343a60
| x29: ffff800008343a60 x28: 0000000000000001 x27: 0000000000400cc0
| x26: ffffaed00953fcd0 x25: 0000000000000000 x24: ffff65c743e8bf00
| x23: ffffaed0093d2488 x22: ffff65c743fadc00 x21: 0000000000000001
| x20: ffff65c743ec1000 x19: ffff65c743fadc00 x18: 0000000000000000
| x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
| x14: 0000000000000000 x13: 203a6f666e692072 x12: 6567676972742023
| x11: 0a230a6d6172676f x10: 000000000000002c x9 : ffffaed007be1fcc
| x8 : 000000000000002c x7 : 7f7f7f7f7f7f7f7f x6 : 000000000000002c
| x5 : ffff65c743b0103e x4 : ffffaed00953fcd1 x3 : 000000000000003d
| x2 : 0000000000020001 x1 : 0000000000000001 x0 : 0000000000000000
| Call trace:
|  hist_field_name+0x94/0x144
|  hist_field_print+0x28/0x14c
|  event_hist_trigger_print+0x174/0x4d0
|  hist_show+0xf8/0x980
|  seq_read_iter+0x1bc/0x4b0
|  seq_read+0x8c/0xc4
|  vfs_read+0xc8/0x2a4
|  ksys_read+0x70/0xfc
|  __arm64_sys_read+0x24/0x30
|  invoke_syscall+0x50/0x120
|  el0_svc_common.constprop.0+0x4c/0x100
|  do_el0_svc+0x44/0xd0
|  el0_svc+0x2c/0x84
|  el0t_64_sync_handler+0xbc/0x140
|  el0t_64_sync+0x190/0x194
| ---[ end trace 0000000000000000 ]---
| # event histogram
| #
| # trigger info: hist:keys=n:vals=hitcount,.buckets=8:sort=hitcount:size=2048 [active]
| #
| 
| { n: 18446574505247538232 } hitcount:          1  :          1
| { n: 18446574505249480120 } hitcount:          1  :          1
| { n: 18446574505255937966 } hitcount:          1  :          1
| { n: 18446574505234423224 } hitcount:          1  :          1

[...]

| Totals:
|     Hits: 371
|     Entries: 263
|     Dropped: 0

Note: the 'n' values are large because '$arg2' is actually the 'from' pointer here, another mistake of mine (I had meant to capture '$arg3').

Thanks,
Mark.

I forgot to add Tom Zanussi on this series.

-- Steve