diff mbox series

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

Message ID	20221125190948.2062-2-linux@weissschuh.net
State	New
Headers	Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20; From: =?utf-8?q?Thomas_Wei=C3=9Fschuh?= <linux@weissschuh.net> To: "Rafael J. Wysocki" <rafael@kernel.org>, Pavel Machek <pavel@ucw.cz>, Len Brown <len.brown@intel.com>, linux-pm@vger.kernel.org, Petr Mladek <pmladek@suse.com>, Sergey Senozhatsky <senozhatsky@chromium.org>, Andy Whitcroft <apw@canonical.com>, Joe Perches <joe@perches.com> Cc: =?utf-8?q?Thomas_Wei=C3=9Fschuh?= <linux@weissschuh.net>, linux-kernel@vger.kernel.org, Steven Rostedt <rostedt@goodmis.org>, Dwaipayan Ray <dwaipayanray1@gmail.com>, Lukas Bulwahn <lukas.bulwahn@gmail.com> Subject: [PATCH v2 1/3] printk: introduce new macros pr_<level>_cont() Date: Fri, 25 Nov 2022 20:09:46 +0100 Message-Id: <20221125190948.2062-2-linux@weissschuh.net> In-Reply-To: <20221125190948.2062-1-linux@weissschuh.net> References: <20221125190948.2062-1-linux@weissschuh.net> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Precedence: bulk
Series	printk: introduce new macros pr_<level>_cont() \| [v2,0/3] printk: introduce new macros pr_<level>_cont() [v2,1/3] printk: introduce new macros pr_<level>_cont() [v2,2/3] checkpatch: handle new pr_<level>_cont macros [v2,3/3] power: process: use explicit levels for printk continuations

Commit Message

Thomas Weißschuh Nov. 25, 2022, 7:09 p.m. UTC

  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(+)

Comments

Joe Perches Nov. 25, 2022, 8:18 p.m. UTC | #1

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 {

Thomas Weißschuh Nov. 25, 2022, 8:33 p.m. UTC | #2

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 {
>

Petr Mladek Nov. 30, 2022, 1:59 p.m. UTC | #3

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

Petr Mladek Nov. 30, 2022, 2:23 p.m. UTC | #4

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

Thomas Weißschuh Nov. 30, 2022, 2:50 p.m. UTC | #5

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

Thomas Weißschuh Nov. 30, 2022, 2:56 p.m. UTC | #6

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

Petr Mladek Dec. 2, 2022, 12:21 p.m. UTC | #7

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

Petr Mladek Dec. 2, 2022, 12:27 p.m. UTC | #8

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.

diff mbox series

Patch

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 {