seq-buf/ftrace: Various fixes

Linus,

This includes fixes for seq_buf_bprintf() truncation issue. It also contains fixes to ftrace when /proc/sys/kernel/ftrace_enabled and function tracing are started. Doing the following causes some issues:

 # echo 0 > /proc/sys/kernel/ftrace_enabled
 # echo function_graph > /sys/kernel/debug/tracing/current_tracer
 # echo 1 > /proc/sys/kernel/ftrace_enabled
 # echo nop > /sys/kernel/debug/tracing/current_tracer
 # echo function_graph > /sys/kernel/debug/tracing/current_tracer

As well as with function tracing too. Pratyush Anand first reported this issue to me and supplied a patch. When I tested this on my x86 test box, it caused thousands of backtraces and warnings to appear in dmesg, which also caused a denial of service (a warning for every function that was listed). I applied Pratyush's patch but it did not fix the issue for me. I looked into it and found a slight problem with trampoline accounting. I fixed it and sent Pratyush a patch, but he said that it did not fix the issue for him.

I later learned tha Pratyush was using an ARM64 server, and when I tested on my ARM board, I was able to reproduce the same issue as Pratyush. After applying his patch, it fixed the problem. The above test uncovered two different bugs, one in x86 and one in ARM and ARM64. As this looked like it would affect PowerPC, I tested it on my PPC64 box. It too broke, but neither the patch that fixed ARM or x86 fixed this box (the changes were all in generic code!). The above test, uncovered two more bugs that affected PowerPC. Again, the changes were only done to generic code. It's the way the arch code expected things to be done that was different between the archs. Some where more sensitive than others.

The rest of this series fixes the PPC bugs as well.

This is on top of the last pull request I sent out. But doesn't seem to have been pulled.

Please pull the latest trace-fixes-v4.0-rc2-2 tree, which can be found at:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
trace-fixes-v4.0-rc2-2

Tag SHA1: 5b136f3e4bf380f18402f3354cd13f9f0ffbeb02 Head SHA1: 524a38682573b2e15ab6317ccfe50280441514be

Pratyush Anand (1):
ftrace: Fix en(dis)able graph caller when en(dis)abling record via sysctl

Steven Rostedt (Red Hat) (4):
seq_buf: Fix seq_buf_vprintf() truncation
seq_buf: Fix seq_buf_bprintf() truncation
ftrace: Clear REGS_EN and TRAMP_EN flags on disabling record via sysctl
ftrace: Fix ftrace enable ordering of sysctl ftrace_enabled

----

 kernel/trace/ftrace.c | 40 ++++++++++++++++++++++++++++++----------
 lib/seq_buf.c         |  4 ++--
 2 files changed, 32 insertions(+), 12 deletions(-)

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

In seq_buf_vprintf(), vsnprintf() is used to copy the format into the buffer remaining in the seq_buf structure. The return of vsnprintf() is the amount of characters written to the buffer excluding the '\0', unless the line was truncated!

If the line copied does not fit, it is truncated, and a '\0' is added to the end of the buffer. But in this case, '\0' is included in the length of the line written. To know if the buffer had overflowed, the return length will be the same as the length of the buffer passed in.

The check in seq_buf_vprintf() only checked if the length returned from vsnprintf() would fit in the buffer, as the seq_buf_vprintf() is only to be an all or nothing command. It either writes all the string into the seq_buf, or none of it. If the string is truncated, the pointers inside the seq_buf must be reset to what they were when the function was called. This is not the case. On overflow, it copies only part of the string.

The fix is to change the overflow check to see if the length returned from vsnprintf() is less than the length remaining in the seq_buf buffer, and not if it is less than or equal to as it currently does. Then seq_buf_vprintf() will know if the write from vsnpritnf() was truncated or not.

---
 lib/seq_buf.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 88c0854bd752..0c92583b7b7e 100644
