[PATCH 1/6] dyndbg: fix usability bug by adding pr_errs for -EINVALs

[PATCH 1/6] dyndbg: fix usability bug by adding pr_errs for -EINVALs

[Jim Cromie]

A recent usability grumble on LKML prompted a review of error
reporting when writing dyndbg queries.  For each -EINVAL, this adds
pr_err()s to explain the error.

To: Jason Baron <jbaron@redhat.com>
To: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
CC: Jianpeng Ma <majianpeng@gmail.com>
Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 40 ++++++++++++++++++++++++++++++----------
 1 file changed, 30 insertions(+), 10 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index e7f7d99..ceda053 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -222,8 +222,10 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
 			int quote = *buf++;
 			for (end = buf ; *end && *end != quote ; end++)
 				;
-			if (!*end)
+			if (!*end) {
+				pr_err("unclosed quote: %s\n", buf);
 				return -EINVAL;	/* unclosed quote */
+			}
 		} else {
 			for (end = buf ; *end && !isspace(*end) ; end++)
 				;
@@ -231,8 +233,10 @@ static int ddebug_tokenize(char *buf, char *words[], int maxwords)
 		}
 
 		/* `buf' is start of word, `end' is one past its end */
-		if (nwords == maxwords)
+		if (nwords == maxwords) {
+			pr_err("too many words, legal max <=%d\n", maxwords);
 			return -EINVAL;	/* ran out of words[] before bytes */
+		}
 		if (*end)
 			*end++ = '\0';	/* terminate the word */
 		words[nwords++] = buf;
@@ -264,7 +268,11 @@ static inline int parse_lineno(const char *str, unsigned int *val)
 		return 0;
 	}
 	*val = simple_strtoul(str, &end, 10);
-	return end == NULL || end == str || *end != '\0' ? -EINVAL : 0;
+	if (end == NULL || end == str || *end != '\0') {
+		pr_err("illegal line-number: %s\n", str);
+		return -EINVAL;
+	}
+	return 0;
 }
 
 /*
@@ -344,8 +352,10 @@ static int ddebug_parse_query(char *words[], int nwords,
 	int rc;
 
 	/* check we have an even number of words */
-	if (nwords % 2 != 0)
+	if (nwords % 2 != 0) {
+		pr_err("legal query spec is pairs of: spec value\n");
 		return -EINVAL;
+	}
 	memset(query, 0, sizeof(*query));
 
 	if (modname)
@@ -371,8 +381,10 @@ static int ddebug_parse_query(char *words[], int nwords,
 			}
 			if (last)
 				*last++ = '\0';
-			if (parse_lineno(first, &query->first_lineno) < 0)
+			if (parse_lineno(first, &query->first_lineno) < 0) {
+				pr_err("line-number is <0\n");
 				return -EINVAL;
+			}
 			if (last) {
 				/* range <first>-<last> */
 				if (parse_lineno(last, &query->last_lineno)
@@ -413,6 +425,7 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 		op = *str++;
 		break;
 	default:
+		pr_err("bad flags-op, expecting [+-=], not %c\n", *str);
 		return -EINVAL;
 	}
 	vpr_info("op='%c'\n", op);
@@ -424,8 +437,10 @@ static int ddebug_parse_flags(const char *str, unsigned int *flagsp,
 				break;
 			}
 		}
-		if (i < 0)
+		if (i < 0) {
+			pr_err("unknown flag: %c\n", *str);
 			return -EINVAL;
+		}
 	}
 	vpr_info("flags=0x%x\n", flags);
 
@@ -457,13 +472,18 @@ static int ddebug_exec_query(char *query_string, const char *modname)
 	char *words[MAXWORDS];
 
 	nwords = ddebug_tokenize(query_string, words, MAXWORDS);
-	if (nwords <= 0)
+	if (nwords <= 0) {
+		pr_err("tokenize failed\n");
 		return -EINVAL;
-	if (ddebug_parse_query(words, nwords-1, &query, modname))
+	}
+	if (ddebug_parse_query(words, nwords-1, &query, modname)) {
+		pr_err("query spec parse failed\n");
 		return -EINVAL;
-	if (ddebug_parse_flags(words[nwords-1], &flags, &mask))
+	}
+	if (ddebug_parse_flags(words[nwords-1], &flags, &mask)) {
+		pr_err("flags parse failed\n");
 		return -EINVAL;
-
+	}
 	/* actually go and implement the change */
 	nfound = ddebug_change(&query, flags, mask);
 	vpr_info_dq((&query), (nfound) ? "applied" : "no-match");
-- 
1.7.11.4

[PATCH 2/6] dyndbg: spelling fix s/conrol/control/

[Jim Cromie]

