printk: console: Allow each console to have its own loglevel

[Once the goals of this patch are generally agreed upon, it can be split
out further with more detailed changelogs if desired.]

Consoles can have vastly different latencies and throughputs. For example, writing a message to the serial console can take on the order
of tens of milliseconds to get the UART to successfully write a message.
While this might be fine for a single, one-off message, this can cause
significant application-level stalls in situations where the kernel writes large amounts of information to the console.

Quoted 4 lines · Chris Down

[Once the goals of this patch are generally agreed upon, it can be split
out further with more detailed changelogs if desired.]

Quoted 10 lines

Consoles can have vastly different latencies and throughputs. For example, writing a message to the serial console can take on the order
of tens of milliseconds to get the UART to successfully write a message.
While this might be fine for a single, one-off message, this can cause
significant application-level stalls in situations where the kernel writes large amounts of information to the console.

It's more than just application-level stalls. I have seen some cases of the kernel spending so much time logging things to serial console that it thinks it locked up, and panics as a result of how slow the serial console is.

Adding insult to injury, because the log level is sytem wide, we only see _some_ of the hints of why the kernel started spewing like that in the netcons logs.

If we print all the information, we will have more hosts panic because we spent too much time in the serial console code.

If we print less information, we won't find out some of the other things causing issues on systems.

Having per console log levels will allow us to avoid the serial console issues, and gather all the info we need on other stuff happening on the system.

The problem is clear. But the big part of the problem is that printk() tries to show the messages on all consoles immediately.

I wonder how much the per-console loglevel would be needed when the console handling is offloaded to per-console kthreads, see
https://lore.kernel.org/all/[email protected]/
It causes that printk() should "never" block and each console might run on its own speed.

It still might be useful from some reasons:

+ Serial consoles might miss messages because the old messages are over-written before they reach the console. It might be solved by big enough buffer.

+ printk() still tries to show the messages immediately in some critical situations, for example, early boot, watchdog warnings, suspend, reboot, OOps, panic(). The slow consoles might still cause stalls and put the system into its knees.

+ People might need to explicitly disable the kthreads, for example, when debugging a situation when kthreads are not scheduled.

PS: I am sorry for the late response. I am still snowed under many tasks. The printk kthreads are complicated and need a lot of attention. Plus there was a sickness, vacations, and other tasks.

[Once the goals of this patch are generally agreed upon, it can be split out further with more detailed changelogs if desired.]

Consoles can have vastly different latencies and throughputs. For example, writing a message to the serial console can take on the order of tens of milliseconds to get the UART to successfully write a message. While this might be fine for a single, one-off message, this can cause significant application-level stalls in situations where the kernel writes large amounts of information to the console.

This means that while you might want to send at least INFO level messages to (for example) netconsole, which is relatively fast, you may only want to send at least WARN level messages to the serial console. Such an implementation would permit debugging using the serial console in cases that netconsole doesn't receive messages during particularly bad system issues, while still keeping the noise low enough to avoid inducing latency in userspace applications. This patch adds such an interface, extending the existing console loglevel controls to allow each console to have its own loglevel.

One can't just disable the serial console, because one may actually need it in situations where the machine is in a bad enough state that nothing is received on netconsole. One also can't just bump the loglevel at runtime after the issue, because usually the machine is already so wedged by this point that it isn't responsive to such requests.

In terms of technical implementation, this patch embeds a device pointer in the console struct, and registers each console using it so we can expose attributes in sysfs.

The lifecycle of this classdev looks like this on registration:

    register_console(con)/printk_late_init()
      console_register_device(con)
        device_initialize(con->classdev) # refcount++
        device_add(con->classdev)        # refcount++

At stable state, the refcount is two.

Console unregistration looks like this:

    [con->classdev refcount drops to 0]
        console_classdev_release(con->classdev)
            kfree(con->classdev)

    unregister_console(con)
        device_unregister(con->classdev)
            device_del(con->classdev) # refcount--
                device_remove_class_symlinks()
                    kernfs_remove_by_name_ns()
                        kernfs_drain()
                            kernfs_drain_open_files() # wait for close()
            put_device(con->classdev) # refcount--

We also deprecate the kernel.printk sysctl as it doesn't know about per-console loglevels, and is generally pretty confusing.

For information on the precedence and application of the new controls, see Documentation/ABI/testing/sysfs-class-console and Documentation/admin-guide/per-console-loglevel.rst.

Signed-off-by Chris Down <[email protected]>