@@ -61,7 +61,7 @@ int seq_buf_vprintf(struct seq_buf *s, const char *fmt, va_list args)
 
 	if (s->len < s->size) {
 		len = vsnprintf(s->buffer + s->len, s->size - s->len, fmt, args);
-		if (seq_buf_can_fit(s, len)) {
+		if (s->len + len < s->size) {
 			s->len += len;
 			return 0;
 		}

2.1.4

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

In seq_buf_bprintf(), bstr_printf() is used to copy the format into the buffer remaining in the seq_buf structure. The return of bstr_printf() is the amount of characters written to the buffer excluding the '\0', unless the line was truncated!

If the line copied does not fit, it is truncated, and a '\0' is added to the end of the buffer. But in this case, '\0' is included in the length of the line written. To know if the buffer had overflowed, the return length will be the same or greater than the length of the buffer passed in.

The check in seq_buf_bprintf() only checked if the length returned from bstr_printf() would fit in the buffer, as the seq_buf_bprintf() is only to be an all or nothing command. It either writes all the string into the seq_buf, or none of it. If the string is truncated, the pointers inside the seq_buf must be reset to what they were when the function was called. This is not the case. On overflow, it copies only part of the string.

The fix is to change the overflow check to see if the length returned from bstr_printf() is less than the length remaining in the seq_buf buffer, and not if it is less than or equal to as it currently does. Then seq_buf_bprintf() will know if the write from bstr_printf() was truncated or not.

---
 lib/seq_buf.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 0c92583b7b7e..5c94e1012a91 100644
@@ -118,7 +118,7 @@ int seq_buf_bprintf(struct seq_buf *s, const char *fmt, const u32 *binary)
 
 	if (s->len < s->size) {
 		ret = bstr_printf(s->buffer + s->len, len, fmt, binary);
-		if (seq_buf_can_fit(s, ret)) {
+		if (s->len + ret < s->size) {
 			s->len += ret;
 			return 0;
 		}

2.1.4

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

When /proc/sys/kernel/ftrace_enabled is set to zero, all function tracing is disabled. But the records that represent the functions still hold information about the ftrace_ops that are hooked to them.

ftrace_ops may request "REGS" (have a full set of pt_regs passed to the callback), or "TRAMP" (the ops has its own trampoline to use). When the record is updated to represent the state of the ops hooked to it, it sets "REGS_EN" and/or "TRAMP_EN" to state that the callback points to the correct trampoline (REGS has its own trampoline).

When ftrace_enabled is set to zero, all ftrace locations are a nop, so they do not point to any trampoline. But the _EN flags are still set. This can cause the accounting to go wrong when ftrace_enabled is cleared and an ops that has a trampoline is registered or unregistered.

For example, the following will cause ftrace to crash:

 # echo function_graph > /sys/kernel/debug/tracing/current_tracer
 # echo 0 > /proc/sys/kernel/ftrace_enabled
 # echo nop > /sys/kernel/debug/tracing/current_tracer
 # echo 1 > /proc/sys/kernel/ftrace_enabled
 # echo function_graph > /sys/kernel/debug/tracing/current_tracer

As function_graph uses a trampoline, when ftrace_enabled is set to zero the updates to the record are not done. When enabling function_graph again, the record will still have the TRAMP_EN flag set, and it will look for an op that has a trampoline other than the function_graph ops, and fail to find one.

---
 kernel/trace/ftrace.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

index 45e5cb143d17..14947e014b78 100644
@@ -2041,8 +2041,12 @@ static int ftrace_check_record(struct dyn_ftrace *rec, int enable, int update)
 		if (!ftrace_rec_count(rec))
 			rec->flags = 0;
 		else
-			/* Just disable the record (keep REGS state) */
-			rec->flags &= ~FTRACE_FL_ENABLED;
+			/*
+			 * Just disable the record, but keep the ops TRAMP
+			 * and REGS states. The _EN flags must be disabled though.
+			 */
+			rec->flags &= ~(FTRACE_FL_ENABLED | FTRACE_FL_TRAMP_EN |
+					FTRACE_FL_REGS_EN);
 	}
 
 	return FTRACE_UPDATE_MAKE_NOP;

2.1.4

From: Pratyush Anand <[email protected]>

When ftrace is enabled globally through the proc interface, we must check if ftrace_graph_active is set. If it is set, then we should also pass the FTRACE_START_FUNC_RET command to ftrace_run_update_code(). Similarly, when ftrace is disabled globally through the proc interface, we must check if ftrace_graph_active is set. If it is set, then we should also pass the FTRACE_STOP_FUNC_RET command to ftrace_run_update_code().

Consider the following situation.

 # echo 0 > /proc/sys/kernel/ftrace_enabled

After this ftrace_enabled = 0.

 # echo function_graph > /sys/kernel/debug/tracing/current_tracer

Since ftrace_enabled = 0, ftrace_enable_ftrace_graph_caller() is never called.

 # echo 1 > /proc/sys/kernel/ftrace_enabled

Now ftrace_enabled will be set to true, but still ftrace_enable_ftrace_graph_caller() will not be called, which is not desired.

Further if we execute the following after this:

  # echo nop > /sys/kernel/debug/tracing/current_tracer

Now since ftrace_enabled is set it will call ftrace_disable_ftrace_graph_caller(), which causes a kernel warning on the ARM platform.

On the ARM platform, when ftrace_enable_ftrace_graph_caller() is called, it checks whether the old instruction is a nop or not. If it's not a nop, then it returns an error. If it is a nop then it replaces instruction at that address with a branch to ftrace_graph_caller. ftrace_disable_ftrace_graph_caller() behaves just the opposite. Therefore, if generic ftrace code ever calls either ftrace_enable_ftrace_graph_caller() or ftrace_disable_ftrace_graph_caller() consecutively two times in a row, then it will return an error, which will cause the generic ftrace code to raise a warning.

Note, x86 does not have an issue with this because the architecture specific code for ftrace_enable_ftrace_graph_caller() and ftrace_disable_ftrace_graph_caller() does not check the previous state, and calling either of these functions twice in a row has no ill effect.

[
removed extra if (ftrace_start_up) and defined ftrace_graph_active as 0 if CONFIG_FUNCTION_GRAPH_TRACER is not set.
]

---
 kernel/trace/ftrace.c | 28 ++++++++++++++++++++++------
 1 file changed, 22 insertions(+), 6 deletions(-)

index 14947e014b78..ea520bb54d44 100644
@@ -1059,6 +1059,12 @@ static __init void ftrace_profile_debugfs(struct dentry *d_tracer)
 
 static struct pid * const ftrace_swapper_pid = &init_struct_pid;
 
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+static int ftrace_graph_active;
+#else
+# define ftrace_graph_active 0
+#endif
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 static struct ftrace_ops *removed_ops;

@@ -2692,24 +2698,36 @@ static int ftrace_shutdown(struct ftrace_ops *ops, int command)
 
 static void ftrace_startup_sysctl(void)
 {
+	int command;
+
 	if (unlikely(ftrace_disabled))
 		return;
 
 	/* Force update next time */
 	saved_ftrace_func = NULL;
 	/* ftrace_start_up is true if we want ftrace running */
-	if (ftrace_start_up)
-		ftrace_run_update_code(FTRACE_UPDATE_CALLS);
+	if (ftrace_start_up) {
+		command = FTRACE_UPDATE_CALLS;
+		if (ftrace_graph_active)
+			command |= FTRACE_START_FUNC_RET;
+		ftrace_run_update_code(command);
+	}
 }
 
 static void ftrace_shutdown_sysctl(void)
 {
+	int command;
+
 	if (unlikely(ftrace_disabled))
 		return;
 
 	/* ftrace_start_up is true if ftrace is running */
-	if (ftrace_start_up)
-		ftrace_run_update_code(FTRACE_DISABLE_CALLS);
+	if (ftrace_start_up) {
+		command = FTRACE_DISABLE_CALLS;
+		if (ftrace_graph_active)
+			command |= FTRACE_STOP_FUNC_RET;
+		ftrace_run_update_code(command);
+	}
 }
 
 static cycle_t		ftrace_update_time;

@@ -5594,8 +5612,6 @@ static struct ftrace_ops graph_ops = {
 	ASSIGN_OPS_HASH(graph_ops, &global_ops.local_hash)
 };
 
-static int ftrace_graph_active;
-
 int ftrace_graph_entry_stub(struct ftrace_graph_ent *trace)
 {
 	return 0;

2.1.4

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

Some archs (specifically PowerPC), are sensitive with the ordering of the enabling of the calls to function tracing and setting of the function to use to be traced.

That is, update_ftrace_function() sets what function the ftrace_caller trampoline should call. Some archs require this to be set before calling ftrace_run_update_code().

Another bug was discovered, that ftrace_startup_sysctl() called ftrace_run_update_code() directly. If the function the ftrace_caller trampoline changes, then it will not be updated. Instead a call to ftrace_startup_enable() should be called because it tests to see if the callback changed since the code was disabled, and will tell the arch to update appropriately. Most archs do not need this notification, but PowerPC does.

The problem could be seen by the following commands:

 # echo 0 > /proc/sys/kernel/ftrace_enabled
 # echo function > /sys/kernel/debug/tracing/current_tracer
 # echo 1 > /proc/sys/kernel/ftrace_enabled
 # cat /sys/kernel/debug/tracing/trace

The trace will show that function tracing was not active.

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

index ea520bb54d44..4f228024055b 100644
@@ -2710,7 +2710,7 @@ static void ftrace_startup_sysctl(void)
 		command = FTRACE_UPDATE_CALLS;
 		if (ftrace_graph_active)
 			command |= FTRACE_START_FUNC_RET;
-		ftrace_run_update_code(command);
+		ftrace_startup_enable(command);
 	}
 }
 

@@ -5580,12 +5580,12 @@ ftrace_enable_sysctl(struct ctl_table *table, int write,
 
 	if (ftrace_enabled) {
 
-		ftrace_startup_sysctl();
-
 		/* we are starting ftrace again */
 		if (ftrace_ops_list != &ftrace_list_end)
 			update_ftrace_function();
 
+		ftrace_startup_sysctl();
+
 	} else {
 		/* stopping ftrace calls (just send to ftrace_stub) */
 		ftrace_trace_function = ftrace_stub;

2.1.4

You make no sense. The commits you list were all on top of plain 4.0-rc2.

So exactly what do you expect me to pull, or haven't I pulled?

Linus

The confusing part is that I included the patch in this series that I had in my previous pull request that you did not pull...

http://marc.info/?l=linux-kernel&m=142549997928187

-- Steve

Oh. Ok. I didn't pull that, simply because in the same thread you said you were going to fix the other case that Joe pointed out and you said "I'll make another patch". So I dismissed your previous pull request as premature..

Linus

Yeah I figured as much. But right after I did that fix, the other bug was reported to me. I decided to fix that bug before posting again, and that took a bit longer than I expected.

Sorry for the confusion, I didn't explain it very well. I should have stated this is the new update to my previous pull request with another bug fix included as well.

-- Steve