linux-kernel - Re: [PATCH v2 0/3] printk: introduce new macros pr_<level>

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Thu, 1 Dec 2022 00:37:15 +0100
From:   Thomas Weißschuh <linux@...ssschuh.net>
To:     "Rafael J. Wysocki" <rafael@...nel.org>,
        Petr Mladek <pmladek@...e.com>
Cc:     Pavel Machek <pavel@....cz>, Len Brown <len.brown@...el.com>,
        linux-pm@...r.kernel.org,
        Sergey Senozhatsky <senozhatsky@...omium.org>,
        Andy Whitcroft <apw@...onical.com>,
        Joe Perches <joe@...ches.com>, linux-kernel@...r.kernel.org,
        Steven Rostedt <rostedt@...dmis.org>,
        Dwaipayan Ray <dwaipayanray1@...il.com>,
        Lukas Bulwahn <lukas.bulwahn@...il.com>
Subject: Re: [PATCH v2 0/3] printk: introduce new macros pr_<level>_cont()

On 2022-11-30 18:57+0100, Rafael J. Wysocki wrote:
> On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@...ssschuh.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)