fix name of control file in comment

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index ceda053..43ae319 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -680,7 +680,7 @@ static __init int ddebug_setup_query(char *str)
 __setup("ddebug_query=", ddebug_setup_query);
 
 /*
- * File_ops->write method for <debugfs>/dynamic_debug/conrol.  Gathers the
+ * File_ops->write method for <debugfs>/dynamic_debug/control.  Gathers the
  * command text from userspace, parses and executes it.
  */
 #define USER_BUF_PAGE 4096
-- 
1.7.11.4

[PATCH 3/6] dyndbg: add more info to -E2BIG log warning

[Jim Cromie]

Tell user how big the attempted write was, in case its not obvious.
This helped identify a missing flush in my stress-test script.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 43ae319..85258a8 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -693,7 +693,8 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
 	if (len == 0)
 		return 0;
 	if (len > USER_BUF_PAGE - 1) {
-		pr_warn("expected <%d bytes into control\n", USER_BUF_PAGE);
+		pr_warn("expected <%d bytes into control, you wrote %d\n",
+			USER_BUF_PAGE, (int) len);
 		return -E2BIG;
 	}
 	tmpbuf = kmalloc(len + 1, GFP_KERNEL);
-- 
1.7.11.4

Re: [PATCH 3/6] dyndbg: add more info to -E2BIG log warning

[Jason Baron]