---
 Documentation/ABI/testing/sysfs-class-console |  50 +++
 .../admin-guide/kernel-parameters.txt         |  18 +-
 .../admin-guide/per-console-loglevel.rst      | 116 ++++++
 Documentation/admin-guide/serial-console.rst  |  17 +-
 Documentation/core-api/printk-basics.rst      |  34 +-
 Documentation/networking/netconsole.rst       |  17 +
 MAINTAINERS                                   |   3 +
 include/linux/console.h                       |  23 ++

 include/linux/kern_levels.h                   |   2 +
 init/main.c                                   |   2 +-
 kernel/printk/console_cmdline.h               |   2 +
 kernel/printk/printk.c                        | 352 ++++++++++++++++--
 kernel/printk/sysctl.c                        |  95 ++++-
 13 files changed, 680 insertions(+), 51 deletions(-)
 create mode 100644 Documentation/ABI/testing/sysfs-class-console
 create mode 100644 Documentation/admin-guide/per-console-loglevel.rst

You forgot what changed from v1 :(

Anyway, the driver model interaction looks good to me, nice work, no objections at all.

[Once the goals of this patch are generally agreed upon, it can be split out further with more detailed changelogs if desired.]

Consoles can have vastly different latencies and throughputs. For example, writing a message to the serial console can take on the order of tens of milliseconds to get the UART to successfully write a message. While this might be fine for a single, one-off message, this can cause significant application-level stalls in situations where the kernel writes large amounts of information to the console.

This means that while you might want to send at least INFO level messages to (for example) netconsole, which is relatively fast, you may only want to send at least WARN level messages to the serial console. Such an implementation would permit debugging using the serial console in cases that netconsole doesn't receive messages during particularly bad system issues, while still keeping the noise low enough to avoid inducing latency in userspace applications. This patch adds such an interface, extending the existing console loglevel controls to allow each console to have its own loglevel.

I've had to do something similar for my systems, to allow all messages to always be logged to the pstore console while still allowing the UART console loglevel to be adjusted. I've been carrying the following pstore-specific hack for a while now. This patch set looks like it will be able to solve the problem in a generic way.

Documentation/admin-guide/per-console-loglevel.rst new file +4 -0

@@ -0,0 +1,116 @@
+.. SPDX-License-Identifier: GPL-2.0
+
+.. _per_console_loglevel:
+

Documentation/admin-guide/per-console-loglevel.rst new file +13 -0

+application-level stalls in situations where the kernel writes large amounts of
+information to the console.
+
+This means that while you might want to send at least INFO level messages to
+(for example) netconsole, which is relatively fast, you may only want to send
+at least WARN level messages to the serial console. This permits debugging
+using the serial console in cases that netconsole doesn't receive messages
+during particularly bad system issues, while still keeping the noise low enough
+to avoid inducing latency in userspace applications.
+
+Tunables
+--------
+

Documentation/admin-guide/per-console-loglevel.rst new file +20 -0

+* ``kernel.default_message_loglevel`` sysctl: The default loglevel to send
+  messages at if they are sent with no explicit loglevel.
+
+The default value for ``kernel.default_console_loglevel`` comes from
+``CONFIG_CONSOLE_LOGLEVEL_DEFAULT``, or ``CONFIG_CONSOLE_LOGLEVEL_QUIET`` if
+``quiet`` is passed on the kernel command line.
+
+Console attributes
+~~~~~~~~~~~~~~~~~~
+
+Registered consoles are exposed at ``/sys/class/console``. For example, if you
+are using ``ttyS0``, the console backing it can be viewed at
+``/sys/class/console/ttyS/``. The following files are available:
+
+* ``effective_loglevel`` (r): The effective loglevel after considering all
+  loglevel authorities. For example, if the local loglevel is 3, but the global
+  minimum console loglevel is 5, then the value will be 5.
+* ``effective_loglevel_source`` (r): The loglevel authority which resulted in
+  the effective loglevel being set. The following values can be present:
+

The console-specific loglevel might be set by:

+ "console=device,options/loglevel" kernel parameter at boot time

Quoted 3 lines · Petr Mladek

The console-specific loglevel might be set by:

+ "console=device,options/loglevel" kernel parameter at boot time

I ask if we avoid the use of "/loglevel" and instead use a generic scheme of:

console=device,option,option,option

Of course, it would mean that the type of option would need to be specified. Something like:

console=ttyS0,115200n8,loglevel=3

The reason why I make such a request is because I would like to be able to support disabling threading for certain consoles. Something like:

console=ttyS0,115200n8,nothread

or when we have atomic consoles that we can specify that they are always used with a "sync" option:

console=ttyS0,115200n8,sync

Quoted 8 lines · John Ogness

Quoted 3 lines · Petr Mladek

The console-specific loglevel might be set by:

+ "console=device,options/loglevel" kernel parameter at boot time

I ask if we avoid the use of "/loglevel" and instead use a generic scheme of:

Quoted 6 lines

console=device,option,option,option

Of course, it would mean that the type of option would need to be specified. Something like:

console=ttyS0,115200n8,loglevel=3

I like this. It is longer but it makes the meaning very obvious.

Quoted 4 lines

Of course, it would mean that the type of option would need to be specified. Something like:

console=ttyS0,115200n8,loglevel=3

I like this. It is longer but it makes the meaning very obvious.

I just think about using ':' instead of '=' to distinguish the assignment of outer 'console' vs the inner 'loglevel' parameters.

Documentation/admin-guide/per-console-loglevel.rst line 85

Quoted 3 lines

Documentation/admin-guide/per-console-loglevel.rst new file +3 -0

+    * ``minimum``: The global minimum loglevel
+      (``kernel.minimum_console_loglevel``) is in effect. Set a higher
+      console-specific loglevel to override it.

This is confusing. It might be because I am not a native speaker. It sounds like a higher console-specific loglevel might update (override) the minimum value.

A better explanation is that it is a limit. Neither the global nor the per-console loglevel could be set below this value.

Documentation/admin-guide/per-console-loglevel.rst line 94

Quoted 9 lines

Documentation/admin-guide/per-console-loglevel.rst new file +9 -0

+    * ``forced_minimum``: The global minimum loglevel
+      (``kernel.minimum_console_loglevel``) is in effect. Even if the local
+      console-specific loglevel is higher, it is in effect because the global
+      forced loglevel (``kernel.force_console_loglevel``) is present, but is
+      below ``kernel.minimum_console_loglevel``. Write "unset" to
+      ``kernel.force_console_loglevel`` to disable the forcing, and make sure
+      ``kernel.minimum_console_loglevel`` is below the local console loglevel
+      if you want the per-console loglevel to take effect.
+      console-specific loglevel to override it.

IMHO, this makes things too complicated. A better solution is to do not allow to set any log level below this limit in the first place.

Quoted 8 lines

Documentation/admin-guide/per-console-loglevel.rst new file +7 -0

+    * ``ignore_loglevel``: ``ignore_loglevel`` was specified on the kernel
+      command line. Restart without it to use other controls.
+
+* ``enabled`` (r): Whether the console is enabled.
+* ``loglevel`` (rw): The local loglevel for this console. This will be in
+  effect if no other global control overrides it. Look at
+  ``effective_loglevel`` and ``effective_loglevel_source`` to verify that.

Documentation/admin-guide/per-console-loglevel.rst line 106

Quoted 4 lines

Documentation/admin-guide/per-console-loglevel.rst new file +4 -0

+Deprecated
+~~~~~~~~~~
+
+* ``syslog(SYSLOG_ACTION_CONSOLE_*)``: This sets

Why does it use "_*"? It looks like the entire syslog interface is obsolete. But this patch affects only three actions: ON, OFF, LEVEL.

Documentation/admin-guide/per-console-loglevel.rst line 109

Quoted 3 lines

Documentation/admin-guide/per-console-loglevel.rst new file +3 -0

+  ``kernel.force_console_loglevel``. It is unaware of per-console loglevel
+  semantics and is not recommended. A warning will be emitted if it is used
+  while local loglevels are in effect.

Do we really want to obsolete it? It might be enough to say that it works as force_console_loglevel.

I have one idea. A big difference might be replacing "force_console_loglevel" value with "ignore_per_console_loglevel" parameter.

[...]

The main logic difference is that we do not have 4 loglevel values (global,per-console,minimum,forced) and complicated rules which one will be used in the end.

Instead we have only two values: global, and optional console-specific. 2nd one is used when and only when defined. Plus one or both might ignored when the "ignore*" parameter is used.

Everything else are ways how to set the values at build/boot/run time.

How does it sounds, please?

Quoted 2 lines · Petr Mladek

IMHO, this makes things too complicated. A better solution is to do not allow to set any log level below this limit in the first place.

Hmm, how should we then handle the case that you have set the per-console loglevel to 3 and minimum_console_loglevel later gets changed to 5?

We had this problem when designing cgroup v2 as well, for example in cases where a child requests a higher memory protection than can be afforded by the parent, or where a child sets a higher memory limit than a parent specifies. We went back and forth and eventually settled on allowing these, because the alternatives seemed difficult to reason about or unnecessarily inflexible.

From the per-console loglevel side, one option is to return ERANGE or EINVAL on values we know won't be honoured when setting the per-console loglevel. The problem with that is that it doesn't allow to specify a "desired" limit in case the external factors (in this case, the minimum loglevel) change. This is even more difficult to reason about in our case because the minimum loglevel may be changed dynamically outside of user control.

Another is to disallow setting the minimum loglevel without first resetting consoles which are above the value that is desired to be set, but this seems really cumbersome, and again it doesn't account for cases like panic() and elsewhere where we blindly change it anyway.

Maybe you have another idea about how it should work in the case that the minimum loglevel would take precedence over an existing loglevel?

Quoted 8 lines

Quoted 8 lines

Documentation/admin-guide/per-console-loglevel.rst new file +7 -0

+    * ``ignore_loglevel``: ``ignore_loglevel`` was specified on the kernel
+      command line. Restart without it to use other controls.
+
+* ``enabled`` (r): Whether the console is enabled.
+* ``loglevel`` (rw): The local loglevel for this console. This will be in
+  effect if no other global control overrides it. Look at
+  ``effective_loglevel`` and ``effective_loglevel_source`` to verify that.

Quoted 7 lines

Documentation/admin-guide/per-console-loglevel.rst line 106

Quoted 4 lines

Documentation/admin-guide/per-console-loglevel.rst new file +4 -0

+Deprecated
+~~~~~~~~~~
+
+* ``syslog(SYSLOG_ACTION_CONSOLE_*)``: This sets

Why does it use "_*"? It looks like the entire syslog interface is obsolete. But this patch affects only three actions: ON, OFF, LEVEL.

Not totally sure I know what you mean -- SYSLOG_ACTION_CONSOLE_* limits it to those, no?

    % git grep -ho 'SYSLOG_ACTION_CONSOLE_[A-Z0-9]\+' | sort -u
    SYSLOG_ACTION_CONSOLE_LEVEL
    SYSLOG_ACTION_CONSOLE_OFF
    SYSLOG_ACTION_CONSOLE_ON

Quoted 4 lines

Quoted 3 lines

Documentation/admin-guide/per-console-loglevel.rst new file +3 -0

+  ``kernel.force_console_loglevel``. It is unaware of per-console loglevel
+  semantics and is not recommended. A warning will be emitted if it is used
+  while local loglevels are in effect.

Quoted 2 lines

Do we really want to obsolete it? It might be enough to say that it works as force_console_loglevel.

That's also fine -- my only concern with syslog() is that it's not very explicit about what will happen to consoles with a per-console loglevel set.

That said, once this is merged I suppose we can make it more clear in downstream consumers like dmesg -n, so not a big issue either way. :-)

