[PATCH] checkpatch: Add a warning for log messages that don't end in a line feed

[PATCH] checkpatch: Add a warning for log messages that don't end in a line feed

[Logan Gunthorpe]

Check for lines with a log function using a $logLineFeedFunctions
expression which is similar to the existing $logFunctions expression
except we don't include MODULE and seq_ functions.

Once an appropriate log function is found, mark that we are in a
log function (for multiline calls). The mark is removed once we see a
line ending in ';' or the end of a patch hunk (similar to $in_comment).

For lines that are in a log function (including the first and last),
if we see a quoted string that ends in \n, we remove the mark as we are
likely good. Otherwise, if we see a quote followed by a comma or a close
paraenthesis, that isn't preceded by a backslash than it looks like we
have found the end of the format string without a \n and we WARN.

Signed-off-by: Logan Gunthorpe <logang@deltatee.com>
Cc: Andy Whitcroft <apw@canonical.com>
Cc: Joe Perches <joe@perches.com>
---

This is my penance for breaking this rule for a while.

I've run these changes on a number of patchsets I've submitted and it
seems to perform quite well. I've also done my best to try and trick
it with different forms of log messages but I haven't come up with
anything that's a false positive or negative. If anyone's creative
enough to come up with something that does break it I can see if I can
address it.

 scripts/checkpatch.pl | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/scripts/checkpatch.pl b/scripts/checkpatch.pl
index 8b80bac055e4..917725f36283 100755
--- a/scripts/checkpatch.pl
+++ b/scripts/checkpatch.pl
@@ -460,6 +460,13 @@ our $logFunctions = qr{(?x:
 	seq_vprintf|seq_printf|seq_puts
 )};

