[PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

[PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

This series adds new printk wrapper macros pr_<level>_cont().
These create continuation messages with an explicit level.

Explicit levels are useful when a continuation message is split from its main
message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
which can lead to stray partial log messages when filtering by level.

Also checkpatch is modified to recommend the new macros over plain pr_cont().

Lastly the new macros are used in kernel/power/process.c as this file uses
continuation messages during system suspend-resume which creates a high
likelyhood of interspersed messages.

Changelog:

This was original a single patch but was expanded into a series.

v1: https://lore.kernel.org/lkml/20221121050946.3540-1-linux@weissschuh.net/
v1 -> v2:
  * Introduce new pr_<level>_cont() macros in printk.h
  * Add checkpatch.pl validation

Thomas Weißschuh (3):
  printk: introduce new macros pr_<level>_cont()
  checkpatch: handle new pr_<level>_cont macros
  power: process: use explicit levels for printk continuations

 include/linux/printk.h | 23 +++++++++++++++++++++++
 kernel/power/process.c | 18 +++++++++---------
 scripts/checkpatch.pl  | 10 ++++++++--
 3 files changed, 40 insertions(+), 11 deletions(-)


base-commit: 0b1dcc2cf55ae6523c6fbd0d741b3ac28c9f4536
-- 
2.38.1

[PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

These macros emit continuation messages with explicit levels.
In case the continuation is logged separately from the original message
it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray
continuation messages without context.

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 8c81806c2e99..8f564c38f121 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)
@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
+
 extern const struct file_operations kmsg_fops;
 
 enum {
-- 
2.38.1

[PATCH v2 2/3] checkpatch: handle new pr_<level>_cont macros

[Thomas Weißschuh]

These new macros from include/linux/printk.h replace the usage of plain
pr_cont().

Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
---
 scripts/checkpatch.pl | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/scripts/checkpatch.pl b/scripts/checkpatch.pl
index 1e5e66ae5a52..fb1747639c9c 100755
--- a/scripts/checkpatch.pl
+++ b/scripts/checkpatch.pl
@@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
 
 our $logFunctions = 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|)|
+	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|_cont|)|
 	TP_printk|
 	WARN(?:_RATELIMIT|_ONCE|)|
 	panic|
@@ -6374,11 +6374,17 @@ sub process {
 		}
 
 # check for logging continuations
-		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
+		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_([a-z]+_)?cont\s*\(/) {
 			WARN("LOGGING_CONTINUATION",
 			     "Avoid logging continuation uses where feasible\n" . $herecurr);
 		}
 
+# check for logging continuations without explicit level
+		if ($line =~ /\bpr_cont\s*\(/) {
+			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
+			     "Avoid logging continuation without level\n" . $herecurr);
+		}
+
 # check for unnecessary use of %h[xudi] and %hh[xudi] in logging functions
 		if (defined $stat &&
 		    $line =~ /\b$logFunctions\s*\(/ &&
-- 
2.38.1

[PATCH v2 3/3] power: process: use explicit levels for printk continuations

[Thomas Weißschuh]

Many of the printk messages emitted during suspend and resume are
emitted in fragments using pr_cont()/KERN_CONT.

As during suspend and resume a lot of operations are happing in the
kernel the chances are high that the fragments are interspersed with
unrelated messages.

In this case if no explicit level is specified for the fragments the
standard level is applied, which by default is KERN_WARNING.

If the user is only observing KERN_WARNING and *not* KERN_INFO messages
they will see incomplete message fragments.

By specifing the correct printk level also with the continuations this
mismatch can be avoided.
Also it reduces the amount of false-positive KERN_WARNING messages.

Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
---
 kernel/power/process.c | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

diff --git a/kernel/power/process.c b/kernel/power/process.c
index ddd9988327fe..698a823033e4 100644
--- a/kernel/power/process.c
+++ b/kernel/power/process.c
@@ -82,7 +82,7 @@ static int try_to_freeze_tasks(bool user_only)
 	elapsed_msecs = ktime_to_ms(elapsed);
 
 	if (todo) {
-		pr_cont("\n");
+		pr_info_cont("\n");
 		pr_err("Freezing of tasks %s after %d.%03d seconds "
 		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
 		       wakeup ? "aborted" : "failed",
@@ -101,8 +101,8 @@ static int try_to_freeze_tasks(bool user_only)
 			read_unlock(&tasklist_lock);
 		}
 	} else {
-		pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
-			elapsed_msecs % 1000);
+		pr_info_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
+			     elapsed_msecs % 1000);
 	}
 
 	return todo ? -EBUSY : 0;
@@ -135,9 +135,9 @@ int freeze_processes(void)
 	error = try_to_freeze_tasks(true);
 	if (!error) {
 		__usermodehelper_set_disable_depth(UMH_DISABLED);
-		pr_cont("done.");
+		pr_info_cont("done.");
 	}
-	pr_cont("\n");
+	pr_info_cont("\n");
 	BUG_ON(in_atomic());
 
 	/*
@@ -171,9 +171,9 @@ int freeze_kernel_threads(void)
 	pm_nosig_freezing = true;
 	error = try_to_freeze_tasks(false);
 	if (!error)
-		pr_cont("done.");
+		pr_info_cont("done.");
 
-	pr_cont("\n");
+	pr_info_cont("\n");
 	BUG_ON(in_atomic());
 
 	if (error)
@@ -215,7 +215,7 @@ void thaw_processes(void)
 	usermodehelper_enable();
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info_cont("done.\n");
 	trace_suspend_resume(TPS("thaw_processes"), 0, false);
 }
 
@@ -236,5 +236,5 @@ void thaw_kernel_threads(void)
 	read_unlock(&tasklist_lock);
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info_cont("done.\n");
 }
-- 
2.38.1

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

[Joe Perches]

On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> Many of the printk messages emitted during suspend and resume are
> emitted in fragments using pr_cont()/KERN_CONT.
> 
> As during suspend and resume a lot of operations are happing in the
> kernel the chances are high that the fragments are interspersed with
> unrelated messages.
> 
> In this case if no explicit level is specified for the fragments the
> standard level is applied, which by default is KERN_WARNING.
> 
> If the user is only observing KERN_WARNING and *not* KERN_INFO messages
> they will see incomplete message fragments.
> 
> By specifing the correct printk level also with the continuations this
> mismatch can be avoided.
> Also it reduces the amount of false-positive KERN_WARNING messages.
> 
> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> ---
>  kernel/power/process.c | 18 +++++++++---------
>  1 file changed, 9 insertions(+), 9 deletions(-)
> 
> diff --git a/kernel/power/process.c b/kernel/power/process.c
[]
> @@ -82,7 +82,7 @@ static int try_to_freeze_tasks(bool user_only)
>  	elapsed_msecs = ktime_to_ms(elapsed);
>  
>  	if (todo) {
> -		pr_cont("\n");
> +		pr_info_cont("\n");

I think this isn't needed because of the immediately following pr_err.

>  		pr_err("Freezing of tasks %s after %d.%03d seconds "
>  		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
>  		       wakeup ? "aborted" : "failed",

Re: [PATCH v2 2/3] checkpatch: handle new pr_<level>_cont macros

[Joe Perches]

On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> These new macros from include/linux/printk.h replace the usage of plain
> pr_cont().
[]
> diff --git a/scripts/checkpatch.pl b/scripts/checkpatch.pl
> index 1e5e66ae5a52..fb1747639c9c 100755
> --- a/scripts/checkpatch.pl
> +++ b/scripts/checkpatch.pl
> @@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
>  
>  our $logFunctions = 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|)|
> +	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|_cont|)|

OK

>  	TP_printk|
>  	WARN(?:_RATELIMIT|_ONCE|)|
>  	panic|
> @@ -6374,11 +6374,17 @@ sub process {
>  		}
>  
>  # check for logging continuations
> -		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
> +		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_([a-z]+_)?cont\s*\(/) {
>  			WARN("LOGGING_CONTINUATION",
>  			     "Avoid logging continuation uses where feasible\n" . $herecurr);
>  		}

OK

> +# check for logging continuations without explicit level
> +		if ($line =~ /\bpr_cont\s*\(/) {
> +			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
> +			     "Avoid logging continuation without level\n" . $herecurr);
> +		}
> +

Not so sure about this one.

I think relatively few situations are going to require interleaving avoidance.

>  # check for unnecessary use of %h[xudi] and %hh[xudi] in logging functions
>  		if (defined $stat &&
>  		    $line =~ /\b$logFunctions\s*\(/ &&

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Joe Perches]

On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> These macros emit continuation messages with explicit levels.
> In case the continuation is logged separately from the original message
> it will retain its level instead of falling back to KERN_DEFAULT.
> 
> This remedies the issue that logs filtered by level contain stray
> continuation messages without context.
> 
> Suggested-by: Petr Mladek <pmladek@suse.com>
> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> ---
>  include/linux/printk.h | 23 +++++++++++++++++++++++
>  1 file changed, 23 insertions(+)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 8c81806c2e99..8f564c38f121 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -537,6 +537,8 @@ struct pi_entry {
>   * This macro expands to a printk with KERN_CONT loglevel. It should only be
>   * used when continuing a log message with no newline ('\n') enclosed. Otherwise
>   * it defaults back to KERN_DEFAULT loglevel.
> + *
> + * Use the dedicated pr_<level>_cont() macros instead.
>   */
>  #define pr_cont(fmt, ...) \
>  	printk(KERN_CONT fmt, ##__VA_ARGS__)
> @@ -701,6 +703,27 @@ do {									\
>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>  #endif
>  
> +/*
> + * Print a continuation message with level. In case the continuation is split
> + * from the main message it preserves the level.
> + */
> +
> +#define pr_emerg_cont(fmt, ...)					\
> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

> +#define pr_alert_cont(fmt, ...)					\
> +	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_crit_cont(fmt, ...)					\
> +	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_err_cont(fmt, ...)					\
> +	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_warn_cont(fmt, ...)					\
> +	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_notice_cont(fmt, ...)					\
> +	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_info_cont(fmt, ...)					\
> +	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
> +
>  extern const struct file_operations kmsg_fops;
>  
>  enum {

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

On 2022-11-25 12:18-0800, Joe Perches wrote:
> On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
>> These macros emit continuation messages with explicit levels.
>> In case the continuation is logged separately from the original message
>> it will retain its level instead of falling back to KERN_DEFAULT.
>> 
>> This remedies the issue that logs filtered by level contain stray
>> continuation messages without context.
>> 
>> Suggested-by: Petr Mladek <pmladek@suse.com>
>> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
>> ---
>>  include/linux/printk.h | 23 +++++++++++++++++++++++
>>  1 file changed, 23 insertions(+)
>> 
>> diff --git a/include/linux/printk.h b/include/linux/printk.h
>> index 8c81806c2e99..8f564c38f121 100644
>> --- a/include/linux/printk.h
>> +++ b/include/linux/printk.h
>> @@ -537,6 +537,8 @@ struct pi_entry {
>>   * This macro expands to a printk with KERN_CONT loglevel. It should only be
>>   * used when continuing a log message with no newline ('\n') enclosed. Otherwise
>>   * it defaults back to KERN_DEFAULT loglevel.
>> + *
>> + * Use the dedicated pr_<level>_cont() macros instead.
>>   */
>>  #define pr_cont(fmt, ...) \
>>  	printk(KERN_CONT fmt, ##__VA_ARGS__)
>> @@ -701,6 +703,27 @@ do {									\
>>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>  #endif
>>  
>> +/*
>> + * Print a continuation message with level. In case the continuation is split
>> + * from the main message it preserves the level.
>> + */
>> +
>> +#define pr_emerg_cont(fmt, ...)					\
>> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> 
> Aren't this rather backwards?
> KERN_CONT KERN_<LEVEL> seems to make more sense to me.

If nobody else disagrees I'll do this for v3.

>> +#define pr_alert_cont(fmt, ...)					\
>> +	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_crit_cont(fmt, ...)					\
>> +	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_err_cont(fmt, ...)					\
>> +	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_warn_cont(fmt, ...)					\
>> +	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_notice_cont(fmt, ...)					\
>> +	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_info_cont(fmt, ...)					\
>> +	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
>> +
>>  extern const struct file_operations kmsg_fops;
>>  
>>  enum {
> 

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

[Thomas Weißschuh]

On 2022-11-25 11:53-0800, Joe Perches wrote:
> On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
>> Many of the printk messages emitted during suspend and resume are
>> emitted in fragments using pr_cont()/KERN_CONT.
>> 
>> As during suspend and resume a lot of operations are happing in the
>> kernel the chances are high that the fragments are interspersed with
>> unrelated messages.
>> 
>> In this case if no explicit level is specified for the fragments the
>> standard level is applied, which by default is KERN_WARNING.
>> 
>> If the user is only observing KERN_WARNING and *not* KERN_INFO messages
>> they will see incomplete message fragments.
>> 
>> By specifing the correct printk level also with the continuations this
>> mismatch can be avoided.
>> Also it reduces the amount of false-positive KERN_WARNING messages.
>> 
>> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
>> ---
>>  kernel/power/process.c | 18 +++++++++---------
>>  1 file changed, 9 insertions(+), 9 deletions(-)
>> 
>> diff --git a/kernel/power/process.c b/kernel/power/process.c
> []
>> @@ -82,7 +82,7 @@ static int try_to_freeze_tasks(bool user_only)
>>  	elapsed_msecs = ktime_to_ms(elapsed);
>>  
>>  	if (todo) {
>> -		pr_cont("\n");
>> +		pr_info_cont("\n");
> 
> I think this isn't needed because of the immediately following pr_err.

The pr_cont() itself or the conversion to pr_info_cont() is not needed?

Personally I would prefer to keep the patch as is.

If only the conversion is not needed for consistency with the rest of the file.
If the pr_cont() in general is not needed it should be changed in a dedicated
patch (by somebody who knows this code better).

>>  		pr_err("Freezing of tasks %s after %d.%03d seconds "
>>  		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
>>  		       wakeup ? "aborted" : "failed",
> 

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Petr Mladek]

On Fri 2022-11-25 21:33:40, Thomas Weißschuh wrote:
> On 2022-11-25 12:18-0800, Joe Perches wrote:
> > On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> >> These macros emit continuation messages with explicit levels.
> >> In case the continuation is logged separately from the original message
> >> it will retain its level instead of falling back to KERN_DEFAULT.
> >> 
> >> This remedies the issue that logs filtered by level contain stray
> >> continuation messages without context.
> >> 
> >> --- a/include/linux/printk.h
> >> +++ b/include/linux/printk.h
> >> @@ -701,6 +703,27 @@ do {									\
> >>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> >>  #endif
> >>  
> >> +/*
> >> + * Print a continuation message with level. In case the continuation is split
> >> + * from the main message it preserves the level.
> >> + */
> >> +
> >> +#define pr_emerg_cont(fmt, ...)					\
> >> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> > 
> > Aren't this rather backwards?
> > KERN_CONT KERN_<LEVEL> seems to make more sense to me.
> 
> If nobody else disagrees I'll do this for v3.

I slightly prefer the way how it is now. IMHO, it makes it easier
to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:

<6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... "
<6,c> kernel/power/process.c:218 thaw_processes "done.\n"
<6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
<6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
<6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
<6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... "
<6,c> kernel/power/process.c:140 freeze_processes "\n"
<6,c> kernel/power/process.c:138 freeze_processes "done."
<6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... "
<6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "

That said, I do not want to fight over it. It is hidden behind the
API. The only really visible place is the printk index.

[*] The index is available only when CONFIG_PRINTK_INDEX is enabled.

Best Regards,
Petr

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Petr Mladek]

On Fri 2022-11-25 20:09:46, Thomas Weißschuh wrote:
> These macros emit continuation messages with explicit levels.
> In case the continuation is logged separately from the original message
> it will retain its level instead of falling back to KERN_DEFAULT.
> 
> This remedies the issue that logs filtered by level contain stray
> continuation messages without context.
> 
> Suggested-by: Petr Mladek <pmladek@suse.com>
> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> ---
>  include/linux/printk.h | 23 +++++++++++++++++++++++
>  1 file changed, 23 insertions(+)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 8c81806c2e99..8f564c38f121 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -537,6 +537,8 @@ struct pi_entry {
>   * This macro expands to a printk with KERN_CONT loglevel. It should only be
>   * used when continuing a log message with no newline ('\n') enclosed. Otherwise
>   * it defaults back to KERN_DEFAULT loglevel.
> + *
> + * Use the dedicated pr_<level>_cont() macros instead.
>   */
>  #define pr_cont(fmt, ...) \
>  	printk(KERN_CONT fmt, ##__VA_ARGS__)
> @@ -701,6 +703,27 @@ do {									\
>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>  #endif
>  
> +/*
> + * Print a continuation message with level. In case the continuation is split
> + * from the main message it preserves the level.
> + */
> +
> +#define pr_emerg_cont(fmt, ...)					\
> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_alert_cont(fmt, ...)					\
> +	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_crit_cont(fmt, ...)					\
> +	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_err_cont(fmt, ...)					\
> +	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_warn_cont(fmt, ...)					\
> +	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_notice_cont(fmt, ...)					\
> +	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_info_cont(fmt, ...)					\
> +	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> +/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */

I guess that you wanted to write "pr_debug_cont".

Also I am not sure what you mean with "doesn't make sense". IMHO, it
might  make sense. But it would be hard to use and error prone
with CONFIG_DYNAMIC_DEBUG.

And more importantly, it probably would not work properly. If I get
it corretly the dynamic debug messages are printed by the wrapper:

void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
{
[...]
	vaf.fmt = fmt;
	vaf.va = &args;

	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
[...]

This clearly does not support KERN_CONT in "fmt".

I suggest to either remove the comment completely. Or write something
like:

/* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */


Best Regards,
Petr

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

On 2022-11-30 14:59+0100, Petr Mladek wrote:
> On Fri 2022-11-25 21:33:40, Thomas Weißschuh wrote:
>> On 2022-11-25 12:18-0800, Joe Perches wrote:
>>> On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
>>>> These macros emit continuation messages with explicit levels.
>>>> In case the continuation is logged separately from the original message
>>>> it will retain its level instead of falling back to KERN_DEFAULT.
>>>> 
>>>> This remedies the issue that logs filtered by level contain stray
>>>> continuation messages without context.
>>>> 
>>>> --- a/include/linux/printk.h
>>>> +++ b/include/linux/printk.h
>>>> @@ -701,6 +703,27 @@ do {									\
>>>>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>>>  #endif
>>>>  
>>>> +/*
>>>> + * Print a continuation message with level. In case the continuation is split
>>>> + * from the main message it preserves the level.
>>>> + */
>>>> +
>>>> +#define pr_emerg_cont(fmt, ...)					\
>>>> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>>> 
>>> Aren't this rather backwards?
>>> KERN_CONT KERN_<LEVEL> seems to make more sense to me.
>> 
>> If nobody else disagrees I'll do this for v3.
> 
> I slightly prefer the way how it is now. IMHO, it makes it easier
> to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:
> 
> <6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... "
> <6,c> kernel/power/process.c:218 thaw_processes "done.\n"
> <6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
> <6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
> <6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
> <6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... "
> <6,c> kernel/power/process.c:140 freeze_processes "\n"
> <6,c> kernel/power/process.c:138 freeze_processes "done."
> <6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... "
> <6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "

I did not test it (will do so later) but it seems to me that the code in
kernel/printk/index.c should do this correctly in either case. At least it
tries to:

if (flags & LOG_CONT) {
	/*
	 * LOGLEVEL_DEFAULT here means "use the same level as the
	 * message we're continuing from", not the default message
	 * loglevel, so don't display it as such.
	 */
	if (level == LOGLEVEL_DEFAULT)
		seq_puts(s, "<c>");
		else
		seq_printf(s, "<%d,c>", level);
	} else
		seq_printf(s, "<%d>", level);
	}
}

I'll try to validate it.

If it doesn't work it may make more sense to fix the index file generation.
What do you think

> That said, I do not want to fight over it. It is hidden behind the
> API. The only really visible place is the printk index.
> 
> [*] The index is available only when CONFIG_PRINTK_INDEX is enabled.
> 
> Best Regards,
> Petr

Thomas

Re: [PATCH v2 2/3] checkpatch: handle new pr_<level>_cont macros

[Petr Mladek]

On Fri 2022-11-25 12:17:05, Joe Perches wrote:
> On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> > These new macros from include/linux/printk.h replace the usage of plain
> > pr_cont().
> []
> > --- a/scripts/checkpatch.pl
> > +++ b/scripts/checkpatch.pl
> > @@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
> > +# check for logging continuations without explicit level
> > +		if ($line =~ /\bpr_cont\s*\(/) {
> > +			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
> > +			     "Avoid logging continuation without level\n" . $herecurr);
> > +		}
> > +
> 
> Not so sure about this one.
> 
> I think relatively few situations are going to require interleaving avoidance.

Well, the problem is generic and any pr_cont() is affected except for
NMI context on single CPU system.

I though about a generic solution. We could store the last used printk
log level per-process and per-CPU context. But it does not solve
the situation when an unrelated printk() is printed by a nested
function.

It is exactly the case with try_to_freeze_tasks() in the 3rd patch.
Simplified code:

int freeze_processes(void)
{
	pr_info("Freezing user space processes ... ");
	try_to_freeze_tasks(true);
	pr_info_cont("done.");
}

, where

static int try_to_freeze_tasks(bool user_only)
{
[...]
	if (todo) {
		pr_err("Freezing of tasks %s after %d.%03d seconds "
[...]
}


I would personally add this check into checkpatch.pl. It might help
to make people aware about that pr_cont() is just the best effort.

Best Regards,
Petr

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

On 2022-11-30 15:23+0100, Petr Mladek wrote:
> On Fri 2022-11-25 20:09:46, Thomas Weißschuh wrote:
>> These macros emit continuation messages with explicit levels.
>> In case the continuation is logged separately from the original message
>> it will retain its level instead of falling back to KERN_DEFAULT.
>> 
>> This remedies the issue that logs filtered by level contain stray
>> continuation messages without context.
>> 
>> Suggested-by: Petr Mladek <pmladek@suse.com>
>> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
>> ---
>>  include/linux/printk.h | 23 +++++++++++++++++++++++
>>  1 file changed, 23 insertions(+)
>> 
>> diff --git a/include/linux/printk.h b/include/linux/printk.h
>> index 8c81806c2e99..8f564c38f121 100644
>> --- a/include/linux/printk.h
>> +++ b/include/linux/printk.h
>> @@ -537,6 +537,8 @@ struct pi_entry {
>>   * This macro expands to a printk with KERN_CONT loglevel. It should only be
>>   * used when continuing a log message with no newline ('\n') enclosed. Otherwise
>>   * it defaults back to KERN_DEFAULT loglevel.
>> + *
>> + * Use the dedicated pr_<level>_cont() macros instead.
>>   */
>>  #define pr_cont(fmt, ...) \
>>  	printk(KERN_CONT fmt, ##__VA_ARGS__)
>> @@ -701,6 +703,27 @@ do {									\
>>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>>  #endif
>>  
>> +/*
>> + * Print a continuation message with level. In case the continuation is split
>> + * from the main message it preserves the level.
>> + */
>> +
>> +#define pr_emerg_cont(fmt, ...)					\
>> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_alert_cont(fmt, ...)					\
>> +	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_crit_cont(fmt, ...)					\
>> +	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_err_cont(fmt, ...)					\
>> +	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_warn_cont(fmt, ...)					\
>> +	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_notice_cont(fmt, ...)					\
>> +	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +#define pr_info_cont(fmt, ...)					\
>> +	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
>> +/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
> 
> I guess that you wanted to write "pr_debug_cont".

Indeed.

> Also I am not sure what you mean with "doesn't make sense". IMHO, it
> might  make sense. But it would be hard to use and error prone
> with CONFIG_DYNAMIC_DEBUG.
> 
> And more importantly, it probably would not work properly. If I get
> it corretly the dynamic debug messages are printed by the wrapper:
> 
> void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
> {
> [...]
> 	vaf.fmt = fmt;
> 	vaf.va = &args;
> 
> 	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
> [...]
> 
> This clearly does not support KERN_CONT in "fmt".

Good point.

My doubt was more that it would force users to know which message
continuations belong together and always enable all of them together with
dynamic debug.
Which would be very errorprone and annoying to use.

But if it doesn't work at all that's an even stronger point.

> I suggest to either remove the comment completely. Or write something
> like:
> 
> /* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */

What about:

/* no pr_debug_cont(), it's errorprone to use
 * and can't be supported easily with CONFIG_DYNAMIC_DEBUG */

Thomas

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

[Petr Mladek]

On Fri 2022-11-25 21:41:55, Thomas Weißschuh wrote:
> On 2022-11-25 11:53-0800, Joe Perches wrote:
> > On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> >> Many of the printk messages emitted during suspend and resume are
> >> emitted in fragments using pr_cont()/KERN_CONT.
> >> 
> >> As during suspend and resume a lot of operations are happing in the
> >> kernel the chances are high that the fragments are interspersed with
> >> unrelated messages.
> >> 
> >> In this case if no explicit level is specified for the fragments the
> >> standard level is applied, which by default is KERN_WARNING.
> >> 
> >> If the user is only observing KERN_WARNING and *not* KERN_INFO messages
> >> they will see incomplete message fragments.
> >> 
> >> By specifing the correct printk level also with the continuations this
> >> mismatch can be avoided.
> >> Also it reduces the amount of false-positive KERN_WARNING messages.
> >> 
> >> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> >> ---
> >>  kernel/power/process.c | 18 +++++++++---------
> >>  1 file changed, 9 insertions(+), 9 deletions(-)
> >> 
> >> diff --git a/kernel/power/process.c b/kernel/power/process.c
> > []
> >> @@ -82,7 +82,7 @@ static int try_to_freeze_tasks(bool user_only)
> >>  	elapsed_msecs = ktime_to_ms(elapsed);
> >>  
> >>  	if (todo) {
> >> -		pr_cont("\n");
> >> +		pr_info_cont("\n");
> > 
> > I think this isn't needed because of the immediately following pr_err.

Great catch.


> The pr_cont() itself or the conversion to pr_info_cont() is not needed?

The pr_cont() was needed before the commit 4bcc595ccd80decb42450
("printk: reinstate KERN_CONT for printing continuation lines").

Before this commit, lines were appended even without KERN_CONT
when the previous line did not end with "\n".

The above commit caused that only lines with KERN_CONT will be
appended.

We have the code:

		pr_cont("\n");
		pr_err("Freezing of tasks %s after %d.%03d seconds "

The pr_cont() is not needed here because pr_err() does not have
KERN_CONT. It will always start on a new line.

> Personally I would prefer to keep the patch as is.
> 
> If only the conversion is not needed for consistency with the rest of the file.
> If the pr_cont() in general is not needed it should be changed in a dedicated
> patch (by somebody who knows this code better).

I agree that it should be removed in a separate patch. The commit
message should mention the commit that modified the KERN_CONT
handling.

Best Regards,
Petr

Re: [PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

[Rafael J. Wysocki]

On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
>
> This series adds new printk wrapper macros pr_<level>_cont().
> These create continuation messages with an explicit level.
>
> Explicit levels are useful when a continuation message is split from its main
> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
> which can lead to stray partial log messages when filtering by level.
>
> Also checkpatch is modified to recommend the new macros over plain pr_cont().
>
> Lastly the new macros are used in kernel/power/process.c as this file uses
> continuation messages during system suspend-resume which creates a high
> likelyhood of interspersed messages.

Well, if process.c is the only problematic piece of code in this
respect, I'm not sure if adding the new infrastructure for its benefit
alone is worth it, because it can very well do without pr_cont() at
all.

Please see the patch below (compiled only, sorry for gmail-induced
white space damage).  I'll submit it properly later if it works for
everyone.

---
 kernel/power/process.c |   25 ++++++++++---------------
 1 file changed, 10 insertions(+), 15 deletions(-)

Index: linux-pm/kernel/power/process.c
===================================================================
--- linux-pm.orig/kernel/power/process.c
+++ linux-pm/kernel/power/process.c
@@ -27,6 +27,8 @@ unsigned int __read_mostly freeze_timeou

 static int try_to_freeze_tasks(bool user_only)
 {
+    const char *what = user_only ? "user space processes" :
+                    "remaining freezable tasks";
     struct task_struct *g, *p;
     unsigned long end_time;
     unsigned int todo;
@@ -36,6 +38,8 @@ static int try_to_freeze_tasks(bool user
     bool wakeup = false;
     int sleep_usecs = USEC_PER_MSEC;

+    pr_info("Freezing %s\n", what);
+
     start = ktime_get_boottime();

     end_time = jiffies + msecs_to_jiffies(freeze_timeout_msecs);
@@ -82,9 +86,8 @@ static int try_to_freeze_tasks(bool user
     elapsed_msecs = ktime_to_ms(elapsed);

     if (todo) {
-        pr_cont("\n");
-        pr_err("Freezing of tasks %s after %d.%03d seconds "
-               "(%d tasks refusing to freeze, wq_busy=%d):\n",
+        pr_err("Freezing %s %s after %d.%03d seconds "
+               "(%d tasks refusing to freeze, wq_busy=%d):\n", what,
                wakeup ? "aborted" : "failed",
                elapsed_msecs / 1000, elapsed_msecs % 1000,
                todo - wq_busy, wq_busy);
@@ -101,8 +104,8 @@ static int try_to_freeze_tasks(bool user
             read_unlock(&tasklist_lock);
         }
     } else {
-        pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
-            elapsed_msecs % 1000);
+        pr_info("Freezing %s completed (elapsed %d.%03d seconds)\n",
+            what, elapsed_msecs / 1000, elapsed_msecs % 1000);
     }

     return todo ? -EBUSY : 0;
@@ -130,14 +133,11 @@ int freeze_processes(void)
         static_branch_inc(&freezer_active);

     pm_wakeup_clear(0);
-    pr_info("Freezing user space processes ... ");
     pm_freezing = true;
     error = try_to_freeze_tasks(true);
-    if (!error) {
+    if (!error)
         __usermodehelper_set_disable_depth(UMH_DISABLED);
-        pr_cont("done.");
-    }
-    pr_cont("\n");
+
     BUG_ON(in_atomic());

     /*
@@ -166,14 +166,9 @@ int freeze_kernel_threads(void)
 {
     int error;

-    pr_info("Freezing remaining freezable tasks ... ");
-
     pm_nosig_freezing = true;
     error = try_to_freeze_tasks(false);
-    if (!error)
-        pr_cont("done.");

-    pr_cont("\n");
     BUG_ON(in_atomic());

     if (error)

Re: [PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

[Thomas Weißschuh]

On 2022-11-30 18:57+0100, Rafael J. Wysocki wrote:
> On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
>>
>> This series adds new printk wrapper macros pr_<level>_cont().
>> These create continuation messages with an explicit level.
>>
>> Explicit levels are useful when a continuation message is split from its main
>> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
>> which can lead to stray partial log messages when filtering by level.
>>
>> Also checkpatch is modified to recommend the new macros over plain pr_cont().
>>
>> Lastly the new macros are used in kernel/power/process.c as this file uses
>> continuation messages during system suspend-resume which creates a high
>> likelyhood of interspersed messages.
> 
> Well, if process.c is the only problematic piece of code in this
> respect, I'm not sure if adding the new infrastructure for its benefit
> alone is worth it, because it can very well do without pr_cont() at
> all.

In general all usages of pr_cont() are problematic.
Any continuation can be split from its main message, leading to misleved
continuations.
process.c is just the one that I noticed reliably hitting this problem on my
machine.

> Please see the patch below (compiled only, sorry for gmail-induced
> white space damage).  I'll submit it properly later if it works for
> everyone.

The patch looks fine to me and getting rid of usages of pr_cont() seems to be
the better aproach where it is possible.

Petr: do you still want me to submit the new macros even if it is not used
directly anymore?

> ---
>  kernel/power/process.c |   25 ++++++++++---------------
>  1 file changed, 10 insertions(+), 15 deletions(-)
> 
> Index: linux-pm/kernel/power/process.c
> ===================================================================
> --- linux-pm.orig/kernel/power/process.c
> +++ linux-pm/kernel/power/process.c
> @@ -27,6 +27,8 @@ unsigned int __read_mostly freeze_timeou
> 
>  static int try_to_freeze_tasks(bool user_only)
>  {
> +    const char *what = user_only ? "user space processes" :
> +                    "remaining freezable tasks";
>      struct task_struct *g, *p;
>      unsigned long end_time;
>      unsigned int todo;
> @@ -36,6 +38,8 @@ static int try_to_freeze_tasks(bool user
>      bool wakeup = false;
>      int sleep_usecs = USEC_PER_MSEC;
> 
> +    pr_info("Freezing %s\n", what);
> +
>      start = ktime_get_boottime();
> 
>      end_time = jiffies + msecs_to_jiffies(freeze_timeout_msecs);
> @@ -82,9 +86,8 @@ static int try_to_freeze_tasks(bool user
>      elapsed_msecs = ktime_to_ms(elapsed);
> 
>      if (todo) {
> -        pr_cont("\n");
> -        pr_err("Freezing of tasks %s after %d.%03d seconds "
> -               "(%d tasks refusing to freeze, wq_busy=%d):\n",
> +        pr_err("Freezing %s %s after %d.%03d seconds "
> +               "(%d tasks refusing to freeze, wq_busy=%d):\n", what,
>                 wakeup ? "aborted" : "failed",
>                 elapsed_msecs / 1000, elapsed_msecs % 1000,
>                 todo - wq_busy, wq_busy);
> @@ -101,8 +104,8 @@ static int try_to_freeze_tasks(bool user
>              read_unlock(&tasklist_lock);
>          }
>      } else {
> -        pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
> -            elapsed_msecs % 1000);
> +        pr_info("Freezing %s completed (elapsed %d.%03d seconds)\n",
> +            what, elapsed_msecs / 1000, elapsed_msecs % 1000);
>      }
> 
>      return todo ? -EBUSY : 0;
> @@ -130,14 +133,11 @@ int freeze_processes(void)
>          static_branch_inc(&freezer_active);
> 
>      pm_wakeup_clear(0);
> -    pr_info("Freezing user space processes ... ");
>      pm_freezing = true;
>      error = try_to_freeze_tasks(true);
> -    if (!error) {
> +    if (!error)
>          __usermodehelper_set_disable_depth(UMH_DISABLED);
> -        pr_cont("done.");
> -    }
> -    pr_cont("\n");
> +
>      BUG_ON(in_atomic());
> 
>      /*
> @@ -166,14 +166,9 @@ int freeze_kernel_threads(void)
>  {
>      int error;
> 
> -    pr_info("Freezing remaining freezable tasks ... ");
> -
>      pm_nosig_freezing = true;
>      error = try_to_freeze_tasks(false);
> -    if (!error)
> -        pr_cont("done.");
> 
> -    pr_cont("\n");
>      BUG_ON(in_atomic());
> 
>      if (error)

Re: [PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

[Petr Mladek]

On Thu 2022-12-01 00:37:15, Thomas Weißschuh wrote:
> On 2022-11-30 18:57+0100, Rafael J. Wysocki wrote:
> > On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
> >>
> >> This series adds new printk wrapper macros pr_<level>_cont().
> >> These create continuation messages with an explicit level.
> >>
> >> Explicit levels are useful when a continuation message is split from its main
> >> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
> >> which can lead to stray partial log messages when filtering by level.
> >>
> >> Also checkpatch is modified to recommend the new macros over plain pr_cont().
> >>
> >> Lastly the new macros are used in kernel/power/process.c as this file uses
> >> continuation messages during system suspend-resume which creates a high
> >> likelyhood of interspersed messages.
> > 
> > Well, if process.c is the only problematic piece of code in this
> > respect, I'm not sure if adding the new infrastructure for its benefit
> > alone is worth it, because it can very well do without pr_cont() at
> > all.
> 
> In general all usages of pr_cont() are problematic.
> Any continuation can be split from its main message, leading to misleved
> continuations.

In most cases this happens "only" when a message from another CPU
or interrupt context is printed in parallel.

> process.c is just the one that I noticed reliably hitting this problem on my
> machine.

The situation in process.c was even worse. The error message was
printed in the middle of the to-be-continued message. As a result,
the loglevel of the pr_cont() part was always (reliably) broken
when the error message was printed.


> > Please see the patch below (compiled only, sorry for gmail-induced
> > white space damage).  I'll submit it properly later if it works for
> > everyone.
> 
> The patch looks fine to me and getting rid of usages of pr_cont() seems to be
> the better aproach where it is possible.

I agree. It is always better to avoid pr_cont() when possible.

> Petr: do you still want me to submit the new macros even if it is not used
> directly anymore?

Good question. In general, new API should not be added if there is
no user. So, I would prefer to do not add the API if the problem
will be fixed without it.

Best Regards,
Petr

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Petr Mladek]

On Wed 2022-11-30 15:50:55, Thomas Weißschuh wrote:
> On 2022-11-30 14:59+0100, Petr Mladek wrote:
> > On Fri 2022-11-25 21:33:40, Thomas Weißschuh wrote:
> >> On 2022-11-25 12:18-0800, Joe Perches wrote:
> >>> On Fri, 2022-11-25 at 20:09 +0100, Thomas Weißschuh wrote:
> >>>> These macros emit continuation messages with explicit levels.
> >>>> In case the continuation is logged separately from the original message
> >>>> it will retain its level instead of falling back to KERN_DEFAULT.
> >>>> 
> >>>> This remedies the issue that logs filtered by level contain stray
> >>>> continuation messages without context.
> >>>> 
> >>>> --- a/include/linux/printk.h
> >>>> +++ b/include/linux/printk.h
> >>>> @@ -701,6 +703,27 @@ do {									\
> >>>>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> >>>>  #endif
> >>>>  
> >>>> +/*
> >>>> + * Print a continuation message with level. In case the continuation is split
> >>>> + * from the main message it preserves the level.
> >>>> + */
> >>>> +
> >>>> +#define pr_emerg_cont(fmt, ...)					\
> >>>> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >>> 
> >>> Aren't this rather backwards?
> >>> KERN_CONT KERN_<LEVEL> seems to make more sense to me.
> >> 
> >> If nobody else disagrees I'll do this for v3.
> > 
> > I slightly prefer the way how it is now. IMHO, it makes it easier
> > to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:
> > 
> > <6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... "
> > <6,c> kernel/power/process.c:218 thaw_processes "done.\n"
> > <6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
> > <6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
> > <6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
> > <6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... "
> > <6,c> kernel/power/process.c:140 freeze_processes "\n"
> > <6,c> kernel/power/process.c:138 freeze_processes "done."
> > <6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... "
> > <6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "
> 
> I did not test it (will do so later) but it seems to me that the code in
> kernel/printk/index.c should do this correctly in either case. At least it
> tries to:
> 
> if (flags & LOG_CONT) {
> 	/*
> 	 * LOGLEVEL_DEFAULT here means "use the same level as the
> 	 * message we're continuing from", not the default message
> 	 * loglevel, so don't display it as such.
> 	 */
> 	if (level == LOGLEVEL_DEFAULT)
> 		seq_puts(s, "<c>");
> 		else
> 		seq_printf(s, "<%d,c>", level);
> 	} else
> 		seq_printf(s, "<%d>", level);
> 	}

Great. It makes the index consistent. I should have checked the code ;-)

I do not mind then about the ordering in the macro definitions.
It really seems to be only an implementation detail.

Best Regards,
Petr

Re: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont()

[Petr Mladek]

On Wed 2022-11-30 15:56:33, Thomas Weißschuh wrote:
> On 2022-11-30 15:23+0100, Petr Mladek wrote:
> > On Fri 2022-11-25 20:09:46, Thomas Weißschuh wrote:
> >> These macros emit continuation messages with explicit levels.
> >> In case the continuation is logged separately from the original message
> >> it will retain its level instead of falling back to KERN_DEFAULT.
> >> 
> >> This remedies the issue that logs filtered by level contain stray
> >> continuation messages without context.
> >> 
> >> Suggested-by: Petr Mladek <pmladek@suse.com>
> >> Signed-off-by: Thomas Weißschuh <linux@weissschuh.net>
> >> ---
> >>  include/linux/printk.h | 23 +++++++++++++++++++++++
> >>  1 file changed, 23 insertions(+)
> >> 
> >> diff --git a/include/linux/printk.h b/include/linux/printk.h
> >> index 8c81806c2e99..8f564c38f121 100644
> >> --- a/include/linux/printk.h
> >> +++ b/include/linux/printk.h
> >> @@ -537,6 +537,8 @@ struct pi_entry {
> >>   * This macro expands to a printk with KERN_CONT loglevel. It should only be
> >>   * used when continuing a log message with no newline ('\n') enclosed. Otherwise
> >>   * it defaults back to KERN_DEFAULT loglevel.
> >> + *
> >> + * Use the dedicated pr_<level>_cont() macros instead.
> >>   */
> >>  #define pr_cont(fmt, ...) \
> >>  	printk(KERN_CONT fmt, ##__VA_ARGS__)
> >> @@ -701,6 +703,27 @@ do {									\
> >>  	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> >>  #endif
> >>  
> >> +/*
> >> + * Print a continuation message with level. In case the continuation is split
> >> + * from the main message it preserves the level.
> >> + */
> >> +
> >> +#define pr_emerg_cont(fmt, ...)					\
> >> +	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_alert_cont(fmt, ...)					\
> >> +	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_crit_cont(fmt, ...)					\
> >> +	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_err_cont(fmt, ...)					\
> >> +	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_warn_cont(fmt, ...)					\
> >> +	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_notice_cont(fmt, ...)					\
> >> +	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +#define pr_info_cont(fmt, ...)					\
> >> +	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
> >> +/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
> > 
> > I guess that you wanted to write "pr_debug_cont".
> 
> Indeed.
> 
> > Also I am not sure what you mean with "doesn't make sense". IMHO, it
> > might  make sense. But it would be hard to use and error prone
> > with CONFIG_DYNAMIC_DEBUG.
> > 
> > And more importantly, it probably would not work properly. If I get
> > it corretly the dynamic debug messages are printed by the wrapper:
> > 
> > void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...)
> > {
> > [...]
> > 	vaf.fmt = fmt;
> > 	vaf.va = &args;
> > 
> > 	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);
> > [...]
> > 
> > This clearly does not support KERN_CONT in "fmt".
> 
> Good point.
> 
> My doubt was more that it would force users to know which message
> continuations belong together and always enable all of them together with
> dynamic debug.
> Which would be very errorprone and annoying to use.

Yes. This is what I meant with "hard to use" but I was not clear
enough :-)

> 
> But if it doesn't work at all that's an even stronger point.
> 
> > I suggest to either remove the comment completely. Or write something
> > like:
> > 
> > /* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */
> 
> What about:
> 
> /* no pr_debug_cont(), it's errorprone to use
>  * and can't be supported easily with CONFIG_DYNAMIC_DEBUG */

Sounds good to me.

Best Regards,
Petr

PS: Heh, I just realized that we actually abandoned these changes because
    the continuous lines in kernel/power/process.c are going to be
    removed. (/me doing too many things in parallel).

    Anyway, it is possible that someone would take this patches to fix
    another continuous lines in the future.