Quoted 7 lines · Chris Down

Quoted 2 lines · Petr Mladek

IMHO, this makes things too complicated. A better solution is to do not allow to set any log level below this limit in the first place.

Hmm, how should we then handle the case that you have set the per-console loglevel to 3 and minimum_console_loglevel later gets changed to 5?

Quoted 6 lines

We had this problem when designing cgroup v2 as well, for example in cases where a child requests a higher memory protection than can be afforded by the parent, or where a child sets a higher memory limit than a parent specifies. We went back and forth and eventually settled on allowing these, because the alternatives seemed difficult to reason about or unnecessarily inflexible.

I see.

Quoted 7 lines

From the per-console loglevel side, one option is to return ERANGE or EINVAL on values we know won't be honoured when setting the per-console loglevel. The problem with that is that it doesn't allow to specify a "desired" limit in case the external factors (in this case, the minimum loglevel) change. This is even more difficult to reason about in our case because the minimum loglevel may be changed dynamically outside of user control.

Quoted 7 lines

Another is to disallow setting the minimum loglevel without first resetting consoles which are above the value that is desired to be set, but this seems really cumbersome, and again it doesn't account for cases like panic() and elsewhere where we blindly change it anyway.

Maybe you have another idea about how it should work in the case that the minimum loglevel would take precedence over an existing loglevel?

minimum_console_loglevel is currently used only in syslog interface. It is ignored when the levels are set using sysctl.

IMHO, the reason is that sysctl might eventually get called even with
less privileged user.

I would keep this behavior. I mean that a change of minimum_console_loglevel would not affect other values immediately. It will be used to crop the value when anyone wants to change the global loglevel via syslog later.

Well, it would make sense to crop the global or per-console loglevels even when they are later changed via the new sysctl or sysfs interface. It would be a limit for less privileged users.

Maybe, it is over-engineered. I wonder if anyone really uses the minimum level in practice.

Ok, I will incorporate the EINVAL return for sysctl in a separate patch first, and then add the new sysfs one to the existing changes for v3. :-)

Quoted 3 lines · Chris Down

Ok, I will incorporate the EINVAL return for sysctl in a separate patch first, and then add the new sysfs one to the existing changes for v3. :-)

Thinking more about this, I will probably not change the existing kernel.printk semantics to return EINVAL, since it could silently(ish) cause regressions for existing misconfigured systems on boot. I'll just add the clamps to the new controls.