+our $logLineFeedFunctions = qr{(?x:
+	printk(?:_ratelimited|_once|_deferred_once|_deferred|)|
+	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|)|
+	WARN(?:_RATELIMIT|_ONCE|)|
+	panic
+)};
+
 our $signature_tags = qr{(?xi:
 	Signed-off-by:|
 	Acked-by:|
@@ -2202,6 +2209,7 @@ sub process {
 	my $here = '';
 	my $context_function;		#undef'd unless there's a known function
 	my $in_comment = 0;
+	my $in_log_function = 0;
 	my $comment_edge = 0;
 	my $first_line = 0;
 	my $p1_prefix = '';
@@ -2247,6 +2255,7 @@ sub process {
 				$realcnt=1+1;
 			}
 			$in_comment = 0;
+			$in_log_function = 0;

 			# Guestimate if this is a continuing comment.  Run
 			# the context looking for a comment "edge".  If this
@@ -5389,6 +5398,23 @@ sub process {
 			}
 		}

+# check for logging functions with lines that don't end in a '\n"'
+		if ($line =~ /\b$logLineFeedFunctions\s*\(/) {
+			$in_log_function = 1;
+		}
+		if ($in_log_function) {
+			my $qstr = get_quoted_string($line, $rawline);
+			if ($qstr =~ /\\n"$/) {
+				$in_log_function = 0;
+			} elsif ($line =~ /[^\\]"[,)]/) {
+				WARN("LOGGING_MISSING_LINEFEED",
+				     "Log messages should end in a line feed (\\n)\n" . $herecurr);
+				$in_log_function = 0;
+			} elsif ($line =~ /;$/) {
+				$in_log_function = 0;
+			}
+		}
+
 # check for logging continuations
 		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
 			WARN("LOGGING_CONTINUATION",
--
2.11.0

Re: [PATCH] checkpatch: Add a warning for log messages that don't end in a line feed

[Joe Perches]

On Wed, 2017-11-22 at 13:55 -0700, Logan Gunthorpe wrote:
> Check for lines with a log function using a $logLineFeedFunctions
> expression which is similar to the existing $logFunctions expression
> except we don't include MODULE and seq_ functions.
> 
> Once an appropriate log function is found, mark that we are in a
> log function (for multiline calls). The mark is removed once we see a
> line ending in ';' or the end of a patch hunk (similar to $in_comment).
> 
> For lines that are in a log function (including the first and last),
> if we see a quoted string that ends in \n, we remove the mark as we are
> likely good. Otherwise, if we see a quote followed by a comma or a close
> paraenthesis, that isn't preceded by a backslash than it looks like we
> have found the end of the format string without a \n and we WARN.
> 
> Signed-off-by: Logan Gunthorpe <logang@deltatee.com>
> Cc: Andy Whitcroft <apw@canonical.com>
> Cc: Joe Perches <joe@perches.com>
> ---
> 
> This is my penance for breaking this rule for a while.
> 
> I've run these changes on a number of patchsets I've submitted and it
> seems to perform quite well.
>
>  I've also done my best to try and trick
> it with different forms of log messages but I haven't come up with
> anything that's a false positive or negative. If anyone's creative
> enough to come up with something that does break it I can see if I can
> address it.

nack.

Try running it on the kernel source tree with -f and
see what you think.

$ git ls-files -- "*.[ch]" |
  xargs --max-args=20 --max-procs=$(grep -c ^processor /proc/cpuinfo) \
    ./scripts/checkpatch.pl -f --quiet --no-summary \
      --types=LOGGING_MISSING_LINEFEED

There are a lot of false positives.

Any printk with a pr_cont/printk(KERN_CONT that follows
generates this warning.

A lot of macros also add "\n" to the passed format
string (e.g.: ext4_warning)

Any concatenated format like "foo" ##bar "baz\n" would
also get this eror.

A couple more comments below:

cheers, Joe

>  scripts/checkpatch.pl | 26 ++++++++++++++++++++++++++
>  1 file changed, 26 insertions(+)
> 
> diff --git a/scripts/checkpatch.pl b/scripts/checkpatch.pl
> index 8b80bac055e4..917725f36283 100755
> --- a/scripts/checkpatch.pl
> +++ b/scripts/checkpatch.pl
> @@ -460,6 +460,13 @@ our $logFunctions = qr{(?x:
>  	seq_vprintf|seq_printf|seq_puts
>  )};
> 
> +our $logLineFeedFunctions = qr{(?x:
> +	printk(?:_ratelimited|_once|_deferred_once|_deferred|)|
> +	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|)|
> +	WARN(?:_RATELIMIT|_ONCE|)|
> +	panic
> +)};
> +
>  our $signature_tags = qr{(?xi:
>  	Signed-off-by:|
>  	Acked-by:|
> @@ -2202,6 +2209,7 @@ sub process {
>  	my $here = '';
>  	my $context_function;		#undef'd unless there's a known function
>  	my $in_comment = 0;
> +	my $in_log_function = 0;
>  	my $comment_edge = 0;
>  	my $first_line = 0;
>  	my $p1_prefix = '';
> @@ -2247,6 +2255,7 @@ sub process {
>  				$realcnt=1+1;
>  			}
>  			$in_comment = 0;
> +			$in_log_function = 0;
> 
>  			# Guestimate if this is a continuing comment.  Run
>  			# the context looking for a comment "edge".  If this
> @@ -5389,6 +5398,23 @@ sub process {
>  			}
>  		}
> 
> +# check for logging functions with lines that don't end in a '\n"'
> +		if ($line =~ /\b$logLineFeedFunctions\s*\(/) {
> +			$in_log_function = 1;
> +		}
> +		if ($in_log_function) {
> +			my $qstr = get_quoted_string($line, $rawline);
> +			if ($qstr =~ /\\n"$/) {
> +				$in_log_function = 0;

This doesn't work if there are multiple patch fragments.

> +			} elsif ($line =~ /[^\\]"[,)]/) {
> +				WARN("LOGGING_MISSING_LINEFEED",

LINEFEED isn't correct, NEWLINE please

> +				     "Log messages should end in a line feed (\\n)\n" . $herecurr);
> +				$in_log_function = 0;
> +			} elsif ($line =~ /;$/) {
> +				$in_log_function = 0;
> +			}
> +		}
> +
>  # check for logging continuations
>  		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
>  			WARN("LOGGING_CONTINUATION",
> --
> 2.11.0