Hi,
I have a console driver that registers an additional boot console and
"normal" console. The command line is:
earlycon=uart8250,mmio32,0x68A10000 console=ttyS0,115200n8
earlylog=0x8f110000,0x10000
When the second bootconsole is registered via register_console(), the
output in the log buffer is written a second time to the uart8250
console resulting in duplicate output. When the second "normal"
console is registered the complete buffer is written again to
uart8250. It looks like a bug in printk but I'm still trying to figure
out how it's keeping track of what has been written to a console.
I've attached the driver and uart8250 output.
Thanks.
Adding printk maintainers.
This commit seems to have introduced the error:
commit f92b070f2dc89a8ff1a0cc8b608e20abef894c7d
Author: Petr Mladek <[email protected]>
Date: Thu Sep 13 14:34:06 2018 +0200
printk: Do not miss new messages when replaying the log
If I checkout to the commit before
(a06b0c82a049d34d4dc273e8692ed0894458c468), the console output is
normal when registering 2 bootconsoles and 2 normal consoles. I've
added the log for 4.19.0-rc3 for comparison (previous version was
5.1.0). I don't think this commit took into account that more than one
console could be registered. When the second console is registered,
'console_seq >= exclusive_console_stop_seq' is true (both are 0) and
exclusive_console is always set to NULL resulting in the log being
replayed again to the uart8250 console:
/* Output to all consoles once old messages replayed. */
if (unlikely(exclusive_console &&
console_seq >= exclusive_console_stop_seq)) {
exclusive_console = NULL;
}
I'm looking into it but any input is helpful. Thanks.
On Wed, Nov 6, 2019 at 5:09 PM Jonathan Richardson
<[email protected]> wrote:
>
> Hi,
>
> I have a console driver that registers an additional boot console and
> "normal" console. The command line is:
> earlycon=uart8250,mmio32,0x68A10000 console=ttyS0,115200n8
> earlylog=0x8f110000,0x10000
>
> When the second bootconsole is registered via register_console(), the
> output in the log buffer is written a second time to the uart8250
> console resulting in duplicate output. When the second "normal"
> console is registered the complete buffer is written again to
> uart8250. It looks like a bug in printk but I'm still trying to figure
> out how it's keeping track of what has been written to a console.
>
> I've attached the driver and uart8250 output.
>
> Thanks.
On Wed 2019-11-13 17:28:45, Jonathan Richardson wrote:
> Adding printk maintainers.
> This commit seems to have introduced the error:
>
> commit f92b070f2dc89a8ff1a0cc8b608e20abef894c7d
> Author: Petr Mladek <[email protected]>
> Date: Thu Sep 13 14:34:06 2018 +0200
>
> printk: Do not miss new messages when replaying the log
>
> If I checkout to the commit before
> (a06b0c82a049d34d4dc273e8692ed0894458c468), the console output is
> normal when registering 2 bootconsoles and 2 normal consoles. I've
> added the log for 4.19.0-rc3 for comparison (previous version was
> 5.1.0). I don't think this commit took into account that more than one
> console could be registered. When the second console is registered,
> 'console_seq >= exclusive_console_stop_seq' is true (both are 0) and
> exclusive_console is always set to NULL resulting in the log being
> replayed again to the uart8250 console:
This race should not happen because Both exclusive_console and
exclusive_console_stop_seq are manipulated under console_lock.
And the log is replayed before console_lock is released.
> /* Output to all consoles once old messages replayed. */
> if (unlikely(exclusive_console &&
> console_seq >= exclusive_console_stop_seq)) {
> exclusive_console = NULL;
> }
>
> I'm looking into it but any input is helpful. Thanks.
IMHO, the problem is that the log should not be replayed at all.
See the following code in register_console():
/*
* If we have a bootconsole, and are switching to a real console,
* don't print everything out again, since when the boot console, and
* the real console are the same physical device, it's annoying to
* see the beginning boot messages twice
*/
if (bcon && ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV))
newcon->flags &= ~CON_PRINTBUFFER;
I already see two problems there:
1. CON_PRINTBUFFER is cleared only when the new console has
CON_CONSDEV flag set. It is set only for the console
that is defined as the last on the command line.
It is a so-called preferred console.
2. bcon is set to the first console in console_drivers list.
It is the first registered boot console.
Sigh, this works for simple configuration. But it fails badly when
more different consoles are configured.
We should clear CON_PRINTBUFFER flag when the real console
replacing an already registered boot console is registered.
BTW: Similar bug is also at the end of register_console().
The boot consoles are unregistered only when the preferred
console is installed.
For a proper solution we would need to match boot and real
consoles that write messages into the physical device.
But I am afraid that there is no support for this.
con->match() callback compares the name defined on
the command line. And it has side effects (the matching
console is prepared for registration).
To be honest I am not much familiar with the device interface.
I am not sure if there is a way to detect the two drivers
use the same physical hardware.
Sigh, it is a huge historical mess. It would needed a lot
of work to clean it up.
Best Regards,
Petr
Gosh, that part of printk is really complex.
On (19/11/14 10:57), Petr Mladek wrote:
> For a proper solution we would need to match boot and real
> consoles that write messages into the physical device.
> But I am afraid that there is no support for this.
Wouldn't those have same tty driver?
---
kernel/printk/printk.c | 16 ++++++++++++++++
1 file changed, 16 insertions(+)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f1b08015d3fa..a84cb20acf42 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2690,6 +2690,19 @@ static int __init keep_bootcon_setup(char *str)
early_param("keep_bootcon", keep_bootcon_setup);
+static bool known_console_driver(struct console *newcon)
+{
+ struct console *con;
+
+ for_each_console(con) {
+ if (!(con->flags & CON_ENABLED))
+ continue;
+ if (con->device && con->device == newcon->device)
+ return true;
+ }
+ return false;
+}
+
/*
* The console driver calls this routine during kernel initialization
* to register the console printing procedure with printk() and to
@@ -2828,6 +2841,9 @@ void register_console(struct console *newcon)
if (newcon->flags & CON_EXTENDED)
nr_ext_console_drivers++;
+ if (known_console_driver(newcon))
+ newcon->flags &= ~CON_PRINTBUFFER;
+
if (newcon->flags & CON_PRINTBUFFER) {
/*
* console_unlock(); will print out the buffered messages
On Thu, Nov 14, 2019 at 8:33 PM Sergey Senozhatsky
<[email protected]> wrote:
>
> Gosh, that part of printk is really complex.
>
> On (19/11/14 10:57), Petr Mladek wrote:
> > For a proper solution we would need to match boot and real
> > consoles that write messages into the physical device.
> > But I am afraid that there is no support for this.
>
> Wouldn't those have same tty driver?
>
> ---
>
> kernel/printk/printk.c | 16 ++++++++++++++++
> 1 file changed, 16 insertions(+)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index f1b08015d3fa..a84cb20acf42 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2690,6 +2690,19 @@ static int __init keep_bootcon_setup(char *str)
>
> early_param("keep_bootcon", keep_bootcon_setup);
>
> +static bool known_console_driver(struct console *newcon)
> +{
> + struct console *con;
> +
> + for_each_console(con) {
> + if (!(con->flags & CON_ENABLED))
> + continue;
> + if (con->device && con->device == newcon->device)
> + return true;
> + }
> + return false;
> +}
> +
> /*
> * The console driver calls this routine during kernel initialization
> * to register the console printing procedure with printk() and to
> @@ -2828,6 +2841,9 @@ void register_console(struct console *newcon)
> if (newcon->flags & CON_EXTENDED)
> nr_ext_console_drivers++;
>
> + if (known_console_driver(newcon))
> + newcon->flags &= ~CON_PRINTBUFFER;
> +
> if (newcon->flags & CON_PRINTBUFFER) {
> /*
> * console_unlock(); will print out the buffered messages
Thanks. It also needs to be cleared when the second console driver is
registered (of the same type, boot or normal), not just when a normal
con replaces a bootconsole. A simple way of avoiding the problem I'm
seeing is to not even set the CON_PRINTBUFFER flag on my consoles. It
skips the replay and the output on all consoles looks fine. The flag
is only used by register_console(), although I don't think that is the
intended usage? There are no console drivers that do this.
On (19/11/18 13:38), Jonathan Richardson wrote:
> > +static bool known_console_driver(struct console *newcon)
> > +{
> > + struct console *con;
> > +
> > + for_each_console(con) {
> > + if (!(con->flags & CON_ENABLED))
> > + continue;
> > + if (con->device && con->device == newcon->device)
> > + return true;
> > + }
> > + return false;
> > +}
> > +
> > /*
> > * The console driver calls this routine during kernel initialization
> > * to register the console printing procedure with printk() and to
> > @@ -2828,6 +2841,9 @@ void register_console(struct console *newcon)
> > if (newcon->flags & CON_EXTENDED)
> > nr_ext_console_drivers++;
> >
> > + if (known_console_driver(newcon))
> > + newcon->flags &= ~CON_PRINTBUFFER;
> > +
> > if (newcon->flags & CON_PRINTBUFFER) {
> > /*
> > * console_unlock(); will print out the buffered messages
>
> Thanks. It also needs to be cleared when the second console driver is
> registered (of the same type, boot or normal)
The second 'normal' console can be, for instance, netcon - it's sort
of OK to have CON_PRINTBUFFER tty and CON_PRINTBUFFER netcon consoles.
Maybe
> not just when a normal con replaces a bootconsole. A simple way of
> avoiding the problem I'm seeing is to not even set the CON_PRINTBUFFER
> flag on my consoles.
This is up to the console driver to decide.
> It skips the replay and the output on all consoles looks fine. The flag
> is only used by register_console(), although I don't think that is the
> intended usage? There are no console drivers that do this.
Not sure I'm following. There are consoles that want all logbuf messages
once those consoles are available.
$ git grep "\.flags" drivers/tty/ | grep -c CON_PRINTBUFFER
72
-ss
On Mon 2019-11-18 13:38:04, Jonathan Richardson wrote:
> On Thu, Nov 14, 2019 at 8:33 PM Sergey Senozhatsky
> <[email protected]> wrote:
> >
> > Gosh, that part of printk is really complex.
> >
> > On (19/11/14 10:57), Petr Mladek wrote:
> > > For a proper solution we would need to match boot and real
> > > consoles that write messages into the physical device.
> > > But I am afraid that there is no support for this.
> >
> > Wouldn't those have same tty driver?
Interesting idea. Well, do early consoles have tty driver?
> > ---
> >
> > kernel/printk/printk.c | 16 ++++++++++++++++
> > 1 file changed, 16 insertions(+)
> >
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index f1b08015d3fa..a84cb20acf42 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2690,6 +2690,19 @@ static int __init keep_bootcon_setup(char *str)
> >
> > early_param("keep_bootcon", keep_bootcon_setup);
> >
> > +static bool known_console_driver(struct console *newcon)
> > +{
> > + struct console *con;
> > +
> > + for_each_console(con) {
> > + if (!(con->flags & CON_ENABLED))
> > + continue;
> > + if (con->device && con->device == newcon->device)
> > + return true;
> > + }
> > + return false;
> > +}
> > +
> > /*
> > * The console driver calls this routine during kernel initialization
> > * to register the console printing procedure with printk() and to
> > @@ -2828,6 +2841,9 @@ void register_console(struct console *newcon)
> > if (newcon->flags & CON_EXTENDED)
> > nr_ext_console_drivers++;
> >
> > + if (known_console_driver(newcon))
> > + newcon->flags &= ~CON_PRINTBUFFER;
> > +
> > if (newcon->flags & CON_PRINTBUFFER) {
> > /*
> > * console_unlock(); will print out the buffered messages
>
> Thanks.
Jonathan, have you tried this patch, please?
Does it solve your problem?
Best Regards,
Petr
On Tue, Nov 19, 2019 at 3:30 AM Petr Mladek <[email protected]> wrote:
>
> On Mon 2019-11-18 13:38:04, Jonathan Richardson wrote:
> > On Thu, Nov 14, 2019 at 8:33 PM Sergey Senozhatsky
> > <[email protected]> wrote:
> > >
> > > Gosh, that part of printk is really complex.
> > >
> > > On (19/11/14 10:57), Petr Mladek wrote:
> > > > For a proper solution we would need to match boot and real
> > > > consoles that write messages into the physical device.
> > > > But I am afraid that there is no support for this.
> > >
> > > Wouldn't those have same tty driver?
>
> Interesting idea. Well, do early consoles have tty driver?
>
> > > ---
> > >
> > > kernel/printk/printk.c | 16 ++++++++++++++++
> > > 1 file changed, 16 insertions(+)
> > >
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index f1b08015d3fa..a84cb20acf42 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -2690,6 +2690,19 @@ static int __init keep_bootcon_setup(char *str)
> > >
> > > early_param("keep_bootcon", keep_bootcon_setup);
> > >
> > > +static bool known_console_driver(struct console *newcon)
> > > +{
> > > + struct console *con;
> > > +
> > > + for_each_console(con) {
> > > + if (!(con->flags & CON_ENABLED))
> > > + continue;
> > > + if (con->device && con->device == newcon->device)
> > > + return true;
> > > + }
> > > + return false;
> > > +}
> > > +
> > > /*
> > > * The console driver calls this routine during kernel initialization
> > > * to register the console printing procedure with printk() and to
> > > @@ -2828,6 +2841,9 @@ void register_console(struct console *newcon)
> > > if (newcon->flags & CON_EXTENDED)
> > > nr_ext_console_drivers++;
> > >
> > > + if (known_console_driver(newcon))
> > > + newcon->flags &= ~CON_PRINTBUFFER;
> > > +
> > > if (newcon->flags & CON_PRINTBUFFER) {
> > > /*
> > > * console_unlock(); will print out the buffered messages
> >
> > Thanks.
>
> Jonathan, have you tried this patch, please?
> Does it solve your problem?
I've tried it and it doesn't solve the problem. newcon is not a known
console at the time I register my second console. The only thing I can
do is not replay the log by not setting CON_PRINTBUFFER and I
shouldn't have to do that after reading Sergey's last response.
> > Thanks. It also needs to be cleared when the second console driver is
> > registered (of the same type, boot or normal)
>
> The second 'normal' console can be, for instance, netcon - it's sort
> of OK to have CON_PRINTBUFFER tty and CON_PRINTBUFFER netcon consoles.
OK I missed that case.
>
> Maybe
>
> > not just when a normal con replaces a bootconsole. A simple way of
> > avoiding the problem I'm seeing is to not even set the CON_PRINTBUFFER
> > flag on my consoles.
>
> This is up to the console driver to decide.
>
> > It skips the replay and the output on all consoles looks fine. The flag
> > is only used by register_console(), although I don't think that is the
> > intended usage? There are no console drivers that do this.
>
> Not sure I'm following. There are consoles that want all logbuf messages
> once those consoles are available.
I meant mine would be the only driver that didn't set CON_PRINTBUFFER.
Thanks for clarifying why it would be set. I guess what I didn't
understand is why are all the consoles updated (potentially) when a
new console is registered. As I mentioned before I can not set
CON_PRINTBUFFER to avoid the issue but it's probably not what I want.
I would possibly lose some of the log I guess if there was something
in the buffer during registration of the new console. So I tried the
patch but the issue remains as I originally described.
Thanks,
Jon
On (19/11/19 12:30), Petr Mladek wrote:
> On Mon 2019-11-18 13:38:04, Jonathan Richardson wrote:
> > On Thu, Nov 14, 2019 at 8:33 PM Sergey Senozhatsky
> > <[email protected]> wrote:
> > >
> > > Gosh, that part of printk is really complex.
> > >
> > > On (19/11/14 10:57), Petr Mladek wrote:
> > > > For a proper solution we would need to match boot and real
> > > > consoles that write messages into the physical device.
> > > > But I am afraid that there is no support for this.
> > >
> > > Wouldn't those have same tty driver?
>
> Interesting idea. Well, do early consoles have tty driver?
Good question! I'm not sure.
netcon, for instance, doesn't have tty driver, yet still has to find
a proper net device to write the data to. They have some magic inside.
-ss
On Tue 2019-11-19 10:46:22, Jonathan Richardson wrote:
> > > not just when a normal con replaces a bootconsole. A simple way of
> > > avoiding the problem I'm seeing is to not even set the CON_PRINTBUFFER
> > > flag on my consoles.
> >
> > This is up to the console driver to decide.
> >
> > > It skips the replay and the output on all consoles looks fine. The flag
> > > is only used by register_console(), although I don't think that is the
> > > intended usage? There are no console drivers that do this.
> >
> > Not sure I'm following. There are consoles that want all logbuf messages
> > once those consoles are available.
>
> I meant mine would be the only driver that didn't set CON_PRINTBUFFER.
> Thanks for clarifying why it would be set. I guess what I didn't
> understand is why are all the consoles updated (potentially) when a
> new console is registered. As I mentioned before I can not set
> CON_PRINTBUFFER to avoid the issue but it's probably not what I want.
> I would possibly lose some of the log I guess if there was something
> in the buffer during registration of the new console.
Exactly, many things happen before and during the console
registration. There might already be (are) several messages when
new consoles are registered.
Now, people register more different consoles for different purpose.
For example, one is shown on a display, another can be stored by
an external device. It makes sense to show all messages on
all interfaces.
It can cause duplicated messages because there is no support to match
proper console with the early one. The current console registration
code somehow works only with one early console.
Best Regards,
Petr