On Tue, Sep 18, 2012 at 05:36:44PM -0600, Jim Cromie wrote:
> Tell user how big the attempted write was, in case its not obvious.
> This helped identify a missing flush in my stress-test script.
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> ---
>  lib/dynamic_debug.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
> index 43ae319..85258a8 100644
> --- a/lib/dynamic_debug.c
> +++ b/lib/dynamic_debug.c
> @@ -693,7 +693,8 @@ static ssize_t ddebug_proc_write(struct file *file, const char __user *ubuf,
>  	if (len == 0)
>  		return 0;
>  	if (len > USER_BUF_PAGE - 1) {
> -		pr_warn("expected <%d bytes into control\n", USER_BUF_PAGE);
> +		pr_warn("expected <%d bytes into control, you wrote %d\n",
> +			USER_BUF_PAGE, (int) len);

The style here, I think, is generally to leave out the space, ie: (int)len.

Thanks,

-Jason

Re: [PATCH 3/6] dyndbg: add more info to -E2BIG log warning

[Geert Uytterhoeven]

On Mon, Sep 24, 2012 at 9:00 PM, Jason Baron <jbaron@redhat.com> wrote:
>> -             pr_warn("expected <%d bytes into control\n", USER_BUF_PAGE);

%u?

>> +             pr_warn("expected <%d bytes into control, you wrote %d\n",
>> +                     USER_BUF_PAGE, (int) len);
>
> The style here, I think, is generally to leave out the space, ie: (int)len.

Better, remove the cast and use "%zu" to properly format the size_t.

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH 3/6] dyndbg: add more info to -E2BIG log warning

[Jim Cromie]

On Mon, Sep 24, 2012 at 1:04 PM, Geert Uytterhoeven
<geert@linux-m68k.org> wrote:
> On Mon, Sep 24, 2012 at 9:00 PM, Jason Baron <jbaron@redhat.com> wrote:
>>> -             pr_warn("expected <%d bytes into control\n", USER_BUF_PAGE);
>
> %u?
>
>>> +             pr_warn("expected <%d bytes into control, you wrote %d\n",
>>> +                     USER_BUF_PAGE, (int) len);
>>
>> The style here, I think, is generally to leave out the space, ie: (int)len.
>
> Better, remove the cast and use "%zu" to properly format the size_t.
>

Ack, thanks.  Update coming soon.

Is there a suitable macro defn to replace this?

#define USER_BUF_PAGE 4096

grep -r 4096 include/ fs/  finds plenty, but none look particularly
appropriate here.


> Gr{oetje,eeting}s,
>
>                         Geert
>
> --
> Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
>
> In personal conversations with technical people, I call myself a hacker. But
> when I'm talking to journalists I just say "programmer" or something like that.
>                                 -- Linus Torvalds

[PATCH 4/6] dyndbg: increase verbosity for proc-show, proc-next

[Jim Cromie]

When dynamic_debug.verbose=1, catting /dbg/dynamic_debug/control
creates reams of log entries from ddebug_proc_(show|next|start|open).

Add vXpr_info() macro, and adjust verbosity required to enable those
callsites to 9 for show, next, and 8 for start, open.  This leaves
other verbosity levels available should that appear useful later.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 18 +++++++++++-------
 1 file changed, 11 insertions(+), 7 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 85258a8..11a8897 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -107,8 +107,12 @@ static char *ddebug_describe_flags(struct _ddebug *dp, char *buf,
 	return buf;
 }
 
-#define vpr_info(fmt, ...) \
-	if (verbose) do { pr_info(fmt, ##__VA_ARGS__); } while (0)
+#define vXpr_info(X, fmt, ...) \
+	if (verbose >= X) do { pr_info(fmt, ##__VA_ARGS__); } while (0)
+
+#define vpr_info(fmt, ...)	vXpr_info(1, fmt, ##__VA_ARGS__)
+#define v8pr_info(fmt, ...)	vXpr_info(8, fmt, ##__VA_ARGS__)
+#define v9pr_info(fmt, ...)	vXpr_info(9, fmt, ##__VA_ARGS__)
 
 #define vpr_info_dq(q, msg)					\
 do {								\
@@ -768,7 +772,7 @@ static void *ddebug_proc_start(struct seq_file *m, loff_t *pos)
 	struct _ddebug *dp;
 	int n = *pos;
 
-	vpr_info("called m=%p *pos=%lld\n", m, (unsigned long long)*pos);
+	v8pr_info("called m=%p *pos=%lld\n", m, (unsigned long long)*pos);
 
 	mutex_lock(&ddebug_lock);
 
@@ -792,7 +796,7 @@ static void *ddebug_proc_next(struct seq_file *m, void *p, loff_t *pos)
 	struct ddebug_iter *iter = m->private;
 	struct _ddebug *dp;
 
-	vpr_info("called m=%p p=%p *pos=%lld\n",
+	v9pr_info("called m=%p p=%p *pos=%lld\n",
 		m, p, (unsigned long long)*pos);
 
 	if (p == SEQ_START_TOKEN)
@@ -815,7 +819,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
 	struct _ddebug *dp = p;
 	char flagsbuf[10];
 
-	vpr_info("called m=%p p=%p\n", m, p);
+	v9pr_info("called m=%p p=%p\n", m, p);
 
 	if (p == SEQ_START_TOKEN) {
 		seq_puts(m,
@@ -839,7 +843,7 @@ static int ddebug_proc_show(struct seq_file *m, void *p)
  */
 static void ddebug_proc_stop(struct seq_file *m, void *p)
 {
-	vpr_info("called m=%p p=%p\n", m, p);
+	v8pr_info("called m=%p p=%p\n", m, p);
 	mutex_unlock(&ddebug_lock);
 }
 
@@ -862,7 +866,7 @@ static int ddebug_proc_open(struct inode *inode, struct file *file)
 	struct ddebug_iter *iter;
 	int err;
 
-	vpr_info("called\n");
+	v8pr_info("called\n");
 
 	iter = kzalloc(sizeof(*iter), GFP_KERNEL);
 	if (iter == NULL)
-- 
1.7.11.4

[PATCH 5/6] dyndbg: in dynamic_emit_prefix, change inter-field separator

[Jim Cromie]

dynamic_emit_prefix() currently separates modname, funcname, lineno
with ':'.  This is confounds use of cut -d: <logfile>, since the field
positions can change per callsite with dynamic-debug.  So change
inter-field separator to '.' and keep the ':' prefix terminator.

This improves the situation, but doesnt solve it entirely; if
dyndbg==p is used instead of dyndbg==p[fmlt]+, the callsite is enabled
but no prefix is added, so theres one less ':' in the message.
Changing the terminator to ',' would fix this, and might be warranted,
especially since pr_fmt() typically adds a ':' as well.

Joe Perches wasnt a fan of this, but his complaint was essentially
that cut -d: was a poor way to do this kind of thing.  I concede that
point, but note that the kernel is not in the habit of needlessly
confounding users work, at least when accommodating them is so trivial.

cc: Joe Perches <joe@perches.com>
Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 12 +++++++-----
 1 file changed, 7 insertions(+), 5 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index 11a8897..f1f7467 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -556,16 +556,18 @@ static char *dynamic_emit_prefix(const struct _ddebug *desc, char *buf)
 	}
 	pos_after_tid = pos;
 	if (desc->flags & _DPRINTK_FLAGS_INCL_MODNAME)
-		pos += snprintf(buf + pos, remaining(pos), "%s:",
+		pos += snprintf(buf + pos, remaining(pos), "%s.",
 				desc->modname);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_FUNCNAME)
-		pos += snprintf(buf + pos, remaining(pos), "%s:",
+		pos += snprintf(buf + pos, remaining(pos), "%s.",
 				desc->function);
 	if (desc->flags & _DPRINTK_FLAGS_INCL_LINENO)
-		pos += snprintf(buf + pos, remaining(pos), "%d:",
+		pos += snprintf(buf + pos, remaining(pos), "%d.",
 				desc->lineno);
-	if (pos - pos_after_tid)
-		pos += snprintf(buf + pos, remaining(pos), " ");
+	if (pos - pos_after_tid) {
+		pos--;
+		pos += snprintf(buf + pos, remaining(pos), ": ");
+	}
 	if (pos >= PREFIX_SIZE)
 		buf[PREFIX_SIZE - 1] = '\0';
 
-- 
1.7.11.4

Re: [PATCH 5/6] dyndbg: in dynamic_emit_prefix, change inter-field separator

[Joe Perches]

On Tue, 2012-09-18 at 17:36 -0600, Jim Cromie wrote:
> dynamic_emit_prefix() currently separates modname, funcname, lineno
> with ':'.  This is confounds use of cut -d: <logfile>, since the field
> positions can change per callsite with dynamic-debug.  So change
> inter-field separator to '.' and keep the ':' prefix terminator.
> 
> This improves the situation, but doesnt solve it entirely; if
> dyndbg==p is used instead of dyndbg==p[fmlt]+, the callsite is enabled
> but no prefix is added, so theres one less ':' in the message.
> Changing the terminator to ',' would fix this, and might be warranted,
> especially since pr_fmt() typically adds a ':' as well.
> 
> Joe Perches wasnt a fan of this, but his complaint was essentially
> that cut -d: was a poor way to do this kind of thing.  I concede that
> point, but note that the kernel is not in the habit of needlessly
> confounding users work, at least when accommodating them is so trivial.

And I still think this is ugly as it requires different parsing
by scripts when using combinations of +pfmlt

Re: [PATCH 5/6] dyndbg: in dynamic_emit_prefix, change inter-field separator

[Jason Baron]

On Tue, Sep 18, 2012 at 07:56:42PM -0700, Joe Perches wrote:
> On Tue, 2012-09-18 at 17:36 -0600, Jim Cromie wrote:
> > dynamic_emit_prefix() currently separates modname, funcname, lineno
> > with ':'.  This is confounds use of cut -d: <logfile>, since the field
> > positions can change per callsite with dynamic-debug.  So change
> > inter-field separator to '.' and keep the ':' prefix terminator.
> > 
> > This improves the situation, but doesnt solve it entirely; if
> > dyndbg==p is used instead of dyndbg==p[fmlt]+, the callsite is enabled
> > but no prefix is added, so theres one less ':' in the message.
> > Changing the terminator to ',' would fix this, and might be warranted,
> > especially since pr_fmt() typically adds a ':' as well.
> > 
> > Joe Perches wasnt a fan of this, but his complaint was essentially
> > that cut -d: was a poor way to do this kind of thing.  I concede that
> > point, but note that the kernel is not in the habit of needlessly
> > confounding users work, at least when accommodating them is so trivial.
> 
> And I still think this is ugly as it requires different parsing
> by scripts when using combinations of +pfmlt
> 
> 

If this patch doesn't 'solve it entirely', I'm reluctant to ack it,
Would brackets, such as {} around the optional prefix be reasonable?

Thanks,

-Jason

[PATCH 6/6] dyndbg: change varname verbose_bytes to bytes_used

[Jim Cromie]

New name reflects purpose (count bytes used), verbose is just print
condition, and counting proceeds either way.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 lib/dynamic_debug.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/lib/dynamic_debug.c b/lib/dynamic_debug.c
index f1f7467..c787d1d 100644
--- a/lib/dynamic_debug.c
+++ b/lib/dynamic_debug.c
@@ -1033,7 +1033,7 @@ static int __init dynamic_debug_init(void)
 	char *cmdline;
 	int ret = 0;
 	int n = 0, entries = 0, modct = 0;
-	int verbose_bytes = 0;
+	int bytes_used = 0;
 
 	if (__start___verbose == __stop___verbose) {
 		pr_warn("_ddebug table is empty in a "
@@ -1045,7 +1045,7 @@ static int __init dynamic_debug_init(void)
 	iter_start = iter;
 	for (; iter < __stop___verbose; iter++) {
 		entries++;
-		verbose_bytes += strlen(iter->modname) + strlen(iter->function)
+		bytes_used += strlen(iter->modname) + strlen(iter->function)
 			+ strlen(iter->filename) + strlen(iter->format);
 
 		if (strcmp(modname, iter->modname)) {
@@ -1067,7 +1067,7 @@ static int __init dynamic_debug_init(void)
 	vpr_info("%d modules, %d entries and %d bytes in ddebug tables,"
 		" %d bytes in (readonly) verbose section\n",
 		modct, entries, (int)( modct * sizeof(struct ddebug_table)),
-		verbose_bytes + (int)(__stop___verbose - __start___verbose));
+		bytes_used + (int)(__stop___verbose - __start___verbose));
 
 	/* apply ddebug_query boot param, dont unload tables on err */
 	if (ddebug_setup_string[0] != '\0') {
-- 
1.7.11.4