* [PATCH v4 01/11] tracing: Add tracing error log
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-26 8:22 ` Masami Hiramatsu
2019-03-22 15:34 ` [PATCH v4 02/11] tracing: Save the last hist command's associated event name Tom Zanussi
` (10 subsequent siblings)
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Introduce a new ftrace file, tracing/error_log, for ftrace commands to
log errors. This is useful for allowing more complex commands such as
hist trigger and kprobe_event commands to point out specifically where
something may have gone wrong without forcing them to resort to more
ad hoc methods such as tacking error messages onto existing output
files.
To log a tracing error, call the event_log_err() function, passing it
a location string describing where it came from e.g. kprobe_events or
system:event, the command that caused the error, an array of static
error strings describing errors and an index within that array which
describes the specific error, along with the position to place the
error caret.
Reading the log displays the last (currently) 8 errors logged in the
following format:
[timestamp] <loc>: error: <static error text>
Command: <command that caused the error>
^
Memory for the error log isn't allocated unless there has been a trace
event error, and the error log can be cleared and have its memory
freed by writing the empty string in truncation mode to it:
# echo > tracing/error_log.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Suggested-by: Masami Hiramatsu <mhiramat@kernel.org>
Improvements-suggested-by: Steve Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace.c | 223 +++++++++++++++++++++++++++++++++++++++++++++++++++
kernel/trace/trace.h | 4 +
2 files changed, 227 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ccd759eaad79..0388038a9253 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6875,6 +6875,226 @@ static const struct file_operations snapshot_raw_fops = {
#endif /* CONFIG_TRACER_SNAPSHOT */
+#define TRACING_LOG_ERRS_MAX 8
+#define TRACING_LOG_LOC_MAX 128
+
+#define CMD_PREFIX " Command: "
+
+struct err_info {
+ const char **errs; /* ptr to loc-specific array of err strings */
+ u8 type; /* index into errs -> specific err string */
+ u8 pos; /* MAX_FILTER_STR_VAL = 256 */
+ u64 ts;
+};
+
+struct tracing_log_err {
+ struct list_head list;
+ struct err_info info;
+ char loc[TRACING_LOG_LOC_MAX]; /* err location */
+ char cmd[MAX_FILTER_STR_VAL]; /* what caused err */
+};
+
+static LIST_HEAD(tracing_err_log);
+static DEFINE_MUTEX(tracing_err_log_lock);
+
+static unsigned int n_tracing_err_log_entries;
+
+struct tracing_log_err *get_tracing_log_err(void)
+{
+ struct tracing_log_err *err;
+
+ if (n_tracing_err_log_entries < TRACING_LOG_ERRS_MAX) {
+ err = kzalloc(sizeof(*err), GFP_KERNEL);
+ if (!err)
+ err = ERR_PTR(-ENOMEM);
+ n_tracing_err_log_entries++;
+
+ return err;
+ }
+
+ err = list_first_entry(&tracing_err_log, struct tracing_log_err, list);
+ list_del(&err->list);
+
+ return err;
+}
+
+/**
+ * err_pos - find the position of a string within a command for error careting
+ * @cmd: The tracing command that caused the error
+ * @str: The string to position the caret at within @cmd
+ *
+ * Finds the position of the first occurence of @str within @cmd. The
+ * return value can be passed to tracing_log_err() for caret placement
+ * within @cmd.
+ *
+ * Returns the index within @cmd of the first occurence of @str or 0
+ * if @str was not found.
+ */
+unsigned int err_pos(char *cmd, const char *str)
+{
+ char *found;
+
+ if (WARN_ON(!strlen(cmd)))
+ return 0;
+
+ found = strstr(cmd, str);
+ if (found)
+ return found - cmd;
+
+ return 0;
+}
+
+/**
+ * tracing_log_err - write an error to the tracing error log
+ * @loc: A string describing where the error occurred
+ * @cmd: The tracing command that caused the error
+ * @errs: The array of loc-specific static error strings
+ * @type: The index into errs[], which produces the specific static err string
+ * @pos: The position the caret should be placed in the cmd
+ *
+ * Writes an error into tracing/error_log of the form:
+ *
+ * <loc>: error: <text>
+ * Command: <cmd>
+ * ^
+ *
+ * tracing/error_log is a small log file containing the last
+ * TRACING_LOG_ERRS_MAX errors (8). Memory for errors isn't allocated
+ * unless there has been a tracing error, and the error log can be
+ * cleared and have its memory freed by writing the empty string in
+ * truncation mode to it i.e. echo > tracing/error_log.
+ *
+ * NOTE: the @errs array along with the @type param are used to
+ * produce a static error string - this string is not copied and saved
+ * when the error is logged - only a pointer to it is saved. See
+ * existing callers for examples of how static strings are typically
+ * defined for use with tracing_log_err().
+ */
+void tracing_log_err(const char *loc, const char *cmd,
+ const char **errs, u8 type, u8 pos)
+{
+ struct tracing_log_err *err;
+
+ mutex_lock(&tracing_err_log_lock);
+ err = get_tracing_log_err();
+ if (PTR_ERR(err) == -ENOMEM) {
+ mutex_unlock(&tracing_err_log_lock);
+ return;
+ }
+
+ snprintf(err->loc, TRACING_LOG_LOC_MAX, "%s: error: ", loc);
+ snprintf(err->cmd, MAX_FILTER_STR_VAL,"\n" CMD_PREFIX "%s\n", cmd);
+
+ err->info.errs = errs;
+ err->info.type = type;
+ err->info.pos = pos;
+ err->info.ts = local_clock();
+
+ list_add_tail(&err->list, &tracing_err_log);
+ mutex_unlock(&tracing_err_log_lock);
+}
+
+static void clear_tracing_err_log(void)
+{
+ struct tracing_log_err *err, *next;
+
+ mutex_lock(&tracing_err_log_lock);
+ list_for_each_entry_safe(err, next, &tracing_err_log, list) {
+ list_del(&err->list);
+ kfree(err);
+ }
+
+ n_tracing_err_log_entries = 0;
+ mutex_unlock(&tracing_err_log_lock);
+}
+
+static void *tracing_err_log_seq_start(struct seq_file *m, loff_t *pos)
+{
+ mutex_lock(&tracing_err_log_lock);
+
+ return seq_list_start(&tracing_err_log, *pos);
+}
+
+static void *tracing_err_log_seq_next(struct seq_file *m, void *v, loff_t *pos)
+{
+ return seq_list_next(v, &tracing_err_log, pos);
+}
+
+static void tracing_err_log_seq_stop(struct seq_file *m, void *v)
+{
+ mutex_unlock(&tracing_err_log_lock);
+}
+
+static void tracing_err_log_show_pos(struct seq_file *m, u8 pos)
+{
+ u8 i;
+
+ for (i = 0; i < sizeof(CMD_PREFIX) - 1; i++)
+ seq_putc(m, ' ');
+ for (i = 0; i < pos; i++)
+ seq_putc(m, ' ');
+ seq_puts(m, "^\n");
+}
+
+static int tracing_err_log_seq_show(struct seq_file *m, void *v)
+{
+ struct tracing_log_err *err = v;
+
+ if (err) {
+ const char *err_text = err->info.errs[err->info.type];
+ u64 sec = err->info.ts;
+ u32 nsec;
+
+ nsec = do_div(sec, NSEC_PER_SEC);
+ seq_printf(m, "[%5llu.%06u] %s%s", sec, nsec / 1000,
+ err->loc, err_text);
+ seq_printf(m, "%s", err->cmd);
+ tracing_err_log_show_pos(m, err->info.pos);
+ }
+
+ return 0;
+}
+
+static const struct seq_operations tracing_err_log_seq_ops = {
+ .start = tracing_err_log_seq_start,
+ .next = tracing_err_log_seq_next,
+ .stop = tracing_err_log_seq_stop,
+ .show = tracing_err_log_seq_show
+};
+
+static int tracing_err_log_open(struct inode *inode, struct file *file)
+{
+ if (file->f_mode & FMODE_WRITE) {
+ if (file->f_flags & O_TRUNC)
+ return 0;
+ else
+ return -EINVAL;
+ }
+
+ return seq_open(file, &tracing_err_log_seq_ops);
+}
+
+static ssize_t tracing_err_log_write(struct file *file,
+ const char __user *buffer,
+ size_t count, loff_t *ppos)
+{
+ if (count == 1)
+ clear_tracing_err_log();
+ else
+ return -EINVAL;
+
+ *ppos += count;
+
+ return count;
+}
+
+static const struct file_operations tracing_err_log_fops = {
+ .open = tracing_err_log_open,
+ .write = tracing_err_log_write,
+ .read = seq_read,
+ .llseek = seq_lseek,
+};
+
static int tracing_buffers_open(struct inode *inode, struct file *filp)
{
struct trace_array *tr = inode->i_private;
@@ -8258,6 +8478,9 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer)
tr, &snapshot_fops);
#endif
+ trace_create_file("error_log", 0644, d_tracer,
+ tr, &tracing_err_log_fops);
+
for_each_tracing_cpu(cpu)
tracing_init_tracefs_percpu(tr, cpu);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index d80cee49e0eb..b711edbef7e7 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1884,6 +1884,10 @@ extern ssize_t trace_parse_run_command(struct file *file,
const char __user *buffer, size_t count, loff_t *ppos,
int (*createfn)(int, char**));
+extern unsigned int err_pos(char *cmd, const char *str);
+extern void tracing_log_err(const char *loc, const char *cmd,
+ const char **errs, u8 type, u8 pos);
+
/*
* Normal trace_printk() and friends allocates special buffers
* to do the manipulation, as well as saves the print formats
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 01/11] tracing: Add tracing error log
2019-03-22 15:34 ` [PATCH v4 01/11] tracing: Add tracing error log Tom Zanussi
@ 2019-03-26 8:22 ` Masami Hiramatsu
0 siblings, 0 replies; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-26 8:22 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
Hi Tom,
On Fri, 22 Mar 2019 10:34:27 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> +static int tracing_err_log_open(struct inode *inode, struct file *file)
> +{
> + if (file->f_mode & FMODE_WRITE) {
> + if (file->f_flags & O_TRUNC)
> + return 0;
> + else
> + return -EINVAL;
> + }
> +
> + return seq_open(file, &tracing_err_log_seq_ops);
> +}
> +
> +static ssize_t tracing_err_log_write(struct file *file,
> + const char __user *buffer,
> + size_t count, loff_t *ppos)
> +{
> + if (count == 1)
> + clear_tracing_err_log();
> + else
> + return -EINVAL;
> +
> + *ppos += count;
> +
> + return count;
> +}
Hmm, could you make this as same as "tracing/trace"?
- It clears buffer at open with WRITE & TRUNC flag
- It just ignore how much user wrote (works as /dev/null)
See tracing_open() and tracing_write_stub() in
kernel/trace/trace.c.
Thank you,
> +
> +static const struct file_operations tracing_err_log_fops = {
> + .open = tracing_err_log_open,
> + .write = tracing_err_log_write,
> + .read = seq_read,
> + .llseek = seq_lseek,
> +};
> +
> static int tracing_buffers_open(struct inode *inode, struct file *filp)
> {
> struct trace_array *tr = inode->i_private;
> @@ -8258,6 +8478,9 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer)
> tr, &snapshot_fops);
> #endif
>
> + trace_create_file("error_log", 0644, d_tracer,
> + tr, &tracing_err_log_fops);
> +
> for_each_tracing_cpu(cpu)
> tracing_init_tracefs_percpu(tr, cpu);
>
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index d80cee49e0eb..b711edbef7e7 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1884,6 +1884,10 @@ extern ssize_t trace_parse_run_command(struct file *file,
> const char __user *buffer, size_t count, loff_t *ppos,
> int (*createfn)(int, char**));
>
> +extern unsigned int err_pos(char *cmd, const char *str);
> +extern void tracing_log_err(const char *loc, const char *cmd,
> + const char **errs, u8 type, u8 pos);
> +
> /*
> * Normal trace_printk() and friends allocates special buffers
> * to do the manipulation, as well as saves the print formats
> --
> 2.14.1
>
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v4 02/11] tracing: Save the last hist command's associated event name
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 01/11] tracing: Add tracing error log Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 03/11] tracing: Use tracing error_log with hist triggers Tom Zanussi
` (9 subsequent siblings)
11 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
In preparation for making use of the new trace error log, save the
subsystem and event name associated with the last hist command - it
will be passed as the location param in the event_log_err() calls.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace_events_hist.c | 33 +++++++++++++++++++++++++++------
1 file changed, 27 insertions(+), 6 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index ca46339f3009..e93b59d80274 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -535,15 +535,34 @@ static struct track_data *track_data_alloc(unsigned int key_len,
return data;
}
-static char last_hist_cmd[MAX_FILTER_STR_VAL];
+static char last_cmd[MAX_FILTER_STR_VAL];
+static char last_cmd_loc[MAX_FILTER_STR_VAL];
+
static char hist_err_str[MAX_FILTER_STR_VAL];
-static void last_cmd_set(char *str)
+static void last_cmd_set(struct trace_event_file *file, char *str)
{
+ const char *system = NULL, *name = NULL;
+ struct trace_event_call *call;
+
if (!str)
return;
- strncpy(last_hist_cmd, str, MAX_FILTER_STR_VAL - 1);
+ strncpy(last_cmd, str, MAX_FILTER_STR_VAL - 1);
+
+ if (file) {
+ call = file->event_call;
+
+ system = call->class->system;
+ if (system) {
+ name = trace_event_name(call);
+ if (!name)
+ system = NULL;
+ }
+ }
+
+ if (system)
+ snprintf(last_cmd_loc, MAX_FILTER_STR_VAL, "hist:%s:%s", system, name);
}
static void hist_err(char *str, char *var)
@@ -583,6 +602,8 @@ static void hist_err_event(char *str, char *system, char *event, char *var)
static void hist_err_clear(void)
{
hist_err_str[0] = '\0';
+ last_cmd[0] = '\0';
+ last_cmd_loc[0] = '\0';
}
static bool have_hist_err(void)
@@ -5439,8 +5460,8 @@ static int hist_show(struct seq_file *m, void *v)
}
if (have_hist_err()) {
- seq_printf(m, "\nERROR: %s\n", hist_err_str);
- seq_printf(m, " Last command: %s\n", last_hist_cmd);
+ seq_printf(m, "\n%s: error: \n", hist_err_str);
+ seq_printf(m, " Last command: %s\n", last_cmd);
}
out_unlock:
@@ -6044,8 +6065,8 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
lockdep_assert_held(&event_mutex);
if (glob && strlen(glob)) {
- last_cmd_set(param);
hist_err_clear();
+ last_cmd_set(file, param);
}
if (!param)
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* [PATCH v4 03/11] tracing: Use tracing error_log with hist triggers
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 01/11] tracing: Add tracing error log Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 02/11] tracing: Save the last hist command's associated event name Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters Tom Zanussi
` (8 subsequent siblings)
11 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Replace hist_err() and hist_err_event() with tracing_log_err() from
the new tracing error_log mechanism.
Also add a couple related helper functions and remove most of the old
hist_err()-related code.
With this change, users no longer read the hist files for hist trigger
error information, but instead look at tracing/error_log for the same
information.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++-------------------
1 file changed, 104 insertions(+), 102 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index e93b59d80274..88100c39527c 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -22,6 +22,57 @@
#define STR_VAR_LEN_MAX 32 /* must be multiple of sizeof(u64) */
+#define ERRORS \
+ C(NONE, "No error"), \
+ C(DUPLICATE_VAR, "Variable already defined"), \
+ C(VAR_NOT_UNIQUE, "Variable name not unique, need to use fully qualified name (subsys.event.var) for variable"), \
+ C(TOO_MANY_VARS, "Too many variables defined"), \
+ C(MALFORMED_ASSIGNMENT, "Malformed assignment"), \
+ C(NAMED_MISMATCH, "Named hist trigger doesn't match existing named trigger (includes variables)"), \
+ C(TRIGGER_EEXIST, "Hist trigger already exists"), \
+ C(TRIGGER_ENOENT_CLEAR, "Can't clear or continue a nonexistent hist trigger"), \
+ C(SET_CLOCK_FAIL, "Couldn't set trace_clock"), \
+ C(BAD_FIELD_MODIFIER, "Invalid field modifier"), \
+ C(TOO_MANY_SUBEXPR, "Too many subexpressions (3 max)"), \
+ C(TIMESTAMP_MISMATCH, "Timestamp units in expression don't match"), \
+ C(TOO_MANY_FIELD_VARS, "Too many field variables defined"), \
+ C(EVENT_FILE_NOT_FOUND, "Event file not found"), \
+ C(HIST_NOT_FOUND, "Matching event histogram not found"), \
+ C(HIST_CREATE_FAIL, "Couldn't create histogram for field"), \
+ C(SYNTH_VAR_NOT_FOUND, "Couldn't find synthetic variable"), \
+ C(SYNTH_EVENT_NOT_FOUND,"Couldn't find synthetic event"), \
+ C(SYNTH_TYPE_MISMATCH, "Param type doesn't match synthetic event field type"), \
+ C(SYNTH_COUNT_MISMATCH, "Param count doesn't match synthetic event field count"), \
+ C(FIELD_VAR_PARSE_FAIL, "Couldn't parse field variable"), \
+ C(VAR_CREATE_FIND_FAIL, "Couldn't create or find variable"), \
+ C(ONX_NOT_VAR, "For onmax(x) or onchange(x), x must be a variable"), \
+ C(ONX_VAR_NOT_FOUND, "Couldn't find onmax or onchange variable"), \
+ C(ONX_VAR_CREATE_FAIL, "Couldn't create onmax or onchange variable"), \
+ C(FIELD_VAR_CREATE_FAIL,"Couldn't create field variable"), \
+ C(TOO_MANY_PARAMS, "Too many action params"), \
+ C(PARAM_NOT_FOUND, "Couldn't find param"), \
+ C(INVALID_PARAM, "Invalid action param"), \
+ C(ACTION_NOT_FOUND, "No action found"), \
+ C(NO_SAVE_PARAMS, "No params found for save()"), \
+ C(TOO_MANY_SAVE_ACTIONS,"Can't have more than one save() action per hist"), \
+ C(ACTION_MISMATCH, "Handler doesn't support action"), \
+ C(NO_CLOSING_PAREN, "No closing paren found"), \
+ C(SUBSYS_NOT_FOUND, "Missing subsystem"), \
+ C(INVALID_SUBSYS_EVENT, "Invalid subsystem or event name"), \
+ C(INVALID_REF_KEY, "Using variable references as keys not supported"), \
+ C(VAR_NOT_FOUND, "Couldn't find variable"), \
+ C(FIELD_NOT_FOUND, "Couldn't find field"),
+
+#undef C
+#define C(a, b) HIST_ERR_##a
+
+enum { ERRORS };
+
+#undef C
+#define C(a, b) b
+
+static const char *err_text[] = { ERRORS };
+
struct hist_field;
typedef u64 (*hist_field_fn_t) (struct hist_field *field,
@@ -538,7 +589,10 @@ static struct track_data *track_data_alloc(unsigned int key_len,
static char last_cmd[MAX_FILTER_STR_VAL];
static char last_cmd_loc[MAX_FILTER_STR_VAL];
-static char hist_err_str[MAX_FILTER_STR_VAL];
+static int errpos(char *str)
+{
+ return err_pos(last_cmd, str);
+}
static void last_cmd_set(struct trace_event_file *file, char *str)
{
@@ -565,55 +619,17 @@ static void last_cmd_set(struct trace_event_file *file, char *str)
snprintf(last_cmd_loc, MAX_FILTER_STR_VAL, "hist:%s:%s", system, name);
}
-static void hist_err(char *str, char *var)
+static void hist_err(u8 err_type, u8 err_pos)
{
- int maxlen = MAX_FILTER_STR_VAL - 1;
-
- if (!str)
- return;
-
- if (strlen(hist_err_str))
- return;
-
- if (!var)
- var = "";
-
- if (strlen(hist_err_str) + strlen(str) + strlen(var) > maxlen)
- return;
-
- strcat(hist_err_str, str);
- strcat(hist_err_str, var);
-}
-
-static void hist_err_event(char *str, char *system, char *event, char *var)
-{
- char err[MAX_FILTER_STR_VAL];
-
- if (system && var)
- snprintf(err, MAX_FILTER_STR_VAL, "%s.%s.%s", system, event, var);
- else if (system)
- snprintf(err, MAX_FILTER_STR_VAL, "%s.%s", system, event);
- else
- strscpy(err, var, MAX_FILTER_STR_VAL);
-
- hist_err(str, err);
+ tracing_log_err(last_cmd_loc, last_cmd, err_text, err_type, err_pos);
}
static void hist_err_clear(void)
{
- hist_err_str[0] = '\0';
last_cmd[0] = '\0';
last_cmd_loc[0] = '\0';
}
-static bool have_hist_err(void)
-{
- if (strlen(hist_err_str))
- return true;
-
- return false;
-}
-
struct synth_trace_event {
struct trace_entry ent;
u64 fields[];
@@ -1740,7 +1756,7 @@ static struct trace_event_file *find_var_file(struct trace_array *tr,
if (find_var_field(var_hist_data, var_name)) {
if (found) {
- hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name);
+ hist_err(HIST_ERR_VAR_NOT_UNIQUE, errpos(var_name));
return NULL;
}
@@ -1791,7 +1807,7 @@ find_match_var(struct hist_trigger_data *hist_data, char *var_name)
hist_field = find_file_var(file, var_name);
if (hist_field) {
if (found) {
- hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name);
+ hist_err(HIST_ERR_VAR_NOT_UNIQUE, errpos(var_name));
return ERR_PTR(-EINVAL);
}
@@ -2023,7 +2039,6 @@ static int parse_action(char *str, struct hist_trigger_attrs *attrs)
attrs->n_actions++;
ret = 0;
}
-
return ret;
}
@@ -2083,7 +2098,7 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs)
char *assignment;
if (attrs->n_assignments == TRACING_MAP_VARS_MAX) {
- hist_err("Too many variables defined: ", str);
+ hist_err(HIST_ERR_TOO_MANY_VARS, errpos(str));
ret = -EINVAL;
goto out;
}
@@ -2681,8 +2696,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
system, event_name);
if (!ref_field)
- hist_err_event("Couldn't find variable: $",
- system, event_name, var_name);
+ hist_err(HIST_ERR_VAR_NOT_FOUND, errpos(var_name));
return ref_field;
}
@@ -2716,7 +2730,7 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
else if (strcmp(modifier, "usecs") == 0)
*flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
else {
- hist_err("Invalid field modifier: ", modifier);
+ hist_err(HIST_ERR_BAD_FIELD_MODIFIER, errpos(modifier));
field = ERR_PTR(-EINVAL);
goto out;
}
@@ -2732,7 +2746,7 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
else {
field = trace_find_event_field(file->event_call, field_name);
if (!field || !field->size) {
- hist_err("Couldn't find field: ", field_name);
+ hist_err(HIST_ERR_FIELD_NOT_FOUND, errpos(field_name));
field = ERR_PTR(-EINVAL);
goto out;
}
@@ -2843,7 +2857,7 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
/* we support only -(xxx) i.e. explicit parens required */
if (level > 3) {
- hist_err("Too many subexpressions (3 max): ", str);
+ hist_err(HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
ret = -EINVAL;
goto free;
}
@@ -2926,7 +2940,7 @@ static int check_expr_operands(struct hist_field *operand1,
if ((operand1_flags & HIST_FIELD_FL_TIMESTAMP_USECS) !=
(operand2_flags & HIST_FIELD_FL_TIMESTAMP_USECS)) {
- hist_err("Timestamp units in expression don't match", NULL);
+ hist_err(HIST_ERR_TIMESTAMP_MISMATCH, 0);
return -EINVAL;
}
@@ -2944,7 +2958,7 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
char *sep, *operand1_str;
if (level > 3) {
- hist_err("Too many subexpressions (3 max): ", str);
+ hist_err(HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
return ERR_PTR(-EINVAL);
}
@@ -3182,16 +3196,14 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
int ret;
if (target_hist_data->n_field_var_hists >= SYNTH_FIELDS_MAX) {
- hist_err_event("trace action: Too many field variables defined: ",
- subsys_name, event_name, field_name);
+ hist_err(HIST_ERR_TOO_MANY_FIELD_VARS, errpos(field_name));
return ERR_PTR(-EINVAL);
}
file = event_file(tr, subsys_name, event_name);
if (IS_ERR(file)) {
- hist_err_event("trace action: Event file not found: ",
- subsys_name, event_name, field_name);
+ hist_err(HIST_ERR_EVENT_FILE_NOT_FOUND, errpos(field_name));
ret = PTR_ERR(file);
return ERR_PTR(ret);
}
@@ -3204,8 +3216,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
*/
hist_data = find_compatible_hist(target_hist_data, file);
if (!hist_data) {
- hist_err_event("trace action: Matching event histogram not found: ",
- subsys_name, event_name, field_name);
+ hist_err(HIST_ERR_HIST_NOT_FOUND, errpos(field_name));
return ERR_PTR(-EINVAL);
}
@@ -3266,8 +3277,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
kfree(cmd);
kfree(var_hist->cmd);
kfree(var_hist);
- hist_err_event("trace action: Couldn't create histogram for field: ",
- subsys_name, event_name, field_name);
+ hist_err(HIST_ERR_HIST_CREATE_FAIL, errpos(field_name));
return ERR_PTR(ret);
}
@@ -3279,8 +3289,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
if (IS_ERR_OR_NULL(event_var)) {
kfree(var_hist->cmd);
kfree(var_hist);
- hist_err_event("trace action: Couldn't find synthetic variable: ",
- subsys_name, event_name, field_name);
+ hist_err(HIST_ERR_SYNTH_VAR_NOT_FOUND, errpos(field_name));
return ERR_PTR(-EINVAL);
}
@@ -3417,21 +3426,21 @@ static struct field_var *create_field_var(struct hist_trigger_data *hist_data,
int ret = 0;
if (hist_data->n_field_vars >= SYNTH_FIELDS_MAX) {
- hist_err("Too many field variables defined: ", field_name);
+ hist_err(HIST_ERR_TOO_MANY_FIELD_VARS, errpos(field_name));
ret = -EINVAL;
goto err;
}
val = parse_atom(hist_data, file, field_name, &flags, NULL);
if (IS_ERR(val)) {
- hist_err("Couldn't parse field variable: ", field_name);
+ hist_err(HIST_ERR_FIELD_VAR_PARSE_FAIL, errpos(field_name));
ret = PTR_ERR(val);
goto err;
}
var = create_var(hist_data, file, field_name, val->size, val->type);
if (IS_ERR(var)) {
- hist_err("Couldn't create or find variable: ", field_name);
+ hist_err(HIST_ERR_VAR_CREATE_FIND_FAIL, errpos(field_name));
kfree(val);
ret = PTR_ERR(var);
goto err;
@@ -3764,14 +3773,14 @@ static int track_data_create(struct hist_trigger_data *hist_data,
track_data_var_str = data->track_data.var_str;
if (track_data_var_str[0] != '$') {
- hist_err("For onmax(x) or onchange(x), x must be a variable: ", track_data_var_str);
+ hist_err(HIST_ERR_ONX_NOT_VAR, errpos(track_data_var_str));
return -EINVAL;
}
track_data_var_str++;
var_field = find_target_event_var(hist_data, NULL, NULL, track_data_var_str);
if (!var_field) {
- hist_err("Couldn't find onmax or onchange variable: ", track_data_var_str);
+ hist_err(HIST_ERR_ONX_VAR_NOT_FOUND, errpos(track_data_var_str));
return -EINVAL;
}
@@ -3784,7 +3793,7 @@ static int track_data_create(struct hist_trigger_data *hist_data,
if (data->handler == HANDLER_ONMAX)
track_var = create_var(hist_data, file, "__max", sizeof(u64), "u64");
if (IS_ERR(track_var)) {
- hist_err("Couldn't create onmax variable: ", "__max");
+ hist_err(HIST_ERR_ONX_VAR_CREATE_FAIL, 0);
ret = PTR_ERR(track_var);
goto out;
}
@@ -3792,7 +3801,7 @@ static int track_data_create(struct hist_trigger_data *hist_data,
if (data->handler == HANDLER_ONCHANGE)
track_var = create_var(hist_data, file, "__change", sizeof(u64), "u64");
if (IS_ERR(track_var)) {
- hist_err("Couldn't create onchange variable: ", "__change");
+ hist_err(HIST_ERR_ONX_VAR_CREATE_FAIL, 0);
ret = PTR_ERR(track_var);
goto out;
}
@@ -3811,20 +3820,20 @@ static int parse_action_params(char *params, struct action_data *data)
while (params) {
if (data->n_params >= SYNTH_FIELDS_MAX) {
- hist_err("Too many action params", "");
+ hist_err(HIST_ERR_TOO_MANY_PARAMS, 0);
goto out;
}
param = strsep(¶ms, ",");
if (!param) {
- hist_err("No action param found", "");
+ hist_err(HIST_ERR_PARAM_NOT_FOUND, 0);
ret = -EINVAL;
goto out;
}
param = strstrip(param);
if (strlen(param) < 2) {
- hist_err("Invalid action param: ", param);
+ hist_err(HIST_ERR_INVALID_PARAM, errpos(param));
ret = -EINVAL;
goto out;
}
@@ -3856,14 +3865,14 @@ static int action_parse(char *str, struct action_data *data,
strsep(&str, ".");
if (!str) {
- hist_err("action parsing: No action found", "");
+ hist_err(HIST_ERR_ACTION_NOT_FOUND, 0);
ret = -EINVAL;
goto out;
}
action_name = strsep(&str, "(");
if (!action_name || !str) {
- hist_err("action parsing: No action found", "");
+ hist_err(HIST_ERR_ACTION_NOT_FOUND, 0);
ret = -EINVAL;
goto out;
}
@@ -3872,7 +3881,7 @@ static int action_parse(char *str, struct action_data *data,
char *params = strsep(&str, ")");
if (!params) {
- hist_err("action parsing: No params found for %s", "save");
+ hist_err(HIST_ERR_NO_SAVE_PARAMS, 0);
ret = -EINVAL;
goto out;
}
@@ -3886,7 +3895,7 @@ static int action_parse(char *str, struct action_data *data,
else if (handler == HANDLER_ONCHANGE)
data->track_data.check_val = check_track_val_changed;
else {
- hist_err("action parsing: Handler doesn't support action: ", action_name);
+ hist_err(HIST_ERR_ACTION_MISMATCH, errpos(action_name));
ret = -EINVAL;
goto out;
}
@@ -3898,7 +3907,7 @@ static int action_parse(char *str, struct action_data *data,
char *params = strsep(&str, ")");
if (!str) {
- hist_err("action parsing: No closing paren found: %s", params);
+ hist_err(HIST_ERR_NO_CLOSING_PAREN, errpos(params));
ret = -EINVAL;
goto out;
}
@@ -3908,7 +3917,7 @@ static int action_parse(char *str, struct action_data *data,
else if (handler == HANDLER_ONCHANGE)
data->track_data.check_val = check_track_val_changed;
else {
- hist_err("action parsing: Handler doesn't support action: ", action_name);
+ hist_err(HIST_ERR_ACTION_MISMATCH, errpos(action_name));
ret = -EINVAL;
goto out;
}
@@ -4061,7 +4070,7 @@ trace_action_find_var(struct hist_trigger_data *hist_data,
}
if (!hist_field)
- hist_err_event("trace action: Couldn't find param: $", system, event, var);
+ hist_err(HIST_ERR_PARAM_NOT_FOUND, errpos(var));
return hist_field;
}
@@ -4136,7 +4145,7 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
event = find_synth_event(synth_event_name);
if (!event) {
- hist_err("trace action: Couldn't find synthetic event: ", synth_event_name);
+ hist_err(HIST_ERR_SYNTH_EVENT_NOT_FOUND, errpos(synth_event_name));
return -EINVAL;
}
@@ -4197,15 +4206,14 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
continue;
}
- hist_err_event("trace action: Param type doesn't match synthetic event field type: ",
- system, event_name, param);
+ hist_err(HIST_ERR_SYNTH_TYPE_MISMATCH, errpos(param));
kfree(p);
ret = -EINVAL;
goto err;
}
if (field_pos != event->n_fields) {
- hist_err("trace action: Param count doesn't match synthetic event field count: ", event->name);
+ hist_err(HIST_ERR_SYNTH_COUNT_MISMATCH, errpos(event->name));
ret = -EINVAL;
goto err;
}
@@ -4251,7 +4259,7 @@ static int action_create(struct hist_trigger_data *hist_data,
if (data->action == ACTION_SAVE) {
if (hist_data->n_save_vars) {
ret = -EEXIST;
- hist_err("save action: Can't have more than one save() action per hist", "");
+ hist_err(HIST_ERR_TOO_MANY_SAVE_ACTIONS, 0);
goto out;
}
@@ -4264,7 +4272,7 @@ static int action_create(struct hist_trigger_data *hist_data,
field_var = create_target_field_var(hist_data, NULL, NULL, param);
if (IS_ERR(field_var)) {
- hist_err("save action: Couldn't create field variable: ", param);
+ hist_err(HIST_ERR_FIELD_VAR_CREATE_FAIL, errpos(param));
ret = PTR_ERR(field_var);
kfree(param);
goto out;
@@ -4298,19 +4306,18 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str)
match_event = strsep(&str, ")");
if (!match_event || !str) {
- hist_err("onmatch: Missing closing paren: ", match_event);
+ hist_err(HIST_ERR_NO_CLOSING_PAREN, errpos(match_event));
goto free;
}
match_event_system = strsep(&match_event, ".");
if (!match_event) {
- hist_err("onmatch: Missing subsystem for match event: ", match_event_system);
+ hist_err(HIST_ERR_SUBSYS_NOT_FOUND, errpos(match_event_system));
goto free;
}
if (IS_ERR(event_file(tr, match_event_system, match_event))) {
- hist_err_event("onmatch: Invalid subsystem or event name: ",
- match_event_system, match_event, NULL);
+ hist_err(HIST_ERR_INVALID_SUBSYS_EVENT, errpos(match_event));
goto free;
}
@@ -4401,7 +4408,7 @@ static int create_var_field(struct hist_trigger_data *hist_data,
return -EINVAL;
if (find_var(hist_data, file, var_name) && !hist_data->remove) {
- hist_err("Variable already defined: ", var_name);
+ hist_err(HIST_ERR_DUPLICATE_VAR, errpos(var_name));
return -EINVAL;
}
@@ -4482,7 +4489,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
}
if (hist_field->flags & HIST_FIELD_FL_VAR_REF) {
- hist_err("Using variable references as keys not supported: ", field_str);
+ hist_err(HIST_ERR_INVALID_REF_KEY, errpos(field_str));
destroy_hist_field(hist_field, 0);
ret = -EINVAL;
goto out;
@@ -4596,13 +4603,13 @@ static int parse_var_defs(struct hist_trigger_data *hist_data)
var_name = strsep(&field_str, "=");
if (!var_name || !field_str) {
- hist_err("Malformed assignment: ", var_name);
+ hist_err(HIST_ERR_MALFORMED_ASSIGNMENT, errpos(var_name));
ret = -EINVAL;
goto free;
}
if (n_vars == TRACING_MAP_VARS_MAX) {
- hist_err("Too many variables defined: ", var_name);
+ hist_err(HIST_ERR_TOO_MANY_VARS, errpos(var_name));
ret = -EINVAL;
goto free;
}
@@ -5459,11 +5466,6 @@ static int hist_show(struct seq_file *m, void *v)
hist_trigger_show(m, data, n++);
}
- if (have_hist_err()) {
- seq_printf(m, "\n%s: error: \n", hist_err_str);
- seq_printf(m, " Last command: %s\n", last_cmd);
- }
-
out_unlock:
mutex_unlock(&event_mutex);
@@ -5835,7 +5837,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
if (named_data) {
if (!hist_trigger_match(data, named_data, named_data,
true)) {
- hist_err("Named hist trigger doesn't match existing named trigger (includes variables): ", hist_data->attrs->name);
+ hist_err(HIST_ERR_NAMED_MISMATCH, errpos(hist_data->attrs->name));
ret = -EINVAL;
goto out;
}
@@ -5856,7 +5858,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
else if (hist_data->attrs->clear)
hist_clear(test);
else {
- hist_err("Hist trigger already exists", NULL);
+ hist_err(HIST_ERR_TRIGGER_EEXIST, 0);
ret = -EEXIST;
}
goto out;
@@ -5864,7 +5866,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
}
new:
if (hist_data->attrs->cont || hist_data->attrs->clear) {
- hist_err("Can't clear or continue a nonexistent hist trigger", NULL);
+ hist_err(HIST_ERR_TRIGGER_ENOENT_CLEAR, 0);
ret = -ENOENT;
goto out;
}
@@ -5889,7 +5891,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
ret = tracing_set_clock(file->tr, hist_data->attrs->clock);
if (ret) {
- hist_err("Couldn't set trace_clock: ", clock);
+ hist_err(HIST_ERR_SET_CLOCK_FAIL, errpos(clock));
goto out;
}
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (2 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 03/11] tracing: Use tracing error_log with hist triggers Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-25 11:37 ` Namhyung Kim
2019-03-22 15:34 ` [PATCH v4 05/11] tracing: Use tracing error_log with probe events Tom Zanussi
` (7 subsequent siblings)
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Use tracing_log_err() from the new tracing error_log mechanism to send
filter parse errors to tracing/error_log.
With this change, users will be able to see filter errors by looking
at tracing/error_log.
The same errors will also be available in the filter file, as
expected.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace_events_filter.c | 7 +++++--
1 file changed, 5 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index ade606c33231..3a1ed8631aa0 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -66,7 +66,8 @@ static const char * ops[] = { OPS };
C(INVALID_FILTER, "Meaningless filter expression"), \
C(IP_FIELD_ONLY, "Only 'ip' field is supported for function trace"), \
C(INVALID_VALUE, "Invalid value (did you forget quotes)?"), \
- C(NO_FILTER, "No filter found"),
+ C(ERRNO, "Error"), \
+ C(NO_FILTER, "No filter found")
#undef C
#define C(a, b) FILT_ERR_##a
@@ -76,7 +77,7 @@ enum { ERRORS };
#undef C
#define C(a, b) b
-static char *err_text[] = { ERRORS };
+static const char *err_text[] = { ERRORS };
/* Called after a '!' character but "!=" and "!~" are not "not"s */
static bool is_not(const char *str)
@@ -947,8 +948,10 @@ static void append_filter_err(struct filter_parse_error *pe,
if (pe->lasterr > 0) {
trace_seq_printf(s, "\n%*s", pos, "^");
trace_seq_printf(s, "\nparse_error: %s\n", err_text[pe->lasterr]);
+ tracing_log_err("event filter parse error", filter->filter_string, err_text, pe->lasterr, pe->lasterr_pos);
} else {
trace_seq_printf(s, "\nError: (%d)\n", pe->lasterr);
+ tracing_log_err("event filter parse error", filter->filter_string, err_text, FILT_ERR_ERRNO, 0);
}
trace_seq_putc(s, 0);
buf = kmemdup_nul(s->buffer, s->seq.len, GFP_KERNEL);
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters
2019-03-22 15:34 ` [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters Tom Zanussi
@ 2019-03-25 11:37 ` Namhyung Kim
2019-03-25 14:28 ` Steven Rostedt
0 siblings, 1 reply; 25+ messages in thread
From: Namhyung Kim @ 2019-03-25 11:37 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, bigeasy, joel, linux-kernel, linux-rt-users
Hi Tom,
On Fri, Mar 22, 2019 at 10:34:30AM -0500, Tom Zanussi wrote:
> From: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> Use tracing_log_err() from the new tracing error_log mechanism to send
> filter parse errors to tracing/error_log.
>
> With this change, users will be able to see filter errors by looking
> at tracing/error_log.
>
> The same errors will also be available in the filter file, as
> expected.
>
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
> kernel/trace/trace_events_filter.c | 7 +++++--
> 1 file changed, 5 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> index ade606c33231..3a1ed8631aa0 100644
> --- a/kernel/trace/trace_events_filter.c
> +++ b/kernel/trace/trace_events_filter.c
> @@ -66,7 +66,8 @@ static const char * ops[] = { OPS };
> C(INVALID_FILTER, "Meaningless filter expression"), \
> C(IP_FIELD_ONLY, "Only 'ip' field is supported for function trace"), \
> C(INVALID_VALUE, "Invalid value (did you forget quotes)?"), \
> - C(NO_FILTER, "No filter found"),
> + C(ERRNO, "Error"), \
> + C(NO_FILTER, "No filter found")
>
> #undef C
> #define C(a, b) FILT_ERR_##a
> @@ -76,7 +77,7 @@ enum { ERRORS };
> #undef C
> #define C(a, b) b
>
> -static char *err_text[] = { ERRORS };
> +static const char *err_text[] = { ERRORS };
>
> /* Called after a '!' character but "!=" and "!~" are not "not"s */
> static bool is_not(const char *str)
> @@ -947,8 +948,10 @@ static void append_filter_err(struct filter_parse_error *pe,
> if (pe->lasterr > 0) {
> trace_seq_printf(s, "\n%*s", pos, "^");
> trace_seq_printf(s, "\nparse_error: %s\n", err_text[pe->lasterr]);
> + tracing_log_err("event filter parse error", filter->filter_string, err_text, pe->lasterr, pe->lasterr_pos);
> } else {
> trace_seq_printf(s, "\nError: (%d)\n", pe->lasterr);
> + tracing_log_err("event filter parse error", filter->filter_string, err_text, FILT_ERR_ERRNO, 0);
These lines are too long, could you please wrap?
Otherwise, the whole series look good to me.
Acked-by: Namhyung Kim <namhyung@kernel.org>
Thanks,
Namhyung
> }
> trace_seq_putc(s, 0);
> buf = kmemdup_nul(s->buffer, s->seq.len, GFP_KERNEL);
> --
> 2.14.1
>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters
2019-03-25 11:37 ` Namhyung Kim
@ 2019-03-25 14:28 ` Steven Rostedt
0 siblings, 0 replies; 25+ messages in thread
From: Steven Rostedt @ 2019-03-25 14:28 UTC (permalink / raw)
To: Namhyung Kim
Cc: Tom Zanussi, tglx, mhiramat, bigeasy, joel, linux-kernel, linux-rt-users
On Mon, 25 Mar 2019 20:37:23 +0900
Namhyung Kim <namhyung@kernel.org> wrote:
> > /* Called after a '!' character but "!=" and "!~" are not "not"s */
> > static bool is_not(const char *str)
> > @@ -947,8 +948,10 @@ static void append_filter_err(struct filter_parse_error *pe,
> > if (pe->lasterr > 0) {
> > trace_seq_printf(s, "\n%*s", pos, "^");
> > trace_seq_printf(s, "\nparse_error: %s\n", err_text[pe->lasterr]);
> > + tracing_log_err("event filter parse error", filter->filter_string, err_text, pe->lasterr, pe->lasterr_pos);
> > } else {
> > trace_seq_printf(s, "\nError: (%d)\n", pe->lasterr);
> > + tracing_log_err("event filter parse error", filter->filter_string, err_text, FILT_ERR_ERRNO, 0);
>
> These lines are too long, could you please wrap?
Agreed.
> Otherwise, the whole series look good to me.
>
> Acked-by: Namhyung Kim <namhyung@kernel.org>
Thanks Namhyung!
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v4 05/11] tracing: Use tracing error_log with probe events
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (3 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 04/11] tracing: Use tracing error_log with trace event filters Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors Tom Zanussi
` (6 subsequent siblings)
11 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Masami Hiramatsu <mhiramat@kernel.org>
Use tracing error_log with probe events for logging error more
precisely. This also makes all parse error returns -EINVAL
(except for -ENOMEM), because user can see better error message
in error_log file now.
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
kernel/trace/trace_kprobe.c | 77 ++++++++-----
kernel/trace/trace_probe.c | 274 +++++++++++++++++++++++++++++++-------------
kernel/trace/trace_probe.h | 77 ++++++++++++-
kernel/trace/trace_uprobe.c | 44 ++++---
4 files changed, 348 insertions(+), 124 deletions(-)
diff --git a/kernel/trace/trace_kprobe.c b/kernel/trace/trace_kprobe.c
index 63aa0ab56051..6f49c01378ee 100644
--- a/kernel/trace/trace_kprobe.c
+++ b/kernel/trace/trace_kprobe.c
@@ -441,13 +441,8 @@ static int __register_trace_kprobe(struct trace_kprobe *tk)
else
ret = register_kprobe(&tk->rp.kp);
- if (ret == 0) {
+ if (ret == 0)
tk->tp.flags |= TP_FLAG_REGISTERED;
- } else if (ret == -EILSEQ) {
- pr_warn("Probing address(0x%p) is not an instruction boundary.\n",
- tk->rp.kp.addr);
- ret = -EINVAL;
- }
return ret;
}
@@ -591,7 +586,7 @@ static int trace_kprobe_create(int argc, const char *argv[])
* Type of args:
* FETCHARG:TYPE : use TYPE instead of unsigned long.
*/
- struct trace_kprobe *tk;
+ struct trace_kprobe *tk = NULL;
int i, len, ret = 0;
bool is_return = false;
char *symbol = NULL, *tmp = NULL;
@@ -615,44 +610,50 @@ static int trace_kprobe_create(int argc, const char *argv[])
if (argc < 2)
return -ECANCELED;
+ trace_probe_log_init("trace_kprobe", argc, argv);
+
event = strchr(&argv[0][1], ':');
if (event)
event++;
if (isdigit(argv[0][1])) {
if (!is_return) {
- pr_info("Maxactive is not for kprobe");
- return -EINVAL;
+ trace_probe_log_err(1, MAXACT_NO_KPROBE);
+ goto parse_error;
}
if (event)
len = event - &argv[0][1] - 1;
else
len = strlen(&argv[0][1]);
- if (len > MAX_EVENT_NAME_LEN - 1)
- return -E2BIG;
+ if (len > MAX_EVENT_NAME_LEN - 1) {
+ trace_probe_log_err(1, BAD_MAXACT);
+ goto parse_error;
+ }
memcpy(buf, &argv[0][1], len);
buf[len] = '\0';
ret = kstrtouint(buf, 0, &maxactive);
if (ret || !maxactive) {
- pr_info("Invalid maxactive number\n");
- return ret;
+ trace_probe_log_err(1, BAD_MAXACT);
+ goto parse_error;
}
/* kretprobes instances are iterated over via a list. The
* maximum should stay reasonable.
*/
if (maxactive > KRETPROBE_MAXACTIVE_MAX) {
- pr_info("Maxactive is too big (%d > %d).\n",
- maxactive, KRETPROBE_MAXACTIVE_MAX);
- return -E2BIG;
+ trace_probe_log_err(1, MAXACT_TOO_BIG);
+ goto parse_error;
}
}
/* try to parse an address. if that fails, try to read the
* input as a symbol. */
if (kstrtoul(argv[1], 0, (unsigned long *)&addr)) {
+ trace_probe_log_set_index(1);
/* Check whether uprobe event specified */
- if (strchr(argv[1], '/') && strchr(argv[1], ':'))
- return -ECANCELED;
+ if (strchr(argv[1], '/') && strchr(argv[1], ':')) {
+ ret = -ECANCELED;
+ goto error;
+ }
/* a symbol specified */
symbol = kstrdup(argv[1], GFP_KERNEL);
if (!symbol)
@@ -660,23 +661,23 @@ static int trace_kprobe_create(int argc, const char *argv[])
/* TODO: support .init module functions */
ret = traceprobe_split_symbol_offset(symbol, &offset);
if (ret || offset < 0 || offset > UINT_MAX) {
- pr_info("Failed to parse either an address or a symbol.\n");
- goto out;
+ trace_probe_log_err(0, BAD_PROBE_ADDR);
+ goto parse_error;
}
if (kprobe_on_func_entry(NULL, symbol, offset))
flags |= TPARG_FL_FENTRY;
if (offset && is_return && !(flags & TPARG_FL_FENTRY)) {
- pr_info("Given offset is not valid for return probe.\n");
- ret = -EINVAL;
- goto out;
+ trace_probe_log_err(0, BAD_RETPROBE);
+ goto parse_error;
}
}
- argc -= 2; argv += 2;
+ trace_probe_log_set_index(0);
if (event) {
- ret = traceprobe_parse_event_name(&event, &group, buf);
+ ret = traceprobe_parse_event_name(&event, &group, buf,
+ event - argv[0]);
if (ret)
- goto out;
+ goto parse_error;
} else {
/* Make a new event name */
if (symbol)
@@ -691,13 +692,14 @@ static int trace_kprobe_create(int argc, const char *argv[])
/* setup a probe */
tk = alloc_trace_kprobe(group, event, addr, symbol, offset, maxactive,
- argc, is_return);
+ argc - 2, is_return);
if (IS_ERR(tk)) {
ret = PTR_ERR(tk);
- /* This must return -ENOMEM otherwise there is a bug */
+ /* This must return -ENOMEM, else there is a bug */
WARN_ON_ONCE(ret != -ENOMEM);
- goto out;
+ goto out; /* We know tk is not allocated */
}
+ argc -= 2; argv += 2;
/* parse arguments */
for (i = 0; i < argc && i < MAX_TRACE_ARGS; i++) {
@@ -707,19 +709,32 @@ static int trace_kprobe_create(int argc, const char *argv[])
goto error;
}
+ trace_probe_log_set_index(i + 2);
ret = traceprobe_parse_probe_arg(&tk->tp, i, tmp, flags);
kfree(tmp);
if (ret)
- goto error;
+ goto error; /* This can be -ENOMEM */
}
ret = register_trace_kprobe(tk);
- if (ret)
+ if (ret) {
+ trace_probe_log_set_index(1);
+ if (ret == -EILSEQ)
+ trace_probe_log_err(0, BAD_INSN_BNDRY);
+ else if (ret == -ENOENT)
+ trace_probe_log_err(0, BAD_PROBE_ADDR);
+ else if (ret != -ENOMEM)
+ trace_probe_log_err(0, FAIL_REG_PROBE);
goto error;
+ }
+
out:
+ trace_probe_log_clear();
kfree(symbol);
return ret;
+parse_error:
+ ret = -EINVAL;
error:
free_trace_kprobe(tk);
goto out;
diff --git a/kernel/trace/trace_probe.c b/kernel/trace/trace_probe.c
index 8f8411e7835f..e11f98c49d72 100644
--- a/kernel/trace/trace_probe.c
+++ b/kernel/trace/trace_probe.c
@@ -13,6 +13,11 @@
#include "trace_probe.h"
+#undef C
+#define C(a, b) b
+
+static const char *trace_probe_err_text[] = { ERRORS };
+
static const char *reserved_field_names[] = {
"common_type",
"common_flags",
@@ -133,6 +138,60 @@ static const struct fetch_type *find_fetch_type(const char *type)
return NULL;
}
+static struct trace_probe_log trace_probe_log;
+
+void trace_probe_log_init(const char *subsystem, int argc, const char **argv)
+{
+ trace_probe_log.subsystem = subsystem;
+ trace_probe_log.argc = argc;
+ trace_probe_log.argv = argv;
+ trace_probe_log.index = 0;
+}
+
+void trace_probe_log_clear(void)
+{
+ memset(&trace_probe_log, 0, sizeof(trace_probe_log));
+}
+
+void trace_probe_log_set_index(int index)
+{
+ trace_probe_log.index = index;
+}
+
+void __trace_probe_log_err(int offset, int err_type)
+{
+ char *command, *p;
+ int i, len = 0, pos = 0;
+
+ if (!trace_probe_log.argv)
+ return;
+
+ /* Recalcurate the length and allocate buffer */
+ for (i = 0; i < trace_probe_log.argc; i++) {
+ if (i == trace_probe_log.index)
+ pos = len;
+ len += strlen(trace_probe_log.argv[i]) + 1;
+ }
+ command = kzalloc(len, GFP_KERNEL);
+ if (!command)
+ return;
+
+ /* And make a command string from argv array */
+ p = command;
+ for (i = 0; i < trace_probe_log.argc; i++) {
+ len = strlen(trace_probe_log.argv[i]);
+ strcpy(p, trace_probe_log.argv[i]);
+ p[len] = ' ';
+ p += len + 1;
+ }
+ *(p - 1) = '\0';
+
+ tracing_log_err(trace_probe_log.subsystem, command,
+ trace_probe_err_text, err_type, pos + offset);
+
+ kfree(command);
+}
+
/* Split symbol and offset. */
int traceprobe_split_symbol_offset(char *symbol, long *offset)
{
@@ -156,7 +215,7 @@ int traceprobe_split_symbol_offset(char *symbol, long *offset)
/* @buf must has MAX_EVENT_NAME_LEN size */
int traceprobe_parse_event_name(const char **pevent, const char **pgroup,
- char *buf)
+ char *buf, int offset)
{
const char *slash, *event = *pevent;
int len;
@@ -164,32 +223,33 @@ int traceprobe_parse_event_name(const char **pevent, const char **pgroup,
slash = strchr(event, '/');
if (slash) {
if (slash == event) {
- pr_info("Group name is not specified\n");
+ trace_probe_log_err(offset, NO_GROUP_NAME);
return -EINVAL;
}
if (slash - event + 1 > MAX_EVENT_NAME_LEN) {
- pr_info("Group name is too long\n");
- return -E2BIG;
+ trace_probe_log_err(offset, GROUP_TOO_LONG);
+ return -EINVAL;
}
strlcpy(buf, event, slash - event + 1);
if (!is_good_name(buf)) {
- pr_info("Group name must follow the same rules as C identifiers\n");
+ trace_probe_log_err(offset, BAD_GROUP_NAME);
return -EINVAL;
}
*pgroup = buf;
*pevent = slash + 1;
+ offset += slash - event + 1;
event = *pevent;
}
len = strlen(event);
if (len == 0) {
- pr_info("Event name is not specified\n");
+ trace_probe_log_err(offset, NO_EVENT_NAME);
return -EINVAL;
} else if (len > MAX_EVENT_NAME_LEN) {
- pr_info("Event name is too long\n");
- return -E2BIG;
+ trace_probe_log_err(offset, EVENT_TOO_LONG);
+ return -EINVAL;
}
if (!is_good_name(event)) {
- pr_info("Event name must follow the same rules as C identifiers\n");
+ trace_probe_log_err(offset, BAD_EVENT_NAME);
return -EINVAL;
}
return 0;
@@ -198,56 +258,67 @@ int traceprobe_parse_event_name(const char **pevent, const char **pgroup,
#define PARAM_MAX_STACK (THREAD_SIZE / sizeof(unsigned long))
static int parse_probe_vars(char *arg, const struct fetch_type *t,
- struct fetch_insn *code, unsigned int flags)
+ struct fetch_insn *code, unsigned int flags, int offs)
{
unsigned long param;
int ret = 0;
int len;
if (strcmp(arg, "retval") == 0) {
- if (flags & TPARG_FL_RETURN)
+ if (flags & TPARG_FL_RETURN) {
code->op = FETCH_OP_RETVAL;
- else
+ } else {
+ trace_probe_log_err(offs, RETVAL_ON_PROBE);
ret = -EINVAL;
+ }
} else if ((len = str_has_prefix(arg, "stack"))) {
if (arg[len] == '\0') {
code->op = FETCH_OP_STACKP;
} else if (isdigit(arg[len])) {
ret = kstrtoul(arg + len, 10, ¶m);
- if (ret || ((flags & TPARG_FL_KERNEL) &&
- param > PARAM_MAX_STACK))
+ if (ret) {
+ goto inval_var;
+ } else if ((flags & TPARG_FL_KERNEL) &&
+ param > PARAM_MAX_STACK) {
+ trace_probe_log_err(offs, BAD_STACK_NUM);
ret = -EINVAL;
- else {
+ } else {
code->op = FETCH_OP_STACK;
code->param = (unsigned int)param;
}
} else
- ret = -EINVAL;
+ goto inval_var;
} else if (strcmp(arg, "comm") == 0) {
code->op = FETCH_OP_COMM;
#ifdef CONFIG_HAVE_FUNCTION_ARG_ACCESS_API
} else if (((flags & TPARG_FL_MASK) ==
(TPARG_FL_KERNEL | TPARG_FL_FENTRY)) &&
(len = str_has_prefix(arg, "arg"))) {
- if (!isdigit(arg[len]))
- return -EINVAL;
ret = kstrtoul(arg + len, 10, ¶m);
- if (ret || !param || param > PARAM_MAX_STACK)
+ if (ret) {
+ goto inval_var;
+ } else if (!param || param > PARAM_MAX_STACK) {
+ trace_probe_log_err(offs, BAD_ARG_NUM);
return -EINVAL;
+ }
code->op = FETCH_OP_ARG;
code->param = (unsigned int)param - 1;
#endif
} else
- ret = -EINVAL;
+ goto inval_var;
return ret;
+
+inval_var:
+ trace_probe_log_err(offs, BAD_VAR);
+ return -EINVAL;
}
/* Recursive argument parser */
static int
parse_probe_arg(char *arg, const struct fetch_type *type,
struct fetch_insn **pcode, struct fetch_insn *end,
- unsigned int flags)
+ unsigned int flags, int offs)
{
struct fetch_insn *code = *pcode;
unsigned long param;
@@ -257,7 +328,7 @@ parse_probe_arg(char *arg, const struct fetch_type *type,
switch (arg[0]) {
case '$':
- ret = parse_probe_vars(arg + 1, type, code, flags);
+ ret = parse_probe_vars(arg + 1, type, code, flags, offs);
break;
case '%': /* named register */
@@ -266,47 +337,57 @@ parse_probe_arg(char *arg, const struct fetch_type *type,
code->op = FETCH_OP_REG;
code->param = (unsigned int)ret;
ret = 0;
- }
+ } else
+ trace_probe_log_err(offs, BAD_REG_NAME);
break;
case '@': /* memory, file-offset or symbol */
if (isdigit(arg[1])) {
ret = kstrtoul(arg + 1, 0, ¶m);
- if (ret)
+ if (ret) {
+ trace_probe_log_err(offs, BAD_MEM_ADDR);
break;
+ }
/* load address */
code->op = FETCH_OP_IMM;
code->immediate = param;
} else if (arg[1] == '+') {
/* kprobes don't support file offsets */
- if (flags & TPARG_FL_KERNEL)
+ if (flags & TPARG_FL_KERNEL) {
+ trace_probe_log_err(offs, FILE_ON_KPROBE);
return -EINVAL;
-
+ }
ret = kstrtol(arg + 2, 0, &offset);
- if (ret)
+ if (ret) {
+ trace_probe_log_err(offs, BAD_FILE_OFFS);
break;
+ }
code->op = FETCH_OP_FOFFS;
code->immediate = (unsigned long)offset; // imm64?
} else {
/* uprobes don't support symbols */
- if (!(flags & TPARG_FL_KERNEL))
+ if (!(flags & TPARG_FL_KERNEL)) {
+ trace_probe_log_err(offs, SYM_ON_UPROBE);
return -EINVAL;
-
+ }
/* Preserve symbol for updating */
code->op = FETCH_NOP_SYMBOL;
code->data = kstrdup(arg + 1, GFP_KERNEL);
if (!code->data)
return -ENOMEM;
- if (++code == end)
- return -E2BIG;
-
+ if (++code == end) {
+ trace_probe_log_err(offs, TOO_MANY_OPS);
+ return -EINVAL;
+ }
code->op = FETCH_OP_IMM;
code->immediate = 0;
}
/* These are fetching from memory */
- if (++code == end)
- return -E2BIG;
+ if (++code == end) {
+ trace_probe_log_err(offs, TOO_MANY_OPS);
+ return -EINVAL;
+ }
*pcode = code;
code->op = FETCH_OP_DEREF;
code->offset = offset;
@@ -317,28 +398,38 @@ parse_probe_arg(char *arg, const struct fetch_type *type,
/* fall through */
case '-':
tmp = strchr(arg, '(');
- if (!tmp)
+ if (!tmp) {
+ trace_probe_log_err(offs, DEREF_NEED_BRACE);
return -EINVAL;
-
+ }
*tmp = '\0';
ret = kstrtol(arg, 0, &offset);
- if (ret)
+ if (ret) {
+ trace_probe_log_err(offs, BAD_DEREF_OFFS);
break;
-
+ }
+ offs += (tmp + 1 - arg) + (arg[0] != '-' ? 1 : 0);
arg = tmp + 1;
tmp = strrchr(arg, ')');
-
- if (tmp) {
+ if (!tmp) {
+ trace_probe_log_err(offs + strlen(arg),
+ DEREF_OPEN_BRACE);
+ return -EINVAL;
+ } else {
const struct fetch_type *t2 = find_fetch_type(NULL);
*tmp = '\0';
- ret = parse_probe_arg(arg, t2, &code, end, flags);
+ ret = parse_probe_arg(arg, t2, &code, end, flags, offs);
if (ret)
break;
- if (code->op == FETCH_OP_COMM)
+ if (code->op == FETCH_OP_COMM) {
+ trace_probe_log_err(offs, COMM_CANT_DEREF);
+ return -EINVAL;
+ }
+ if (++code == end) {
+ trace_probe_log_err(offs, TOO_MANY_OPS);
return -EINVAL;
- if (++code == end)
- return -E2BIG;
+ }
*pcode = code;
code->op = FETCH_OP_DEREF;
@@ -348,6 +439,7 @@ parse_probe_arg(char *arg, const struct fetch_type *type,
}
if (!ret && code->op == FETCH_OP_NOP) {
/* Parsed, but do not find fetch method */
+ trace_probe_log_err(offs, BAD_FETCH_ARG);
ret = -EINVAL;
}
return ret;
@@ -379,7 +471,7 @@ static int __parse_bitfield_probe_arg(const char *bf,
return -EINVAL;
code++;
if (code->op != FETCH_OP_NOP)
- return -E2BIG;
+ return -EINVAL;
*pcode = code;
code->op = FETCH_OP_MOD_BF;
@@ -392,32 +484,53 @@ static int __parse_bitfield_probe_arg(const char *bf,
/* String length checking wrapper */
static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
- struct probe_arg *parg, unsigned int flags)
+ struct probe_arg *parg, unsigned int flags, int offset)
{
struct fetch_insn *code, *scode, *tmp = NULL;
- char *t, *t2;
+ char *t, *t2, *t3;
int ret, len;
- if (strlen(arg) > MAX_ARGSTR_LEN) {
- pr_info("Argument is too long.: %s\n", arg);
- return -ENOSPC;
+ len = strlen(arg);
+ if (len > MAX_ARGSTR_LEN) {
+ trace_probe_log_err(offset, ARG_TOO_LONG);
+ return -EINVAL;
+ } else if (len == 0) {
+ trace_probe_log_err(offset, NO_ARG_BODY);
+ return -EINVAL;
}
+
parg->comm = kstrdup(arg, GFP_KERNEL);
- if (!parg->comm) {
- pr_info("Failed to allocate memory for command '%s'.\n", arg);
+ if (!parg->comm)
return -ENOMEM;
- }
+
t = strchr(arg, ':');
if (t) {
*t = '\0';
t2 = strchr(++t, '[');
if (t2) {
- *t2 = '\0';
- parg->count = simple_strtoul(t2 + 1, &t2, 0);
- if (strcmp(t2, "]") || parg->count == 0)
+ *t2++ = '\0';
+ t3 = strchr(t2, ']');
+ if (!t3) {
+ offset += t2 + strlen(t2) - arg;
+ trace_probe_log_err(offset,
+ ARRAY_NO_CLOSE);
+ return -EINVAL;
+ } else if (t3[1] != '\0') {
+ trace_probe_log_err(offset + t3 + 1 - arg,
+ BAD_ARRAY_SUFFIX);
+ return -EINVAL;
+ }
+ *t3 = '\0';
+ if (kstrtouint(t2, 0, &parg->count) || !parg->count) {
+ trace_probe_log_err(offset + t2 - arg,
+ BAD_ARRAY_NUM);
return -EINVAL;
- if (parg->count > MAX_ARRAY_LEN)
- return -E2BIG;
+ }
+ if (parg->count > MAX_ARRAY_LEN) {
+ trace_probe_log_err(offset + t2 - arg,
+ ARRAY_TOO_BIG);
+ return -EINVAL;
+ }
}
}
/*
@@ -429,7 +542,7 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
else
parg->type = find_fetch_type(t);
if (!parg->type) {
- pr_info("Unsupported type: %s\n", t);
+ trace_probe_log_err(offset + (t ? (t - arg) : 0), BAD_TYPE);
return -EINVAL;
}
parg->offset = *size;
@@ -450,7 +563,7 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
code[FETCH_INSN_MAX - 1].op = FETCH_OP_END;
ret = parse_probe_arg(arg, parg->type, &code, &code[FETCH_INSN_MAX - 1],
- flags);
+ flags, offset);
if (ret)
goto fail;
@@ -458,7 +571,8 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
if (!strcmp(parg->type->name, "string")) {
if (code->op != FETCH_OP_DEREF && code->op != FETCH_OP_IMM &&
code->op != FETCH_OP_COMM) {
- pr_info("string only accepts memory or address.\n");
+ trace_probe_log_err(offset + (t ? (t - arg) : 0),
+ BAD_STRING);
ret = -EINVAL;
goto fail;
}
@@ -470,7 +584,8 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
*/
code++;
if (code->op != FETCH_OP_NOP) {
- ret = -E2BIG;
+ trace_probe_log_err(offset, TOO_MANY_OPS);
+ ret = -EINVAL;
goto fail;
}
}
@@ -483,7 +598,8 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
} else {
code++;
if (code->op != FETCH_OP_NOP) {
- ret = -E2BIG;
+ trace_probe_log_err(offset, TOO_MANY_OPS);
+ ret = -EINVAL;
goto fail;
}
code->op = FETCH_OP_ST_RAW;
@@ -493,20 +609,24 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,
/* Modify operation */
if (t != NULL) {
ret = __parse_bitfield_probe_arg(t, parg->type, &code);
- if (ret)
+ if (ret) {
+ trace_probe_log_err(offset + t - arg, BAD_BITFIELD);
goto fail;
+ }
}
/* Loop(Array) operation */
if (parg->count) {
if (scode->op != FETCH_OP_ST_MEM &&
scode->op != FETCH_OP_ST_STRING) {
- pr_info("array only accepts memory or address\n");
+ trace_probe_log_err(offset + (t ? (t - arg) : 0),
+ BAD_STRING);
ret = -EINVAL;
goto fail;
}
code++;
if (code->op != FETCH_OP_NOP) {
- ret = -E2BIG;
+ trace_probe_log_err(offset, TOO_MANY_OPS);
+ ret = -EINVAL;
goto fail;
}
code->op = FETCH_OP_LP_ARRAY;
@@ -555,15 +675,19 @@ int traceprobe_parse_probe_arg(struct trace_probe *tp, int i, char *arg,
{
struct probe_arg *parg = &tp->args[i];
char *body;
- int ret;
/* Increment count for freeing args in error case */
tp->nr_args++;
body = strchr(arg, '=');
if (body) {
- if (body - arg > MAX_ARG_NAME_LEN || body == arg)
+ if (body - arg > MAX_ARG_NAME_LEN) {
+ trace_probe_log_err(0, ARG_NAME_TOO_LONG);
+ return -EINVAL;
+ } else if (body == arg) {
+ trace_probe_log_err(0, NO_ARG_NAME);
return -EINVAL;
+ }
parg->name = kmemdup_nul(arg, body - arg, GFP_KERNEL);
body++;
} else {
@@ -575,22 +699,16 @@ int traceprobe_parse_probe_arg(struct trace_probe *tp, int i, char *arg,
return -ENOMEM;
if (!is_good_name(parg->name)) {
- pr_info("Invalid argument[%d] name: %s\n",
- i, parg->name);
+ trace_probe_log_err(0, BAD_ARG_NAME);
return -EINVAL;
}
-
if (traceprobe_conflict_field_name(parg->name, tp->args, i)) {
- pr_info("Argument[%d]: '%s' conflicts with another field.\n",
- i, parg->name);
+ trace_probe_log_err(0, USED_ARG_NAME);
return -EINVAL;
}
-
/* Parse fetch argument */
- ret = traceprobe_parse_probe_arg_body(body, &tp->size, parg, flags);
- if (ret)
- pr_info("Parse error at argument[%d]. (%d)\n", i, ret);
- return ret;
+ return traceprobe_parse_probe_arg_body(body, &tp->size, parg, flags,
+ body - arg);
}
void traceprobe_free_probe_arg(struct probe_arg *arg)
diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
index 2177c206de15..b7737666c1a8 100644
--- a/kernel/trace/trace_probe.h
+++ b/kernel/trace/trace_probe.h
@@ -280,8 +280,8 @@ extern int traceprobe_update_arg(struct probe_arg *arg);
extern void traceprobe_free_probe_arg(struct probe_arg *arg);
extern int traceprobe_split_symbol_offset(char *symbol, long *offset);
-extern int traceprobe_parse_event_name(const char **pevent,
- const char **pgroup, char *buf);
+int traceprobe_parse_event_name(const char **pevent, const char **pgroup,
+ char *buf, int offset);
extern int traceprobe_set_print_fmt(struct trace_probe *tp, bool is_return);
@@ -298,3 +298,76 @@ extern void destroy_local_trace_uprobe(struct trace_event_call *event_call);
#endif
extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
size_t offset, struct trace_probe *tp);
+
+#undef ERRORS
+#define ERRORS \
+ C(FILE_NOT_FOUND, "Failed to find the given file"), \
+ C(NO_REGULAR_FILE, "Not a regular file"), \
+ C(BAD_REFCNT, "Invalid reference counter offset"), \
+ C(REFCNT_OPEN_BRACE, "Reference counter brace is not closed"), \
+ C(BAD_REFCNT_SUFFIX, "Reference counter has wrong suffix"), \
+ C(BAD_UPROBE_OFFS, "Invalid uprobe offset"), \
+ C(MAXACT_NO_KPROBE, "Maxactive is not for kprobe"), \
+ C(BAD_MAXACT, "Invalid maxactive number"), \
+ C(MAXACT_TOO_BIG, "Maxactive is too big"), \
+ C(BAD_PROBE_ADDR, "Invalid probed address or symbol"), \
+ C(BAD_RETPROBE, "Retprobe address must be an function entry"), \
+ C(NO_GROUP_NAME, "Group name is not specified"), \
+ C(GROUP_TOO_LONG, "Group name is too long"), \
+ C(BAD_GROUP_NAME, "Group name must follow the same rules as C identifiers"), \
+ C(NO_EVENT_NAME, "Event name is not specified"), \
+ C(EVENT_TOO_LONG, "Event name is too long"), \
+ C(BAD_EVENT_NAME, "Event name must follow the same rules as C identifiers"), \
+ C(RETVAL_ON_PROBE, "$retval is not available on probe"), \
+ C(BAD_STACK_NUM, "Invalid stack number"), \
+ C(BAD_ARG_NUM, "Invalid argument number"), \
+ C(BAD_VAR, "Invalid $-valiable specified"), \
+ C(BAD_REG_NAME, "Invalid register name"), \
+ C(BAD_MEM_ADDR, "Invalid memory address"), \
+ C(FILE_ON_KPROBE, "File offset is not available with kprobe"), \
+ C(BAD_FILE_OFFS, "Invalid file offset value"), \
+ C(SYM_ON_UPROBE, "Symbol is not available with uprobe"), \
+ C(TOO_MANY_OPS, "Dereference is too much nested"), \
+ C(DEREF_NEED_BRACE, "Dereference needs a brace"), \
+ C(BAD_DEREF_OFFS, "Invalid dereference offset"), \
+ C(DEREF_OPEN_BRACE, "Dereference brace is not closed"), \
+ C(COMM_CANT_DEREF, "$comm can not be dereferenced"), \
+ C(BAD_FETCH_ARG, "Invalid fetch argument"), \
+ C(ARRAY_NO_CLOSE, "Array is not closed"), \
+ C(BAD_ARRAY_SUFFIX, "Array has wrong suffix"), \
+ C(BAD_ARRAY_NUM, "Invalid array size"), \
+ C(ARRAY_TOO_BIG, "Array number is too big"), \
+ C(BAD_TYPE, "Unknown type is specified"), \
+ C(BAD_STRING, "String accepts only memory argument"), \
+ C(BAD_BITFIELD, "Invalid bitfield"), \
+ C(ARG_NAME_TOO_LONG, "Argument name is too long"), \
+ C(NO_ARG_NAME, "Argument name is not specified"), \
+ C(BAD_ARG_NAME, "Argument name must follow the same rules as C identifiers"), \
+ C(USED_ARG_NAME, "This argument name is already used"), \
+ C(ARG_TOO_LONG, "Argument expression is too long"), \
+ C(NO_ARG_BODY, "No argument expression"), \
+ C(BAD_INSN_BNDRY, "Probe point is not an instruction boundary"),\
+ C(FAIL_REG_PROBE, "Failed to register probe event"),
+
+#undef C
+#define C(a, b) TP_ERR_##a
+
+/* Define TP_ERR_ */
+enum { ERRORS };
+
+/* Error text is defined in trace_probe.c */
+
+struct trace_probe_log {
+ const char *subsystem;
+ const char **argv;
+ int argc;
+ int index;
+};
+
+void trace_probe_log_init(const char *subsystem, int argc, const char **argv);
+void trace_probe_log_set_index(int index);
+void trace_probe_log_clear(void);
+void __trace_probe_log_err(int offset, int err);
+
+#define trace_probe_log_err(offs, err) \
+ __trace_probe_log_err(offs, TP_ERR_##err)
diff --git a/kernel/trace/trace_uprobe.c b/kernel/trace/trace_uprobe.c
index b54137ec7810..9fb1f8a5c154 100644
--- a/kernel/trace/trace_uprobe.c
+++ b/kernel/trace/trace_uprobe.c
@@ -450,13 +450,19 @@ static int trace_uprobe_create(int argc, const char **argv)
return -ECANCELED;
}
+ trace_probe_log_init("trace_uprobe", argc, argv);
+ trace_probe_log_set_index(1); /* filename is the 2nd argument */
+
*arg++ = '\0';
ret = kern_path(filename, LOOKUP_FOLLOW, &path);
if (ret) {
+ trace_probe_log_err(0, FILE_NOT_FOUND);
kfree(filename);
+ trace_probe_log_clear();
return ret;
}
if (!d_is_reg(path.dentry)) {
+ trace_probe_log_err(0, NO_REGULAR_FILE);
ret = -EINVAL;
goto fail_address_parse;
}
@@ -465,9 +471,16 @@ static int trace_uprobe_create(int argc, const char **argv)
rctr = strchr(arg, '(');
if (rctr) {
rctr_end = strchr(rctr, ')');
- if (rctr > rctr_end || *(rctr_end + 1) != 0) {
+ if (!rctr_end) {
+ ret = -EINVAL;
+ rctr_end = rctr + strlen(rctr);
+ trace_probe_log_err(rctr_end - filename,
+ REFCNT_OPEN_BRACE);
+ goto fail_address_parse;
+ } else if (rctr_end[1] != '\0') {
ret = -EINVAL;
- pr_info("Invalid reference counter offset.\n");
+ trace_probe_log_err(rctr_end + 1 - filename,
+ BAD_REFCNT_SUFFIX);
goto fail_address_parse;
}
@@ -475,22 +488,23 @@ static int trace_uprobe_create(int argc, const char **argv)
*rctr_end = '\0';
ret = kstrtoul(rctr, 0, &ref_ctr_offset);
if (ret) {
- pr_info("Invalid reference counter offset.\n");
+ trace_probe_log_err(rctr - filename, BAD_REFCNT);
goto fail_address_parse;
}
}
/* Parse uprobe offset. */
ret = kstrtoul(arg, 0, &offset);
- if (ret)
+ if (ret) {
+ trace_probe_log_err(arg - filename, BAD_UPROBE_OFFS);
goto fail_address_parse;
-
- argc -= 2;
- argv += 2;
+ }
/* setup a probe */
+ trace_probe_log_set_index(0);
if (event) {
- ret = traceprobe_parse_event_name(&event, &group, buf);
+ ret = traceprobe_parse_event_name(&event, &group, buf,
+ event - argv[0]);
if (ret)
goto fail_address_parse;
} else {
@@ -512,6 +526,9 @@ static int trace_uprobe_create(int argc, const char **argv)
kfree(tail);
}
+ argc -= 2;
+ argv += 2;
+
tu = alloc_trace_uprobe(group, event, argc, is_return);
if (IS_ERR(tu)) {
ret = PTR_ERR(tu);
@@ -532,6 +549,7 @@ static int trace_uprobe_create(int argc, const char **argv)
goto error;
}
+ trace_probe_log_set_index(i + 2);
ret = traceprobe_parse_probe_arg(&tu->tp, i, tmp,
is_return ? TPARG_FL_RETURN : 0);
kfree(tmp);
@@ -540,20 +558,20 @@ static int trace_uprobe_create(int argc, const char **argv)
}
ret = register_trace_uprobe(tu);
- if (ret)
- goto error;
- return 0;
+ if (!ret)
+ goto out;
error:
free_trace_uprobe(tu);
+out:
+ trace_probe_log_clear();
return ret;
fail_address_parse:
+ trace_probe_log_clear();
path_put(&path);
kfree(filename);
- pr_info("Failed to parse address or file.\n");
-
return ret;
}
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (4 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 05/11] tracing: Use tracing error_log with probe events Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-23 10:22 ` Masami Hiramatsu
2019-03-22 15:34 ` [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase Tom Zanussi
` (5 subsequent siblings)
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Masami Hiramatsu <mhiramat@kernel.org>
Add error_log testcase for error logs on probe events.
This tests most of error cases and checks the error position
is correct.
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
.../ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 93 ++++++++++++++++++++++
.../ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 31 ++++++++
2 files changed, 124 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
new file mode 100644
index 000000000000..281665b1348c
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
@@ -0,0 +1,93 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: Kprobe event parser error log check
+
+[ -f kprobe_events ] || exit_unsupported # this is configurable
+
+[ -f error_log ] || exit_unsupported
+
+check_error() { # command-with-error-pos-by-^
+pos=$(echo -n "${1%^*}" | wc -c) # error position
+command=$(echo "$1" | tr -d ^)
+echo "Test command: $command"
+echo > error_log
+(! echo "$command" > kprobe_events ) >& /dev/null
+grep "trace_kprobe: error:" -A 3 error_log
+N=$(tail -n 1 error_log | wc -c)
+# " Command: " and "^\n" => 13
+test $(expr 13 + $pos) -eq $N
+}
+
+if grep -q 'r\[maxactive\]' README; then
+check_error 'p^100 vfs_read' # MAXACT_NO_KPROBE
+check_error 'r^1a111 vfs_read' # BAD_MAXACT
+check_error 'r^100000 vfs_read' # MAXACT_TOO_BIG
+fi
+
+check_error 'p ^non_exist_func' # BAD_PROBE_ADDR (enoent)
+check_error 'p ^hoge-fuga' # BAD_PROBE_ADDR (bad syntax)
+check_error 'p ^hoge+1000-1000' # BAD_PROBE_ADDR (bad syntax)
+check_error 'r ^vfs_read+10' # BAD_RETPROBE
+check_error 'p:^/bar vfs_read' # NO_GROUP_NAME
+check_error 'p:^12345678901234567890123456789012345678901234567890123456789012345/bar vfs_read' # GROUP_TOO_LONG
+
+check_error 'p:^foo.1/bar vfs_read' # BAD_GROUP_NAME
+check_error 'p:foo/^ vfs_read' # NO_EVENT_NAME
+check_error 'p:foo/^12345678901234567890123456789012345678901234567890123456789012345 vfs_read' # EVENT_TOO_LONG
+check_error 'p:foo/^bar.1 vfs_read' # BAD_EVENT_NAME
+
+check_error 'p vfs_read ^$retval' # RETVAL_ON_PROBE
+check_error 'p vfs_read ^$stack10000' # BAD_STACK_NUM
+
+if grep -q '$arg<N>' README; then
+check_error 'p vfs_read ^$arg10000' # BAD_ARG_NUM
+fi
+
+check_error 'p vfs_read ^$none_var' # BAD_VAR
+
+check_error 'p vfs_read ^%none_reg' # BAD_REG_NAME
+check_error 'p vfs_read ^@12345678abcde' # BAD_MEM_ADDR
+check_error 'p vfs_read ^@+10' # FILE_ON_KPROBE
+
+check_error 'p vfs_read ^+0@0)' # DEREF_NEED_BRACE
+check_error 'p vfs_read ^+0ab1(@0)' # BAD_DEREF_OFFS
+check_error 'p vfs_read +0(+0(@0^)' # DEREF_OPEN_BRACE
+
+if grep -A1 "fetcharg:" README | grep -q '\$comm' ; then
+check_error 'p vfs_read +0(^$comm)' # COMM_CANT_DEREF
+fi
+
+check_error 'p vfs_read ^&1' # BAD_FETCH_ARG
+
+
+# We've introduced this limitation with array support
+if grep -q ' <type>\\\[<array-size>\\\]' README; then
+check_error 'p vfs_read +0(^+0(+0(+0(+0(+0(+0(+0(+0(+0(+0(+0(+0(+0(@0))))))))))))))' # TOO_MANY_OPS?
+check_error 'p vfs_read +0(@11):u8[10^' # ARRAY_NO_CLOSE
+check_error 'p vfs_read +0(@11):u8[10]^a' # BAD_ARRAY_SUFFIX
+check_error 'p vfs_read +0(@11):u8[^10a]' # BAD_ARRAY_NUM
+check_error 'p vfs_read +0(@11):u8[^256]' # ARRAY_TOO_BIG
+fi
+
+check_error 'p vfs_read @11:^unknown_type' # BAD_TYPE
+check_error 'p vfs_read $stack0:^string' # BAD_STRING
+check_error 'p vfs_read @11:^b10@a/16' # BAD_BITFIELD
+
+check_error 'p vfs_read ^arg123456789012345678901234567890=@11' # ARG_NAME_TOO_LOG
+check_error 'p vfs_read ^=@11' # NO_ARG_NAME
+check_error 'p vfs_read ^var.1=@11' # BAD_ARG_NAME
+check_error 'p vfs_read var1=@11 ^var1=@12' # USED_ARG_NAME
+check_error 'p vfs_read ^+1234567(+1234567(+1234567(+1234567(+1234567(+1234567(@1234))))))' # ARG_TOO_LONG
+check_error 'p vfs_read arg1=^' # NO_ARG_BODY
+
+# instruction boundary check is valid on x86 (at this moment)
+case $(uname -m) in
+ x86_64|i[3456]86)
+ echo 'p vfs_read' > kprobe_events
+ if grep -q FTRACE ../kprobes/list ; then
+ check_error 'p ^vfs_read+3' # BAD_INSN_BNDRY (only if function-tracer is enabled)
+ fi
+ ;;
+esac
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
new file mode 100644
index 000000000000..957011300bb7
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
@@ -0,0 +1,31 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: Uprobe event parser error log check
+
+[ -f uprobe_events ] || exit_unsupported # this is configurable
+
+[ -f error_log ] || exit_unsupported
+
+check_error() { # command-with-error-pos-by-^
+pos=$(echo -n "${1%^*}" | wc -c) # error position
+command=$(echo "$1" | tr -d ^)
+echo "Test command: $command"
+echo > error_log
+(! echo "$command" > uprobe_events ) >& /dev/null
+grep "trace_uprobe: error:" -A 3 error_log
+N=$(tail -n 1 error_log | wc -c)
+# " Command: " and "^\n" => 13
+test $(expr 13 + $pos) -eq $N
+}
+
+check_error 'p ^/non_exist_file:100' # FILE_NOT_FOUND
+check_error 'p ^/sys:100' # NO_REGULAR_FILE
+check_error 'p /bin/sh:^10a' # BAD_UPROBE_OFFS
+check_error 'p /bin/sh:10(^1a)' # BAD_REFCNT
+check_error 'p /bin/sh:10(10^' # REFCNT_OPEN_BRACE
+check_error 'p /bin/sh:10(10)^a' # BAD_REFCNT_SUFFIX
+
+check_error 'p /bin/sh:10 ^@+ab' # BAD_FILE_OFFS
+check_error 'p /bin/sh:10 ^@symbol' # SYM_ON_UPROBE
+
+exit 0
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors
2019-03-22 15:34 ` [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors Tom Zanussi
@ 2019-03-23 10:22 ` Masami Hiramatsu
2019-03-23 13:11 ` Tom Zanussi
0 siblings, 1 reply; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-23 10:22 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
On Fri, 22 Mar 2019 10:34:32 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> From: Masami Hiramatsu <mhiramat@kernel.org>
>
> Add error_log testcase for error logs on probe events.
> This tests most of error cases and checks the error position
> is correct.
>
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
> .../ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 93 ++++++++++++++++++++++
> .../ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 31 ++++++++
> 2 files changed, 124 insertions(+)
> create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
>
> diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> new file mode 100644
> index 000000000000..281665b1348c
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> @@ -0,0 +1,93 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: Kprobe event parser error log check
> +
> +[ -f kprobe_events ] || exit_unsupported # this is configurable
> +
> +[ -f error_log ] || exit_unsupported
> +
> +check_error() { # command-with-error-pos-by-^
> +pos=$(echo -n "${1%^*}" | wc -c) # error position
> +command=$(echo "$1" | tr -d ^)
> +echo "Test command: $command"
> +echo > error_log
> +(! echo "$command" > kprobe_events ) >& /dev/null
Oops, this one. This must be
(! echo "$command" > kprobe_events ) > /dev/null 2>&1
[...]
> diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
> new file mode 100644
> index 000000000000..957011300bb7
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
> @@ -0,0 +1,31 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: Uprobe event parser error log check
> +
> +[ -f uprobe_events ] || exit_unsupported # this is configurable
> +
> +[ -f error_log ] || exit_unsupported
> +
> +check_error() { # command-with-error-pos-by-^
> +pos=$(echo -n "${1%^*}" | wc -c) # error position
> +command=$(echo "$1" | tr -d ^)
> +echo "Test command: $command"
> +echo > error_log
> +(! echo "$command" > uprobe_events ) >& /dev/null
Here too.
Tom, if you don't mind, could you update it when you update
the series? Or should I resend it?
Thank you,
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors
2019-03-23 10:22 ` Masami Hiramatsu
@ 2019-03-23 13:11 ` Tom Zanussi
2019-03-24 10:11 ` Masami Hiramatsu
0 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-23 13:11 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: rostedt, tglx, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
Hi Masami,
On Sat, 2019-03-23 at 19:22 +0900, Masami Hiramatsu wrote:
> On Fri, 22 Mar 2019 10:34:32 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
>
> > From: Masami Hiramatsu <mhiramat@kernel.org>
> >
> > Add error_log testcase for error logs on probe events.
> > This tests most of error cases and checks the error position
> > is correct.
> >
> > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > ---
> > .../ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 93
> > ++++++++++++++++++++++
> > .../ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 31 ++++++++
> > 2 files changed, 124 insertions(+)
> > create mode 100644
> > tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.t
> > c
> > create mode 100644
> > tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.t
> > c
> >
> > diff --git
> > a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > new file mode 100644
> > index 000000000000..281665b1348c
> > --- /dev/null
> > +++
> > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > @@ -0,0 +1,93 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: Kprobe event parser error log check
> > +
> > +[ -f kprobe_events ] || exit_unsupported # this is configurable
> > +
> > +[ -f error_log ] || exit_unsupported
> > +
> > +check_error() { # command-with-error-pos-by-^
> > +pos=$(echo -n "${1%^*}" | wc -c) # error position
> > +command=$(echo "$1" | tr -d ^)
> > +echo "Test command: $command"
> > +echo > error_log
> > +(! echo "$command" > kprobe_events ) >& /dev/null
>
> Oops, this one. This must be
>
> (! echo "$command" > kprobe_events ) > /dev/null 2>&1
>
> [...]
> > diff --git
> > a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > new file mode 100644
> > index 000000000000..957011300bb7
> > --- /dev/null
> > +++
> > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > @@ -0,0 +1,31 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: Uprobe event parser error log check
> > +
> > +[ -f uprobe_events ] || exit_unsupported # this is configurable
> > +
> > +[ -f error_log ] || exit_unsupported
> > +
> > +check_error() { # command-with-error-pos-by-^
> > +pos=$(echo -n "${1%^*}" | wc -c) # error position
> > +command=$(echo "$1" | tr -d ^)
> > +echo "Test command: $command"
> > +echo > error_log
> > +(! echo "$command" > uprobe_events ) >& /dev/null
>
> Here too.
>
> Tom, if you don't mind, could you update it when you update
> the series? Or should I resend it?
>
I can just change it in the next update. I assume 2> as in the other
patch?
Tom
> Thank you,
>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors
2019-03-23 13:11 ` Tom Zanussi
@ 2019-03-24 10:11 ` Masami Hiramatsu
0 siblings, 0 replies; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-24 10:11 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
On Sat, 23 Mar 2019 08:11:09 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> Hi Masami,
>
> On Sat, 2019-03-23 at 19:22 +0900, Masami Hiramatsu wrote:
> > On Fri, 22 Mar 2019 10:34:32 -0500
> > Tom Zanussi <zanussi@kernel.org> wrote:
> >
> > > From: Masami Hiramatsu <mhiramat@kernel.org>
> > >
> > > Add error_log testcase for error logs on probe events.
> > > This tests most of error cases and checks the error position
> > > is correct.
> > >
> > > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > > ---
> > > .../ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 93
> > > ++++++++++++++++++++++
> > > .../ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 31 ++++++++
> > > 2 files changed, 124 insertions(+)
> > > create mode 100644
> > > tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.t
> > > c
> > > create mode 100644
> > > tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.t
> > > c
> > >
> > > diff --git
> > > a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > > .tc
> > > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > > .tc
> > > new file mode 100644
> > > index 000000000000..281665b1348c
> > > --- /dev/null
> > > +++
> > > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > > .tc
> > > @@ -0,0 +1,93 @@
> > > +#!/bin/sh
> > > +# SPDX-License-Identifier: GPL-2.0
> > > +# description: Kprobe event parser error log check
> > > +
> > > +[ -f kprobe_events ] || exit_unsupported # this is configurable
> > > +
> > > +[ -f error_log ] || exit_unsupported
> > > +
> > > +check_error() { # command-with-error-pos-by-^
> > > +pos=$(echo -n "${1%^*}" | wc -c) # error position
> > > +command=$(echo "$1" | tr -d ^)
> > > +echo "Test command: $command"
> > > +echo > error_log
> > > +(! echo "$command" > kprobe_events ) >& /dev/null
> >
> > Oops, this one. This must be
> >
> > (! echo "$command" > kprobe_events ) > /dev/null 2>&1
> >
> > [...]
> > > diff --git
> > > a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > > .tc
> > > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > > .tc
> > > new file mode 100644
> > > index 000000000000..957011300bb7
> > > --- /dev/null
> > > +++
> > > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > > .tc
> > > @@ -0,0 +1,31 @@
> > > +#!/bin/sh
> > > +# SPDX-License-Identifier: GPL-2.0
> > > +# description: Uprobe event parser error log check
> > > +
> > > +[ -f uprobe_events ] || exit_unsupported # this is configurable
> > > +
> > > +[ -f error_log ] || exit_unsupported
> > > +
> > > +check_error() { # command-with-error-pos-by-^
> > > +pos=$(echo -n "${1%^*}" | wc -c) # error position
> > > +command=$(echo "$1" | tr -d ^)
> > > +echo "Test command: $command"
> > > +echo > error_log
> > > +(! echo "$command" > uprobe_events ) >& /dev/null
> >
> > Here too.
> >
> > Tom, if you don't mind, could you update it when you update
> > the series? Or should I resend it?
> >
>
> I can just change it in the next update. I assume 2> as in the other
> patch?
Yes, that is better, since stdout goes to [ku]probe_event file.
Thank you!
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (5 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 06/11] selftests/ftrace: Add error_log testcase for probe errors Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-23 10:13 ` Masami Hiramatsu
2019-03-22 15:34 ` [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase Tom Zanussi
` (4 subsequent siblings)
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Error handling has been moved to the common tracing/error_log, so this
test is no longer valid.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
.../inter-event/trigger-extended-error-support.tc | 28 ----------------------
1 file changed, 28 deletions(-)
delete mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
deleted file mode 100644
index 9912616a8672..000000000000
--- a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
+++ /dev/null
@@ -1,28 +0,0 @@
-#!/bin/sh
-# SPDX-License-Identifier: GPL-2.0
-# description: event trigger - test extended error support
-
-
-fail() { #msg
- echo $1
- exit_fail
-}
-
-if [ ! -f set_event ]; then
- echo "event tracing is not supported"
- exit_unsupported
-fi
-
-if [ ! -f synthetic_events ]; then
- echo "synthetic event is not supported"
- exit_unsupported
-fi
-
-echo "Test extended error support"
-echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
-! echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger 2> /dev/null
-if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then
- fail "Failed to generate extended error in histogram"
-fi
-
-exit 0
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase
2019-03-22 15:34 ` [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase Tom Zanussi
@ 2019-03-23 10:13 ` Masami Hiramatsu
2019-03-23 13:08 ` Tom Zanussi
0 siblings, 1 reply; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-23 10:13 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
Hi Tom,
This should be tagged with "selftests/ftrace:". :)
Thank you,
On Fri, 22 Mar 2019 10:34:33 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> From: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> Error handling has been moved to the common tracing/error_log, so this
> test is no longer valid.
>
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
> .../inter-event/trigger-extended-error-support.tc | 28 ----------------------
> 1 file changed, 28 deletions(-)
> delete mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
>
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
> deleted file mode 100644
> index 9912616a8672..000000000000
> --- a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
> +++ /dev/null
> @@ -1,28 +0,0 @@
> -#!/bin/sh
> -# SPDX-License-Identifier: GPL-2.0
> -# description: event trigger - test extended error support
> -
> -
> -fail() { #msg
> - echo $1
> - exit_fail
> -}
> -
> -if [ ! -f set_event ]; then
> - echo "event tracing is not supported"
> - exit_unsupported
> -fi
> -
> -if [ ! -f synthetic_events ]; then
> - echo "synthetic event is not supported"
> - exit_unsupported
> -fi
> -
> -echo "Test extended error support"
> -echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
> -! echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger 2> /dev/null
> -if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then
> - fail "Failed to generate extended error in histogram"
> -fi
> -
> -exit 0
> --
> 2.14.1
>
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase
2019-03-23 10:13 ` Masami Hiramatsu
@ 2019-03-23 13:08 ` Tom Zanussi
0 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-23 13:08 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: rostedt, tglx, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
Hi Masami,
On Sat, 2019-03-23 at 19:13 +0900, Masami Hiramatsu wrote:
> Hi Tom,
>
> This should be tagged with "selftests/ftrace:". :)
>
Yeah, will change that in the next update.
Thanks,
Tom
> Thank you,
>
> On Fri, 22 Mar 2019 10:34:33 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
>
> > From: Tom Zanussi <tom.zanussi@linux.intel.com>
> >
> > Error handling has been moved to the common tracing/error_log, so
> > this
> > test is no longer valid.
> >
> > Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> > ---
> > .../inter-event/trigger-extended-error-support.tc | 28 ----------
> > ------------
> > 1 file changed, 28 deletions(-)
> > delete mode 100644
> > tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-
> > extended-error-support.tc
> >
> > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-
> > event/trigger-extended-error-support.tc
> > b/tools/testing/selftests/ftrace/test.d/trigger/inter-
> > event/trigger-extended-error-support.tc
> > deleted file mode 100644
> > index 9912616a8672..000000000000
> > --- a/tools/testing/selftests/ftrace/test.d/trigger/inter-
> > event/trigger-extended-error-support.tc
> > +++ /dev/null
> > @@ -1,28 +0,0 @@
> > -#!/bin/sh
> > -# SPDX-License-Identifier: GPL-2.0
> > -# description: event trigger - test extended error support
> > -
> > -
> > -fail() { #msg
> > - echo $1
> > - exit_fail
> > -}
> > -
> > -if [ ! -f set_event ]; then
> > - echo "event tracing is not supported"
> > - exit_unsupported
> > -fi
> > -
> > -if [ ! -f synthetic_events ]; then
> > - echo "synthetic event is not supported"
> > - exit_unsupported
> > -fi
> > -
> > -echo "Test extended error support"
> > -echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' >
> > events/sched/sched_wakeup/trigger
> > -! echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"'
> > >> events/sched/sched_wakeup/trigger 2> /dev/null
> > -if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then
> > - fail "Failed to generate extended error in histogram"
> > -fi
> > -
> > -exit 0
> > --
> > 2.14.1
> >
>
>
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (6 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 07/11] tracing: Remove trigger-extended-error-support testcase Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-23 12:08 ` Masami Hiramatsu
2019-03-22 15:34 ` [PATCH v4 09/11] tracing: Add tracing/error_log Documentation Tom Zanussi
` (3 subsequent siblings)
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Add a testcase verifying basic tracing/error_log functionality.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
.../ftrace/test.d/ftrace/tracing-error-log.tc | 23 ++++++++++++++++++++++
1 file changed, 23 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
new file mode 100644
index 000000000000..601ffebfbb9f
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
@@ -0,0 +1,23 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: ftrace - test tracing error log support
+
+fail() { #msg
+ echo $1
+ exit_fail
+}
+
+# event tracing is currently the only ftrace tracer that uses the
+# tracing error_log, hence this check
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+echo "Test tracing error log support"
+! echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > events/signal/signal_generate/filter 2> /dev/null
+if ! grep "error:" error_log; then
+ fail "Failed to generate tracing error log error"
+fi
+
+exit 0
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase
2019-03-22 15:34 ` [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase Tom Zanussi
@ 2019-03-23 12:08 ` Masami Hiramatsu
2019-03-23 13:17 ` Tom Zanussi
0 siblings, 1 reply; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-23 12:08 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
On Fri, 22 Mar 2019 10:34:34 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> From: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> Add a testcase verifying basic tracing/error_log functionality.
Would you be OK that you don't test all error cases with
error position?
Thank you,
>
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
> .../ftrace/test.d/ftrace/tracing-error-log.tc | 23 ++++++++++++++++++++++
> 1 file changed, 23 insertions(+)
> create mode 100644 tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
>
> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
> new file mode 100644
> index 000000000000..601ffebfbb9f
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
> @@ -0,0 +1,23 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: ftrace - test tracing error log support
> +
> +fail() { #msg
> + echo $1
> + exit_fail
> +}
> +
> +# event tracing is currently the only ftrace tracer that uses the
> +# tracing error_log, hence this check
> +if [ ! -f set_event ]; then
> + echo "event tracing is not supported"
> + exit_unsupported
> +fi
> +
> +echo "Test tracing error log support"
> +! echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > events/signal/signal_generate/filter 2> /dev/null
> +if ! grep "error:" error_log; then
> + fail "Failed to generate tracing error log error"
> +fi
> +
> +exit 0
> --
> 2.14.1
>
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase
2019-03-23 12:08 ` Masami Hiramatsu
@ 2019-03-23 13:17 ` Tom Zanussi
0 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-23 13:17 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: rostedt, tglx, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
Hi Masami,
On Sat, 2019-03-23 at 21:08 +0900, Masami Hiramatsu wrote:
> On Fri, 22 Mar 2019 10:34:34 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
>
> > From: Tom Zanussi <tom.zanussi@linux.intel.com>
> >
> > Add a testcase verifying basic tracing/error_log functionality.
>
> Would you be OK that you don't test all error cases with
> error position?
>
Good point - I'll add checks for error position in my testcases too.
Thanks,
Tom
> Thank you,
>
> >
> > Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> > ---
> > .../ftrace/test.d/ftrace/tracing-error-log.tc | 23
> > ++++++++++++++++++++++
> > 1 file changed, 23 insertions(+)
> > create mode 100644
> > tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
> >
> > diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/tracing-
> > error-log.tc
> > b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
> > new file mode 100644
> > index 000000000000..601ffebfbb9f
> > --- /dev/null
> > +++ b/tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-
> > log.tc
> > @@ -0,0 +1,23 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: ftrace - test tracing error log support
> > +
> > +fail() { #msg
> > + echo $1
> > + exit_fail
> > +}
> > +
> > +# event tracing is currently the only ftrace tracer that uses the
> > +# tracing error_log, hence this check
> > +if [ ! -f set_event ]; then
> > + echo "event tracing is not supported"
> > + exit_unsupported
> > +fi
> > +
> > +echo "Test tracing error log support"
> > +! echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" >
> > events/signal/signal_generate/filter 2> /dev/null
> > +if ! grep "error:" error_log; then
> > + fail "Failed to generate tracing error log error"
> > +fi
> > +
> > +exit 0
> > --
> > 2.14.1
> >
>
>
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v4 09/11] tracing: Add tracing/error_log Documentation
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (7 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 08/11] selftests/ftrace: Add tracing/error_log testcase Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 10/11] tracing: Add error_log to README Tom Zanussi
` (2 subsequent siblings)
11 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Move most of the hist trigger extended error documentation to
ftrace.rst and expand on it to fully document tracing/error_log.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
Documentation/trace/ftrace.rst | 31 +++++++++++++++++++++++++++++++
Documentation/trace/histogram.rst | 16 ++--------------
2 files changed, 33 insertions(+), 14 deletions(-)
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
index 7c5e6d6ab5d1..809b39d066ee 100644
--- a/Documentation/trace/ftrace.rst
+++ b/Documentation/trace/ftrace.rst
@@ -765,6 +765,37 @@ Here is the list of current tracers that may be configured.
tracers from tracing simply echo "nop" into
current_tracer.
+Error conditions
+----------------
+
+ For most ftrace commands, failure modes are obvious and communicated
+ using standard return codes.
+
+ For other more involved commands, extended error information may be
+ available via the tracing/error_log file. For the commands that
+ support it, reading the tracing/error_log file after an error will
+ display more detailed information about what went wrong, if
+ information is available. The tracing/error_log file is a circular
+ error log displaying a small number (currently, 8) of ftrace errors
+ for the last (8) failed commands.
+
+ The extended error information and usage takes the form shown in
+ this example::
+
+ # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
+ echo: write error: Invalid argument
+
+ # cat /sys/kernel/debug/tracing/error_log
+ [ 5348.887237] location: error: Couldn't yyy: zzz
+ Command: xxx
+ ^
+ [ 7517.023364] location: error: Bad rrr: sss
+ Command: ppp qqq
+ ^
+
+ To clear the error log, echo the empty string into it::
+
+ # echo > /sys/kernel/debug/tracing/error_log
Examples of using the tracer
----------------------------
diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index 0ea59d45aef1..7612c7ad5715 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -199,20 +199,8 @@ Extended error information
For some error conditions encountered when invoking a hist trigger
command, extended error information is available via the
- corresponding event's 'hist' file. Reading the hist file after an
- error will display more detailed information about what went wrong,
- if information is available. This extended error information will
- be available until the next hist trigger command for that event.
-
- If available for a given error condition, the extended error
- information and usage takes the following form::
-
- # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
- echo: write error: Invalid argument
-
- # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist
- ERROR: Couldn't yyy: zzz
- Last command: xxx
+ tracing/error_log file. See Error Conditions in
+ :file:`Documentation/trace/ftrace.rst` for details.
6.2 'hist' trigger examples
---------------------------
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* [PATCH v4 10/11] tracing: Add error_log to README
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (8 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 09/11] tracing: Add tracing/error_log Documentation Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-22 15:34 ` [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase Tom Zanussi
2019-03-23 10:14 ` [PATCH v4 00/11] tracing: common error_log for ftrace Masami Hiramatsu
11 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Add brief blurb about error_log to the 'Important files' section.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0388038a9253..f6ba2c87572a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -4698,6 +4698,7 @@ static const char readme_msg[] =
" trace_pipe\t\t- A consuming read to see the contents of the buffer\n"
" current_tracer\t- function and latency tracers\n"
" available_tracers\t- list of configured tracers for current_tracer\n"
+ " error_log\t- error log for failed commands (that support it)\n"
" buffer_size_kb\t- view and modify size of per cpu buffer\n"
" buffer_total_size_kb - view total size of all cpu buffers\n\n"
" trace_clock\t\t-change the clock used to order events\n"
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (9 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 10/11] tracing: Add error_log to README Tom Zanussi
@ 2019-03-22 15:34 ` Tom Zanussi
2019-03-23 10:28 ` Masami Hiramatsu
2019-03-23 10:14 ` [PATCH v4 00/11] tracing: common error_log for ftrace Masami Hiramatsu
11 siblings, 1 reply; 25+ messages in thread
From: Tom Zanussi @ 2019-03-22 15:34 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
On my system, /bin/sh is symlinked to dash, which doesn't understand
the >& syntax, so the kprobe and uprobe error cases fail, with this in
the log:
./ftracetest: 26: tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc:
Syntax error: Bad fd number
Changing >& to 2> does work though, and should work in any shell.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 2 +-
tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 2 +-
2 files changed, 2 insertions(+), 2 deletions(-)
diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
index 281665b1348c..7eb577b1d222 100644
--- a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
+++ b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
@@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
command=$(echo "$1" | tr -d ^)
echo "Test command: $command"
echo > error_log
-(! echo "$command" > kprobe_events ) >& /dev/null
+(! echo "$command" > kprobe_events ) 2> /dev/null
grep "trace_kprobe: error:" -A 3 error_log
N=$(tail -n 1 error_log | wc -c)
# " Command: " and "^\n" => 13
diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
index 957011300bb7..ec7389b7934b 100644
--- a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
+++ b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
@@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
command=$(echo "$1" | tr -d ^)
echo "Test command: $command"
echo > error_log
-(! echo "$command" > uprobe_events ) >& /dev/null
+(! echo "$command" > uprobe_events ) 2> /dev/null
grep "trace_uprobe: error:" -A 3 error_log
N=$(tail -n 1 error_log | wc -c)
# " Command: " and "^\n" => 13
--
2.14.1
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase
2019-03-22 15:34 ` [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase Tom Zanussi
@ 2019-03-23 10:28 ` Masami Hiramatsu
2019-03-23 13:14 ` Tom Zanussi
0 siblings, 1 reply; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-23 10:28 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
On Fri, 22 Mar 2019 10:34:37 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> From: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> On my system, /bin/sh is symlinked to dash, which doesn't understand
> the >& syntax, so the kprobe and uprobe error cases fail, with this in
> the log:
>
> ./ftracetest: 26: tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc:
> Syntax error: Bad fd number
>
> Changing >& to 2> does work though, and should work in any shell.
Ah, I missed this patch.
This looks good to me.
Acked-by: Masami Hiramatsu <mhiramat@kernel.org>
BTW, where is my checkbashisms testcase ...
>
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
> tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc | 2 +-
> tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc | 2 +-
> 2 files changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> index 281665b1348c..7eb577b1d222 100644
> --- a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> +++ b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
> @@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
> command=$(echo "$1" | tr -d ^)
> echo "Test command: $command"
> echo > error_log
> -(! echo "$command" > kprobe_events ) >& /dev/null
> +(! echo "$command" > kprobe_events ) 2> /dev/null
> grep "trace_kprobe: error:" -A 3 error_log
> N=$(tail -n 1 error_log | wc -c)
> # " Command: " and "^\n" => 13
> diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
> index 957011300bb7..ec7389b7934b 100644
> --- a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
> +++ b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
> @@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
> command=$(echo "$1" | tr -d ^)
> echo "Test command: $command"
> echo > error_log
> -(! echo "$command" > uprobe_events ) >& /dev/null
> +(! echo "$command" > uprobe_events ) 2> /dev/null
> grep "trace_uprobe: error:" -A 3 error_log
> N=$(tail -n 1 error_log | wc -c)
> # " Command: " and "^\n" => 13
> --
> 2.14.1
>
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase
2019-03-23 10:28 ` Masami Hiramatsu
@ 2019-03-23 13:14 ` Tom Zanussi
0 siblings, 0 replies; 25+ messages in thread
From: Tom Zanussi @ 2019-03-23 13:14 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: rostedt, tglx, namhyung, bigeasy, joel, linux-kernel, linux-rt-users
Hi Masami,
On Sat, 2019-03-23 at 19:28 +0900, Masami Hiramatsu wrote:
> On Fri, 22 Mar 2019 10:34:37 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
>
> > From: Tom Zanussi <tom.zanussi@linux.intel.com>
> >
> > On my system, /bin/sh is symlinked to dash, which doesn't
> > understand
> > the >& syntax, so the kprobe and uprobe error cases fail, with this
> > in
> > the log:
> >
> > ./ftracetest: 26:
> > tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.t
> > c:
> > Syntax error: Bad fd number
> >
> > Changing >& to 2> does work though, and should work in any shell.
>
> Ah, I missed this patch.
>
> This looks good to me.
>
> Acked-by: Masami Hiramatsu <mhiramat@kernel.org>
>
OK, thanks, will merge it with the original testcase.
> BTW, where is my checkbashisms testcase ...
Haha, yeah, seems to be a problem with recent testcases.
Tom
>
> >
> > Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> > ---
> > tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.
> > tc | 2 +-
> > tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.
> > tc | 2 +-
> > 2 files changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git
> > a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > index 281665b1348c..7eb577b1d222 100644
> > ---
> > a/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > +++
> > b/tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors
> > .tc
> > @@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
> > command=$(echo "$1" | tr -d ^)
> > echo "Test command: $command"
> > echo > error_log
> > -(! echo "$command" > kprobe_events ) >& /dev/null
> > +(! echo "$command" > kprobe_events ) 2> /dev/null
> > grep "trace_kprobe: error:" -A 3 error_log
> > N=$(tail -n 1 error_log | wc -c)
> > # " Command: " and "^\n" => 13
> > diff --git
> > a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > index 957011300bb7..ec7389b7934b 100644
> > ---
> > a/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > +++
> > b/tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors
> > .tc
> > @@ -11,7 +11,7 @@ pos=$(echo -n "${1%^*}" | wc -c) # error position
> > command=$(echo "$1" | tr -d ^)
> > echo "Test command: $command"
> > echo > error_log
> > -(! echo "$command" > uprobe_events ) >& /dev/null
> > +(! echo "$command" > uprobe_events ) 2> /dev/null
> > grep "trace_uprobe: error:" -A 3 error_log
> > N=$(tail -n 1 error_log | wc -c)
> > # " Command: " and "^\n" => 13
> > --
> > 2.14.1
> >
>
>
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v4 00/11] tracing: common error_log for ftrace
2019-03-22 15:34 [PATCH v4 00/11] tracing: common error_log for ftrace Tom Zanussi
` (10 preceding siblings ...)
2019-03-22 15:34 ` [PATCH v4 11/11] selftests/ftrace: Change stderr redirection for probe error_log testcase Tom Zanussi
@ 2019-03-23 10:14 ` Masami Hiramatsu
11 siblings, 0 replies; 25+ messages in thread
From: Masami Hiramatsu @ 2019-03-23 10:14 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, tglx, mhiramat, namhyung, bigeasy, joel, linux-kernel,
linux-rt-users
Hi Tom,
On Fri, 22 Mar 2019 10:34:26 -0500
Tom Zanussi <zanussi@kernel.org> wrote:
> From: Tom Zanussi <tom.zanussi@linux.intel.com>
>
> Hi,
>
> This is v4 of the frace error_log patchset. This version adds
> Masami's probe events error_log patches and removes the previous
> placeholder for that. It also removes the hist trigger extended error
> err testcase and replaces it with a basic error_log functionality
> testcase, and replaces the error numbering with timestamps, also as
> suggested by Masami. Finally, the Documentation and README are both
> updated to describe the error_log.
Thank you for updating this series! :)
>
> Note: The probe event error_log test cases failed on my Ubuntu system,
> due to the >& redirection operator that dash doesn't understand, so I
> tacked on a final patch that fixes it for me. If acceptable, feel
> free to just merge it with Masami's patch.
Oops, that's my laziness... that should be > /dev/null 2>&1, sorry.
[...]
> Below is an example session of a few failed commands and the
> corresponding error_log contents:
>
> # echo > /sys/kernel/debug/tracing/error_log
>
> # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> -su: echo: write error: Invalid argument
>
> # cat /sys/kernel/debug/tracing/error_log
> [ 217.431858] hist:sched:sched_wakeup: error: Variable already defined
> Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
> ^
>
Yeah, this looks good to me :)
Thank you!
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 25+ messages in thread