[PATCH v5 0/3] printk: fix double printing with earlycon

[PATCH v5 0/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line parameters like
"console=ttyAMA0" _and_ "earlycon" were specified, then log messages
appear twice.

This issue was addressed in the patch [1] but the approach was wrong and
a revert [2] was suggested.

First two patches "printk: fix name/type/scope of preferred_console var" and
"printk: rename selected_console -> preferred_console" were sent some
time ago as one patch "printk: fix name and type of some variables" [3].
They fix name/type/scope of some variables without changing the logic.

The real fix is in the second patch.  The root cause is that the code traverses
the list of specified consoles (the `console_cmdline` array) and stops at the
first match.  But it may happen that the same console is referred by
the elements of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, introduce an invariant "The last non-braille console is always the
preferred one" on the entries of the console_cmdline array and don't try to
check for double entries.  Then traverse it in reverse order to be sure that if
the console is preferred then it will be the first matching entry.

v5:
- rewrite 3/3.  Insetead of rearranging the loop, introduce an invariant
  "The last non-braille console is always the preferred one" on the
  entries of the console_cmdline array and don't try to check for double
  entries.  Then traverse it in reverse order to be sure that if the console
  is preferred then it will be the first matching entry.
- add a better explanation from Petr Mladek for 2/3.

v4:
It was not sent upstream due to some problems in implementation of 3/3.
- add some Acked-by: and Reviewed-by: to 1/3 and 2/3
- v2 was closer to the original logic, even though v3 looked simpler.
  The problem is that newcon->setup() is called twice, firstly
  from newcon->match(), then explicitly.  And it could be called third time
  later in another call to newcon->match().  Implement correct sequence:
    1) try to match against preferred_console,
    2) if that fails check other entries of console_cmdline.
  Also move braille console matching/registration to a separate pass to simplify
  the code.

v3 (only for 3/3):
https://lkml.kernel.org/r/20170303154946.15399-1-aleksey.makarov@linaro.org
- v2 still changes the logic of the code and calls newcon->match() several
  times.  V3 fixes that.  It initially matches the console against
  the preferred_console entry, and then if that fails, against other entries.

v2:
https://lkml.kernel.org/r/20170302131153.22733-1-aleksey.makarov@linaro.org
- split the patch that renames `selected_console` and `preferred_console`
  into two patches (Steven Rostedt)
- add a comment explaining why we need a separate match to check for
  preferred_console (Steven Rostedt)
- v1 of this patchset changed the logic of console initialization a bit.
  That could lead to bugs/incompatibilities.  Use the exactly the same
  logic as in the original code.

v1:
https://lkml.kernel.org/r/20170301161347.4202-1-aleksey.makarov@linaro.org

[1] https://lkml.kernel.org/r/1485963998-921-1-git-send-email-sudeep.holla@arm.com
    commit aea9a80ba98a ("tty: serial: pl011: add ttyAMA for matching pl011 console")
[2] https://lkml.kernel.org/r/20170301152304.29635-1-aleksey.makarov@linaro.org
[3] https://lkml.kernel.org/r/1455299022-11641-2-git-send-email-aleksey.makarov@linaro.org

Aleksey Makarov (3):
  printk: fix name/type/scope of preferred_console var
  printk: rename selected_console -> preferred_console
  printk: fix double printing with earlycon

 kernel/printk/printk.c | 61 ++++++++++++++++++++++++++++++--------------------
 1 file changed, 37 insertions(+), 24 deletions(-)

-- 
2.12.0

[PATCH v5 1/3] printk: fix name/type/scope of preferred_console var

[Aleksey Makarov]

The variable preferred_console is used only inside register_console()
and its semantics is boolean.  It is negative when no console has been
made preferred.

Make it static bool and rename to has_preferred.

Renaming was suggested by Peter Hurley

Acked-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---
 kernel/printk/printk.c | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2984fb0f0257..80bc1b72d03d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -271,7 +271,6 @@ static struct console *exclusive_console;
 static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
 
 static int selected_console = -1;
-static int preferred_console = -1;
 int console_set_on_cmdline;
 EXPORT_SYMBOL(console_set_on_cmdline);
 
@@ -2409,6 +2408,7 @@ void register_console(struct console *newcon)
 	unsigned long flags;
 	struct console *bcon = NULL;
 	struct console_cmdline *c;
+	static bool has_preferred;
 
 	if (console_drivers)
 		for_each_console(bcon)
@@ -2435,15 +2435,15 @@ void register_console(struct console *newcon)
 	if (console_drivers && console_drivers->flags & CON_BOOT)
 		bcon = console_drivers;
 
-	if (preferred_console < 0 || bcon || !console_drivers)
-		preferred_console = selected_console;
+	if (!has_preferred || bcon || !console_drivers)
+		has_preferred = selected_console >= 0;
 
 	/*
 	 *	See if we want to use this console driver. If we
 	 *	didn't select a console we take the first one
 	 *	that registers here.
 	 */
-	if (preferred_console < 0) {
+	if (!has_preferred) {
 		if (newcon->index < 0)
 			newcon->index = 0;
 		if (newcon->setup == NULL ||
@@ -2451,7 +2451,7 @@ void register_console(struct console *newcon)
 			newcon->flags |= CON_ENABLED;
 			if (newcon->device) {
 				newcon->flags |= CON_CONSDEV;
-				preferred_console = 0;
+				has_preferred = true;
 			}
 		}
 	}
@@ -2486,7 +2486,7 @@ void register_console(struct console *newcon)
 		newcon->flags |= CON_ENABLED;
 		if (i == selected_console) {
 			newcon->flags |= CON_CONSDEV;
-			preferred_console = selected_console;
+			has_preferred = true;
 		}
 		break;
 	}
-- 
2.12.0

[PATCH v5 2/3] printk: rename selected_console -> preferred_console

[Aleksey Makarov]

The variable selected_console is set in __add_preferred_console()
to point to the last console parameter that was added to the
console_cmdline array.

Rename it to preferred_console so that the name reflects the usage.

Petr Mladek:
"[..] the selected_console/preferred_console
value is used to keep the console first in the console_drivers list.
IMHO, the main effect is that each line will first appear on this
console, see call_console_drivers(). But the message will still
appear also on all other enabled consoles. From this point,
the name "preferred" sounds better to me. More consoles
are selected (enabled) and only one is preferred (first)."

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Acked-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Peter Hurley <peter@hurleysoftware.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---
 kernel/printk/printk.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 80bc1b72d03d..fd752f0c8ef1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -270,7 +270,7 @@ static struct console *exclusive_console;
 
 static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
 
-static int selected_console = -1;
+static int preferred_console = -1;
 int console_set_on_cmdline;
 EXPORT_SYMBOL(console_set_on_cmdline);
 
@@ -1910,14 +1910,14 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	     i++, c++) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
 			if (!brl_options)
-				selected_console = i;
+				preferred_console = i;
 			return 0;
 		}
 	}
 	if (i == MAX_CMDLINECONSOLES)
 		return -E2BIG;
 	if (!brl_options)
-		selected_console = i;
+		preferred_console = i;
 	strlcpy(c->name, name, sizeof(c->name));
 	c->options = options;
 	braille_set_options(c, brl_options);
@@ -2436,7 +2436,7 @@ void register_console(struct console *newcon)
 		bcon = console_drivers;
 
 	if (!has_preferred || bcon || !console_drivers)
-		has_preferred = selected_console >= 0;
+		has_preferred = preferred_console >= 0;
 
 	/*
 	 *	See if we want to use this console driver. If we
@@ -2484,7 +2484,7 @@ void register_console(struct console *newcon)
 		}
 
 		newcon->flags |= CON_ENABLED;
-		if (i == selected_console) {
+		if (i == preferred_console) {
 			newcon->flags |= CON_CONSDEV;
 			has_preferred = true;
 		}
-- 
2.12.0

[PATCH v5 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line
parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
then log messages appear twice.

The root cause is that the code traverses the list of specified
consoles (the `console_cmdline` array) and stops at the first match.
But it may happen that the same console is referred by the elements
of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, introduce an invariant "The last non-braille console
is always the preferred one" on the entries of the console_cmdline
array and don't try to check for double entries.  Then traverse it
in reverse order to be sure that if the console is preferred then
it will be the first matching entry.

Reported-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---
 kernel/printk/printk.c | 45 +++++++++++++++++++++++++++++----------------
 1 file changed, 29 insertions(+), 16 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd752f0c8ef1..7dc53b2831fb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1902,20 +1902,25 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	int i;
 
 	/*
-	 *	See if this tty is not yet registered, and
-	 *	if we have a slot free.
+	 * Don't check if the console has already been registered, because it is
+	 * pointless.  After all, we can not check if two entries refer to
+	 * the same console if one is matched with console->match(), and another
+	 * by name/index:
+	 *
+	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
+	 *	ttyAMA0 -- added from command line
+	 *
+	 * Also this allows to maintain an invariant that will help to find if
+	 * the matching console is preferred, see register_console():
+	 *
+	 *	The last non-braille console is always the preferred one.
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
-		if (strcmp(c->name, name) == 0 && c->index == idx) {
-			if (!brl_options)
-				preferred_console = i;
-			return 0;
-		}
-	}
+	for (i = 0; i < MAX_CMDLINECONSOLES; i++)
+		if (!console_cmdline[i].name[0])
+			break;
 	if (i == MAX_CMDLINECONSOLES)
 		return -E2BIG;
+	c = console_cmdline + i;
 	if (!brl_options)
 		preferred_console = i;
 	strlcpy(c->name, name, sizeof(c->name));
@@ -2457,12 +2462,20 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 *	See if this console matches one we selected on
-	 *	the command line.
+	 * See if this console matches one we selected on the command line.
+	 *
+	 * The console_cmdline array is traversed in the reverse order because
+	 * we want to be sure that if this console is preferred then it will be
+	 * the first matching entry.  We use the invariant that is maintained in
+	 * __add_preferred_console().
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for (i = MAX_CMDLINECONSOLES - 1; i >= 0; i--) {
+
+		if (!console_cmdline[i].name[0])
+			continue;
+
+		c = console_cmdline + i;
+
 		if (!newcon->match ||
 		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
 			/* default matching */
-- 
2.12.0

Re: [PATCH v5 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Wed 2017-03-15 13:28:52, Aleksey Makarov wrote:
> If a console was specified by ACPI SPCR table _and_ command line
> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> then log messages appear twice.
> 
> The root cause is that the code traverses the list of specified
> consoles (the `console_cmdline` array) and stops at the first match.
> But it may happen that the same console is referred by the elements
> of this array twice:
> 
> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
> 	ttyAMA0 -- from command line
> 
> but in this case `preferred_console` points to the second entry and
> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> 
> To fix that, introduce an invariant "The last non-braille console
> is always the preferred one" on the entries of the console_cmdline
> array and don't try to check for double entries.  Then traverse it
> in reverse order to be sure that if the console is preferred then
> it will be the first matching entry.
> 
> Reported-by: Sudeep Holla <sudeep.holla@arm.com>
> Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
> ---
>  kernel/printk/printk.c | 45 +++++++++++++++++++++++++++++----------------
>  1 file changed, 29 insertions(+), 16 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fd752f0c8ef1..7dc53b2831fb 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1902,20 +1902,25 @@ static int __add_preferred_console(char *name, int idx, char *options,
>  	int i;
>  
>  	/*
> -	 *	See if this tty is not yet registered, and
> -	 *	if we have a slot free.
> +	 * Don't check if the console has already been registered, because it is
> +	 * pointless.  After all, we can not check if two entries refer to
> +	 * the same console if one is matched with console->match(), and another
> +	 * by name/index:
> +	 *
> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
> +	 *	ttyAMA0 -- added from command line
> +	 *
> +	 * Also this allows to maintain an invariant that will help to find if
> +	 * the matching console is preferred, see register_console():

It is an interesting idea.

I just wonder if the check for duplicates was there for a serious
reason. It is hard to say because it was already in the initial git
commit. In each case, MAX_CMDLINECONSOLES is 8. There is not much
space for duplicates.

Note that add_preferred_console() is called also from _probe() calls,
see

   uart_add_one_port() -> of_console_check()
   sunserial_console_match() -> add_preferred_console()

I wonder they might be called repeatedly, for example because
of suspend/restore, hotplug, module load/unload.

I would feel more comfortable if we keep the check for
duplicates here.

It is a pity that the console->match() calls have side effects.
I still wonder if the 4th version might be more safe. The
newcon->setup() call is called only when the console matches.
AFAIK, there is only one braille console. We should be on
the safe side if this one does not implement the match()
callback. Or is it even more complicated?

To be honest, I am not much familiar with the console registration
code. I am still trying to get a better picture. It is pity that
many function have unexpected side effects.

Best Regards,
Petr

Re: [PATCH v5 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (03/15/17 17:58), Petr Mladek wrote:
[..]
> On Wed 2017-03-15 13:28:52, Aleksey Makarov wrote:
> > If a console was specified by ACPI SPCR table _and_ command line
> > parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> > then log messages appear twice.
> > 
> > The root cause is that the code traverses the list of specified
> > consoles (the `console_cmdline` array) and stops at the first match.
> > But it may happen that the same console is referred by the elements
> > of this array twice:
> > 
> > 	pl011,mmio,0x87e024000000,115200 -- from SPCR
> > 	ttyAMA0 -- from command line
> > 
> > but in this case `preferred_console` points to the second entry and
> > the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> > 
> > To fix that, introduce an invariant "The last non-braille console
> > is always the preferred one" on the entries of the console_cmdline
> > array and don't try to check for double entries.  Then traverse it
> > in reverse order to be sure that if the console is preferred then
> > it will be the first matching entry.

overall this approach looks interesting. but I need to look more at
this, since I'm not really familiar with this console registration thing.

your reverse traversal, Aleksey, makes sense to me, but there might be
things I'm missing.

> > @@ -1902,20 +1902,25 @@ static int __add_preferred_console(char *name, int idx, char *options,
> >  	int i;
> >  
> >  	/*
> > -	 *	See if this tty is not yet registered, and
> > -	 *	if we have a slot free.
> > +	 * Don't check if the console has already been registered, because it is
> > +	 * pointless.  After all, we can not check if two entries refer to
> > +	 * the same console if one is matched with console->match(), and another
> > +	 * by name/index:
> > +	 *
> > +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
> > +	 *	ttyAMA0 -- added from command line
> > +	 *
> > +	 * Also this allows to maintain an invariant that will help to find if
> > +	 * the matching console is preferred, see register_console():
> 
> It is an interesting idea.
> 
> I just wonder if the check for duplicates was there for a serious
> reason. It is hard to say because it was already in the initial git
> commit. In each case, MAX_CMDLINECONSOLES is 8. There is not much
> space for duplicates.

hm. as Petr mentioned, device tree may have its own console preferences
specified via stdout-path or linux,stdout-path. which ends up in
	of_console_check()->add_preferred_console().
so we may look at a mix of command line, ACPI port redirection and DT.
DT may have aliases, etc. but I still suspect that that strcmp() is
probably not be completely pointless. some drivers call add_preferred_console()
directly, passing entries that might present in command line. e.g.
	add_preferred_console("ttyS", 2, "115200");



by the way.
we might have a memory leak there.

drivers/of/base.c

bool of_console_check(struct device_node *dn, char *name, int index)
{
	if (!dn || dn != of_stdout || console_set_on_cmdline)
		return false;
	return !add_preferred_console(name, index,
				      kstrdup(of_stdout_options, GFP_KERNEL));
}

printk/printk.c

static int __add_preferred_console(char *name, int idx, char *options,
				   char *brl_options)
{
	struct console_cmdline *c;
	int i;

	/*
	 *	See if this tty is not yet registered, and
	 *	if we have a slot free.
	 */
	for (i = 0, c = console_cmdline;
	     i < MAX_CMDLINECONSOLES && c->name[0];
	     i++, c++) {
		if (strcmp(c->name, name) == 0 && c->index == idx) {
			if (!brl_options)
				selected_console = i;
			return 0;
		}
	}
	if (i == MAX_CMDLINECONSOLES)
		return -E2BIG;
	if (!brl_options)
		selected_console = i;
	strlcpy(c->name, name, sizeof(c->name));
	c->options = options;
	braille_set_options(c, brl_options);

	c->index = idx;
	return 0;
}

int add_preferred_console(char *name, int idx, char *options)
{
	return __add_preferred_console(name, idx, options, NULL);
}



kstrdup()-ed stdout options passed from of_console_check() are getting
lost when:

  a) __add_preferred_console() returns -E2BIG
  b) __add_preferred_console() finds a duplicate entry in console_cmdline


> I would feel more comfortable if we keep the check for
> duplicates here.

I would agree.

	-ss

Re: [PATCH v5 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 03/15/2017 07:58 PM, Petr Mladek wrote:
> On Wed 2017-03-15 13:28:52, Aleksey Makarov wrote:
>> If a console was specified by ACPI SPCR table _and_ command line
>> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
>> then log messages appear twice.
>>
>> The root cause is that the code traverses the list of specified
>> consoles (the `console_cmdline` array) and stops at the first match.
>> But it may happen that the same console is referred by the elements
>> of this array twice:
>>
>> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
>> 	ttyAMA0 -- from command line
>>
>> but in this case `preferred_console` points to the second entry and
>> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
>>
>> To fix that, introduce an invariant "The last non-braille console
>> is always the preferred one" on the entries of the console_cmdline
>> array and don't try to check for double entries.  Then traverse it
>> in reverse order to be sure that if the console is preferred then
>> it will be the first matching entry.
>>
>> Reported-by: Sudeep Holla <sudeep.holla@arm.com>
>> Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
>> ---
>>  kernel/printk/printk.c | 45 +++++++++++++++++++++++++++++----------------
>>  1 file changed, 29 insertions(+), 16 deletions(-)
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index fd752f0c8ef1..7dc53b2831fb 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1902,20 +1902,25 @@ static int __add_preferred_console(char *name, int idx, char *options,
>>  	int i;
>>  
>>  	/*
>> -	 *	See if this tty is not yet registered, and
>> -	 *	if we have a slot free.
>> +	 * Don't check if the console has already been registered, because it is
>> +	 * pointless.  After all, we can not check if two entries refer to
>> +	 * the same console if one is matched with console->match(), and another
>> +	 * by name/index:
>> +	 *
>> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
>> +	 *	ttyAMA0 -- added from command line
>> +	 *
>> +	 * Also this allows to maintain an invariant that will help to find if
>> +	 * the matching console is preferred, see register_console():
> 
> It is an interesting idea.
> 
> I just wonder if the check for duplicates was there for a serious
> reason. It is hard to say because it was already in the initial git
> commit. In each case, MAX_CMDLINECONSOLES is 8. There is not much
> space for duplicates.
> 
> Note that add_preferred_console() is called also from _probe() calls,
> see
> 
>    uart_add_one_port() -> of_console_check()
>    sunserial_console_match() -> add_preferred_console()
> 
> I wonder they might be called repeatedly, for example because
> of suspend/restore, hotplug, module load/unload.
> 
> I would feel more comfortable if we keep the check for
> duplicates here.

Now I see the problem, thank you.

> It is a pity that the console->match() calls have side effects.
> I still wonder if the 4th version might be more safe. 

I pushed v4 to the linaro git server:

https://git.linaro.org/people/aleksey.makarov/linux.git/commit/?h=amakarov/console2.19.v4&id=47a8227e37ca54d9cc7051abe9b3c2d072f4f75f

The problem with that approach is again a side effect.
Function match_console_name() can change newcon->index.
But it can be called in the very first pass that looks for braille console
and if the call to _braille_register_console() fails,
this newcon with changed index is passed to newcon->match().

This can be fixed by introducing a predicate that checks if the
console_cmdline entry has braille options and calling match_console_name()
only for such consoles, but I think that the code is too convoluted
and the v5 approach is better.

I am going to fix v5 preserving both the check for duplicates
and the invariant, but tell me please if you prefer the v4 approach.

> The
> newcon->setup() call is called only when the console matches.
> AFAIK, there is only one braille console. We should be on
> the safe side if this one does not implement the match()
> callback. Or is it even more complicated?

As you can see from the original code, the check for braille console
was performed in that branch of code where we missed newcon->match(),
so yes, it looks like braille console(s) does not have the match() method.
I used that in v4 to factor out matching for braille from the loop.

Thank you
Aleksey Makarov

> To be honest, I am not much familiar with the console registration
> code. I am still trying to get a better picture. It is pity that
> many function have unexpected side effects.
> 
> Best Regards,
> Petr
> --
> To unsubscribe from this list: send the line "unsubscribe linux-serial" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

Re: [PATCH v5 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Thu 2017-03-16 13:36:35, Aleksey Makarov wrote:
> 
> 
> On 03/15/2017 07:58 PM, Petr Mladek wrote:
> > On Wed 2017-03-15 13:28:52, Aleksey Makarov wrote:
> >> If a console was specified by ACPI SPCR table _and_ command line
> >> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> >> then log messages appear twice.
> >>
> >> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> >> index fd752f0c8ef1..7dc53b2831fb 100644
> >> --- a/kernel/printk/printk.c
> >> +++ b/kernel/printk/printk.c
> >> @@ -1902,20 +1902,25 @@ static int __add_preferred_console(char *name, int idx, char *options,
> >>  	int i;
> >>  
> >>  	/*
> >> -	 *	See if this tty is not yet registered, and
> >> -	 *	if we have a slot free.
> >> +	 * Don't check if the console has already been registered, because it is
> >> +	 * pointless.  After all, we can not check if two entries refer to
> >> +	 * the same console if one is matched with console->match(), and another
> >> +	 * by name/index:
> >> +	 *
> >> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
> >> +	 *	ttyAMA0 -- added from command line
> >> +	 *
> >> +	 * Also this allows to maintain an invariant that will help to find if
> >> +	 * the matching console is preferred, see register_console():
> > 
> > It is an interesting idea.
> > 
> > I just wonder if the check for duplicates was there for a serious
> > reason. It is hard to say because it was already in the initial git
> > commit. In each case, MAX_CMDLINECONSOLES is 8. There is not much
> > space for duplicates.
> > 
> > Note that add_preferred_console() is called also from _probe() calls,
> > see
> > 
> >    uart_add_one_port() -> of_console_check()
> >    sunserial_console_match() -> add_preferred_console()
> > 
> > I wonder they might be called repeatedly, for example because
> > of suspend/restore, hotplug, module load/unload.
> > 
> > I would feel more comfortable if we keep the check for
> > duplicates here.
> 
> Now I see the problem, thank you.
> 
> > It is a pity that the console->match() calls have side effects.
> > I still wonder if the 4th version might be more safe. 
> 
> I pushed v4 to the linaro git server:
> 
> https://git.linaro.org/people/aleksey.makarov/linux.git/commit/?h=amakarov/console2.19.v4&id=47a8227e37ca54d9cc7051abe9b3c2d072f4f75f
> 
> The problem with that approach is again a side effect.
> Function match_console_name() can change newcon->index.
> But it can be called in the very first pass that looks for braille console
> and if the call to _braille_register_console() fails,
> this newcon with changed index is passed to newcon->match().

I see. We need to make sure that newcon->match() will not get called
when checking for the braille console.


> This can be fixed by introducing a predicate that checks if the
> console_cmdline entry has braille options and calling match_console_name()
> only for such consoles, but I think that the code is too convoluted
> and the v5 approach is better.

I personally prefer v4. The braille console adds an unexpected
twist into the code because it skips the rest of the function.
IMHO, it is better when it is is tested separately with clear
conditions and comments.

I would personally add the following into
kernel/printk/console_cmdline.h

#define for_each_console_cmdline(c, i) \
	for (i = 0, c = console_cmdline;		\
	     i < MAX_CMDLINECONSOLES && c->name[0];	\
	     i++, c++)

It can be used in both __add_preferred_console()
and register_console().

Also I would add the following into kernel/printk/braille.h

static inline bool
is_braille_console(struct console_cmdline *c)
{
	return !!c->brl_options;
}

Then the braille-specific code in register_console() might
look like:

	/*
	 * Braille console is handled a very special way.
	 * Is is not listed in the console_drivers list.
	 * Instead it registers its own keyboard and vt notifiers.
	 *
	 * Be careful and avoid calling c->match() here
	 * because it might have side effects!
	 */
	if (is_braille_console(c) &&
	    match_console_name(newcon, c) &&
	    _braille_register_console(newcon, c))
		return;


Finally, I would prefer to move

	newcon->flags |= CON_ENABLED;

outside the match_console() function. The function will still
have side effects because of the c->match() calls. But we should
not make it worse. In fact, it would be great to remove side effects
from the c->match() functions in the long term (not in this patch set).

> I am going to fix v5 preserving both the check for duplicates
> and the invariant, but tell me please if you prefer the v4 approach.

I guess that you planed to shuffle console_cmdline entries to keep
the preferred console first/last. I am afraid that it won't be
a nice code either. But I might be wrong.


> > The
> > newcon->setup() call is called only when the console matches.
> > AFAIK, there is only one braille console. We should be on
> > the safe side if this one does not implement the match()
> > callback. Or is it even more complicated?
> 
> As you can see from the original code, the check for braille console
> was performed in that branch of code where we missed newcon->match(),
> so yes, it looks like braille console(s) does not have the match() method.
> I used that in v4 to factor out matching for braille from the loop.

The check for blr_options is sufficient and better.

I suggest to wait at least two days until you spend to much time
on reshuffling the code. It is possible that others would prefer
v5 or suggest even other solution.

Best Regards,
Petr

Re: [PATCH v5 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 03/16/2017 04:54 PM, Petr Mladek wrote:
> On Thu 2017-03-16 13:36:35, Aleksey Makarov wrote:
>>
>>
>> On 03/15/2017 07:58 PM, Petr Mladek wrote:
>>> On Wed 2017-03-15 13:28:52, Aleksey Makarov wrote:

[..]

> I personally prefer v4. The braille console adds an unexpected
> twist into the code because it skips the rest of the function.
> IMHO, it is better when it is is tested separately with clear
> conditions and comments.
> 
> I would personally add the following into
> kernel/printk/console_cmdline.h
> 
> #define for_each_console_cmdline(c, i) \
> 	for (i = 0, c = console_cmdline;		\
> 	     i < MAX_CMDLINECONSOLES && c->name[0];	\
> 	     i++, c++)
> 
> It can be used in both __add_preferred_console()
> and register_console().

Ok

> Also I would add the following into kernel/printk/braille.h
> 
> static inline bool
> is_braille_console(struct console_cmdline *c)
> {
> 	return !!c->brl_options;
> }
> 
> Then the braille-specific code in register_console() might
> look like:
> 
> 	/*
> 	 * Braille console is handled a very special way.
> 	 * Is is not listed in the console_drivers list.
> 	 * Instead it registers its own keyboard and vt notifiers.
> 	 *
> 	 * Be careful and avoid calling c->match() here
> 	 * because it might have side effects!
> 	 */
> 	if (is_braille_console(c) &&
> 	    match_console_name(newcon, c) &&
> 	    _braille_register_console(newcon, c))
> 		return;

Yes, this is exactly what I was going to do.

> Finally, I would prefer to move
> 
> 	newcon->flags |= CON_ENABLED;
> 
> outside the match_console() function. The function will still
> have side effects because of the c->match() calls. But we should
> not make it worse. In fact, it would be great to remove side effects
> from the c->match() functions in the long term (not in this patch set).

I see the motivation but I am afraid this is not possible until
side effects are removed from newcon->match() and match_console().
The point is that match_console() also calls newcon->setup() (side effect)
and this CON_ENABLED flag indicates if this call was successful.

>> I am going to fix v5 preserving both the check for duplicates
>> and the invariant, but tell me please if you prefer the v4 approach.
> 
> I guess that you planed to shuffle console_cmdline entries to keep
> the preferred console first/last. I am afraid that it won't be
> a nice code either. But I might be wrong.

You are right, I tried that, the code was awful.

Thank you
Aleksey Makarov

>>> The
>>> newcon->setup() call is called only when the console matches.
>>> AFAIK, there is only one braille console. We should be on
>>> the safe side if this one does not implement the match()
>>> callback. Or is it even more complicated?
>>
>> As you can see from the original code, the check for braille console
>> was performed in that branch of code where we missed newcon->match(),
>> so yes, it looks like braille console(s) does not have the match() method.
>> I used that in v4 to factor out matching for braille from the loop.
> 
> The check for blr_options is sufficient and better.
> 
> I suggest to wait at least two days until you spend to much time
> on reshuffling the code. It is possible that others would prefer
> v5 or suggest even other solution.
> 
> Best Regards,
> Petr
> --
> To unsubscribe from this list: send the line "unsubscribe linux-serial" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

[PATCH v6 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line
parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
then log messages appear twice.

The root cause is that the code traverses the list of specified
consoles (the `console_cmdline` array) and stops at the first match.
But it may happen that the same console is referred by the elements
of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, split the loop where we search for matching entry of
console_cmdline into three parts that do not intersect:
1) search for braille console
2) check for preferred_console
3) match other entries so that these three parts do not

To to that introduce predicate _braille_is_braille_console() that checks if
its argument is an entry describing a braille console.

Also introduce a macro for_each_console_cmdline() to traverse
the console_cmdline array.

Reported-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---

v5 -> v6:
- drop v5 and continue to work on v4:
- introduce _braille_is_braille_console(). It helps to split original loop
  into three parts: 1) search for braille console, 2) check for
  preferred_console, 3) match other entries so that these three parts do not
  intersect.
- introduce for_each_console_cmdline() macros to traverse console_cmdline
  (Petr Mladek)

 kernel/printk/braille.h |  12 ++++++
 kernel/printk/printk.c  | 104 ++++++++++++++++++++++++++++++++++--------------
 2 files changed, 86 insertions(+), 30 deletions(-)

diff --git a/kernel/printk/braille.h b/kernel/printk/braille.h
index 769d771145c8..183aebf6e1dc 100644
--- a/kernel/printk/braille.h
+++ b/kernel/printk/braille.h
@@ -18,6 +18,12 @@ _braille_register_console(struct console *console, struct console_cmdline *c);
 int
 _braille_unregister_console(struct console *console);
 
+static inline int
+_braille_is_braille_console(struct console_cmdline *c)
+{
+	return !!c->brl_options;
+}
+
 #else
 
 static inline void
@@ -43,6 +49,12 @@ _braille_unregister_console(struct console *console)
 	return 0;
 }
 
+static inline int
+_braille_is_braille_console(struct console_cmdline *c)
+{
+	return 0;
+}
+
 #endif
 
 #endif
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd752f0c8ef1..ab2433681ca5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -270,6 +270,11 @@ static struct console *exclusive_console;
 
 static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
 
+#define for_each_console_cmdline(i, c)			\
+	for (i = 0, c = console_cmdline;		\
+	     i < MAX_CMDLINECONSOLES && c->name[0];	\
+	     i++, c++)
+
 static int preferred_console = -1;
 int console_set_on_cmdline;
 EXPORT_SYMBOL(console_set_on_cmdline);
@@ -1905,9 +1910,7 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	 *	See if this tty is not yet registered, and
 	 *	if we have a slot free.
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for_each_console_cmdline(i, c) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
 			if (!brl_options)
 				preferred_console = i;
@@ -2383,6 +2386,37 @@ static int __init keep_bootcon_setup(char *str)
 
 early_param("keep_bootcon", keep_bootcon_setup);
 
+static bool match_console_name(struct console *newcon,
+			       struct console_cmdline *c)
+{
+	BUILD_BUG_ON(sizeof(c->name) != sizeof(newcon->name));
+	if (strcmp(c->name, newcon->name) != 0)
+		return false;
+	if (newcon->index >= 0 && newcon->index != c->index)
+		return false;
+	if (newcon->index < 0)
+		newcon->index = c->index;
+	return true;
+}
+
+static bool match_console(struct console *newcon, struct console_cmdline *c)
+{
+	if (newcon->match &&
+	    newcon->match(newcon, c->name, c->index, c->options) == 0) {
+		newcon->flags |= CON_ENABLED;
+		return true;
+	}
+
+	if (match_console_name(newcon, c)) {
+		if (!newcon->setup || newcon->setup(newcon, c->options) == 0)
+			newcon->flags |= CON_ENABLED;
+
+		return true;
+	}
+
+	return false;
+}
+
 /*
  * The console driver calls this routine during kernel initialization
  * to register the console printing procedure with printk() and to
@@ -2457,40 +2491,50 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 *	See if this console matches one we selected on
-	 *	the command line.
+	 * See if this console matches one we selected on the command line.
+	 * Do it in three steps:
+	 *
+	 * 1) check if it is a braille console..
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
-		if (!newcon->match ||
-		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
-			/* default matching */
-			BUILD_BUG_ON(sizeof(c->name) != sizeof(newcon->name));
-			if (strcmp(c->name, newcon->name) != 0)
-				continue;
-			if (newcon->index >= 0 &&
-			    newcon->index != c->index)
-				continue;
-			if (newcon->index < 0)
-				newcon->index = c->index;
-
-			if (_braille_register_console(newcon, c))
-				return;
-
-			if (newcon->setup &&
-			    newcon->setup(newcon, c->options) != 0)
-				break;
-		}
+	for_each_console_cmdline(i, c)
+		if (_braille_is_braille_console(c) &&
+		    match_console_name(newcon, c) &&
+		    _braille_register_console(newcon, c))
+			return;
 
-		newcon->flags |= CON_ENABLED;
-		if (i == preferred_console) {
+	/*
+	 * 2) check if this console was set as preferred by command line
+	 * parameters or by call to add_preferred_console().  There may be
+	 * several entries in the console_cmdline array matching with the same
+	 * console, one with newcon->match(), another by name/index:
+	 *
+	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
+	 *	ttyAMA0 -- added from command line
+	 *
+	 * so we can not use the first match.  Instead check the
+	 * entry pointed by preferred_console and then all other entries.
+	 */
+	if (preferred_console >= 0 &&
+	    match_console(newcon, console_cmdline + preferred_console)) {
+		if (newcon->flags & CON_ENABLED) {
 			newcon->flags |= CON_CONSDEV;
 			has_preferred = true;
 		}
-		break;
+		goto match;
+	}
+
+	/*
+	 * 3) check other entries
+	 */
+	for_each_console_cmdline(i, c) {
+		if (preferred_console == i || _braille_is_braille_console(c))
+			continue;
+
+		if (match_console(newcon, c))
+			goto match;
 	}
 
+match:
 	if (!(newcon->flags & CON_ENABLED))
 		return;
 
-- 
2.12.0

Re: [PATCH v6 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 03/17/2017 02:43 PM, Aleksey Makarov wrote:

[..]

> @@ -2457,40 +2491,50 @@ void register_console(struct console *newcon)
>  	}
>  
>  	/*
> -	 *	See if this console matches one we selected on
> -	 *	the command line.
> +	 * See if this console matches one we selected on the command line.
> +	 * Do it in three steps:
> +	 *
> +	 * 1) check if it is a braille console..
>  	 */
> -	for (i = 0, c = console_cmdline;
> -	     i < MAX_CMDLINECONSOLES && c->name[0];
> -	     i++, c++) {
> -		if (!newcon->match ||
> -		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
> -			/* default matching */
> -			BUILD_BUG_ON(sizeof(c->name) != sizeof(newcon->name));
> -			if (strcmp(c->name, newcon->name) != 0)
> -				continue;
> -			if (newcon->index >= 0 &&
> -			    newcon->index != c->index)
> -				continue;
> -			if (newcon->index < 0)
> -				newcon->index = c->index;
> -
> -			if (_braille_register_console(newcon, c))
> -				return;
> -
> -			if (newcon->setup &&
> -			    newcon->setup(newcon, c->options) != 0)
> -				break;
> -		}
> +	for_each_console_cmdline(i, c)
> +		if (_braille_is_braille_console(c) &&
> +		    match_console_name(newcon, c) &&
> +		    _braille_register_console(newcon, c))
> +			return;

I am sorry to say that, but it looks like this does not work either.
newcon->index still can be changed here in match_console_name(), 
but (correctly implemented) _braille_register_console() may refuse
to register it, and the changed newcon is passed to newcon->match() below.

I tried the shuffle (i. e. v5) approach again and it seems I managed to
write quite nice code.  I am going to send it in a minute.

Thank you
Aleksey Makarov

> -		newcon->flags |= CON_ENABLED;
> -		if (i == preferred_console) {
> +	/*
> +	 * 2) check if this console was set as preferred by command line
> +	 * parameters or by call to add_preferred_console().  There may be
> +	 * several entries in the console_cmdline array matching with the same
> +	 * console, one with newcon->match(), another by name/index:
> +	 *
> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
> +	 *	ttyAMA0 -- added from command line
> +	 *
> +	 * so we can not use the first match.  Instead check the
> +	 * entry pointed by preferred_console and then all other entries.
> +	 */
> +	if (preferred_console >= 0 &&
> +	    match_console(newcon, console_cmdline + preferred_console)) {
> +		if (newcon->flags & CON_ENABLED) {
>  			newcon->flags |= CON_CONSDEV;
>  			has_preferred = true;
>  		}
> -		break;
> +		goto match;
> +	}
> +
> +	/*
> +	 * 3) check other entries
> +	 */
> +	for_each_console_cmdline(i, c) {
> +		if (preferred_console == i || _braille_is_braille_console(c))
> +			continue;
> +
> +		if (match_console(newcon, c))
> +			goto match;
>  	}
>  
> +match:
>  	if (!(newcon->flags & CON_ENABLED))
>  		return;
>  
> 

[PATCH v7 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line
parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
then log messages appear twice.

The root cause is that the code traverses the list of specified
consoles (the `console_cmdline` array) and stops at the first match.
But it may happen that the same console is referred by the elements
of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, introduce an invariant "The last non-braille console
is always the preferred one" on the entries of the console_cmdline
array.  Then traverse it in reverse order to be sure that if
the console is preferred then it will be the first matching entry.

Reported-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---

v6 -> v7:
- return back to v5 :)
- leave the check for already registered entries and add a function that
  maintains the invariant.

v5 -> v6:
- drop v5 and continue to work on v4:
- introduce _braille_is_braille_console(). It helps to split original loop
  into three parts: 1) search for braille console, 2) check for
  preferred_console, 3) match other entries so that these three parts do not
  intersect.
- introduce for_each_console_cmdline() macros to traverse console_cmdline
  (Petr Mladek)

 kernel/printk/printk.c | 48 ++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 42 insertions(+), 6 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd752f0c8ef1..88f86fb23bc4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1895,6 +1895,34 @@ asmlinkage __visible void early_printk(const char *fmt, ...)
 }
 #endif
 
+/*
+ * This function maintains an invariant that will help to find if
+ * the matching console is preferred, see register_console():
+ *
+ *      The last non-braille console is always the preferred one.
+ */
+static void ensure_preferred_is_last(int i)
+{
+	int last;
+
+	for (last = MAX_CMDLINECONSOLES - 1;
+	     last >= 0 && !console_cmdline[last].name[0];
+	     last--)
+		;
+
+	BUG_ON(last < 0);
+
+	if (i != last) {
+		struct console_cmdline t;
+
+		t = console_cmdline[i];
+		console_cmdline[i] = console_cmdline[last];
+		console_cmdline[last] = t;
+	}
+
+	preferred_console = last;
+}
+
 static int __add_preferred_console(char *name, int idx, char *options,
 				   char *brl_options)
 {
@@ -1910,7 +1938,7 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	     i++, c++) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
 			if (!brl_options)
-				preferred_console = i;
+				ensure_preferred_is_last(i);
 			return 0;
 		}
 	}
@@ -2457,12 +2485,20 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 *	See if this console matches one we selected on
-	 *	the command line.
+	 * See if this console matches one we selected on the command line.
+	 *
+	 * The console_cmdline array is traversed in the reverse order because
+	 * we want to be sure that if this console is preferred then it will be
+	 * the first matching entry.  We use the invariant that is maintained in
+	 * __add_preferred_console().
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for (i = MAX_CMDLINECONSOLES - 1; i >= 0; i--) {
+
+		if (!console_cmdline[i].name[0])
+			continue;
+
+		c = console_cmdline + i;
+
 		if (!newcon->match ||
 		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
 			/* default matching */
-- 
2.12.0

Re: [PATCH v7 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

Hello,

On (03/17/17 16:43), Aleksey Makarov wrote:
[..]
> +static void ensure_preferred_is_last(int i)
> +{
> +	int last;
> +
> +	for (last = MAX_CMDLINECONSOLES - 1;
> +	     last >= 0 && !console_cmdline[last].name[0];
> +	     last--)
> +		;
> +
> +	BUG_ON(last < 0);

let's not panic().


a nitpick, console swap can be done as

	if (i != last)
		swap(console_cmdline[i], console_cmdline[last]);
	preferred_console = last;


		-ss

[PATCH v8 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line
parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
then log messages appear twice.

The root cause is that the code traverses the list of specified
consoles (the `console_cmdline` array) and stops at the first match.
But it may happen that the same console is referred by the elements
of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, introduce an invariant "The last non-braille console
is always the preferred one" on the entries of the console_cmdline
array.  Then traverse it in reverse order to be sure that if
the console is preferred then it will be the first matching entry.

Reported-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---

v7 -> v8:
- add an explanation to the comment how console_cmdline can contain entries
  referring to the same console
- move the body of the function introduced in the previous version to cycle
- don't panic() (Sergey Senozhatsky).  Don't check this condition because
  the loop condition guarantees that it holds.
- use swap() (Sergey Senozhatsky)

v6 -> v7:
- return back to v5 
- leave the check for already registered entries and add a function that
  maintains the invariant.

v5 -> v6:
- drop v5 and continue to work on v4:
- introduce _braille_is_braille_console(). It helps to split original loop
  into three parts: 1) search for braille console, 2) check for
  preferred_console, 3) match other entries so that these three parts do not
  intersect.
- introduce for_each_console_cmdline() macros to traverse console_cmdline
  (Petr Mladek)

 kernel/printk/printk.c | 49 ++++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 42 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd752f0c8ef1..462036e7a767 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1909,8 +1909,28 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	     i < MAX_CMDLINECONSOLES && c->name[0];
 	     i++, c++) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
-			if (!brl_options)
-				preferred_console = i;
+			int last;
+
+			if (brl_options)
+				return 0;
+
+			/*
+			 * Maintain an invariant that will help to find if
+			 * the matching console is preferred, see
+			 * register_console():
+			 *
+			 * The last non-braille console is always
+			 * the preferred one.
+			 */
+			for (last = MAX_CMDLINECONSOLES - 1;
+			     last >= 0 && !console_cmdline[last].name[0];
+			     last--)
+				;
+
+			if (i != last)
+				swap(console_cmdline[i], console_cmdline[last]);
+
+			preferred_console = last;
 			return 0;
 		}
 	}
@@ -2457,12 +2477,27 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 *	See if this console matches one we selected on
-	 *	the command line.
+	 * See if this console matches one we selected on the command line.
+	 *
+	 * There may be several entries in the console_cmdline array matching
+	 * with the same console, one with newcon->match(), another by
+	 * name/index:
+	 *
+	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
+	 *	ttyAMA0 -- added from command line
+	 *
+	 * Traverse the console_cmdline array in reverse order to be
+	 * sure that if this console is preferred then it will be the first
+	 * matching entry.  We use the invariant that is maintained in
+	 * __add_preferred_console().
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for (i = MAX_CMDLINECONSOLES - 1; i >= 0; i--) {
+
+		if (!console_cmdline[i].name[0])
+			continue;
+
+		c = console_cmdline + i;
+
 		if (!newcon->match ||
 		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
 			/* default matching */
-- 
2.12.0

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Mon 2017-03-20 13:03:00, Aleksey Makarov wrote:
> If a console was specified by ACPI SPCR table _and_ command line
> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> then log messages appear twice.
> 
> The root cause is that the code traverses the list of specified
> consoles (the `console_cmdline` array) and stops at the first match.
> But it may happen that the same console is referred by the elements
> of this array twice:
> 
> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
> 	ttyAMA0 -- from command line
> 
> but in this case `preferred_console` points to the second entry and
> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> 
> To fix that, introduce an invariant "The last non-braille console
> is always the preferred one" on the entries of the console_cmdline
> array.  Then traverse it in reverse order to be sure that if
> the console is preferred then it will be the first matching entry.

Sigh, I am afraid that we need to go this way. I hate the side
effects of the match() functions. It would be great to get
rid of them. But it is non-trivial and out of scope for this fix.


> Reported-by: Sudeep Holla <sudeep.holla@arm.com>
> Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fd752f0c8ef1..462036e7a767 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1909,8 +1909,28 @@ static int __add_preferred_console(char *name, int idx, char *options,
>  	     i < MAX_CMDLINECONSOLES && c->name[0];
>  	     i++, c++) {
>  		if (strcmp(c->name, name) == 0 && c->index == idx) {
> -			if (!brl_options)
> -				preferred_console = i;
> +			int last;
> +
> +			if (brl_options)
> +				return 0;
> +
> +			/*
> +			 * Maintain an invariant that will help to find if
> +			 * the matching console is preferred, see
> +			 * register_console():
> +			 *
> +			 * The last non-braille console is always
> +			 * the preferred one.
> +			 */
> +			for (last = MAX_CMDLINECONSOLES - 1;
> +			     last >= 0 && !console_cmdline[last].name[0];
> +			     last--)
> +				;

This is a rather non-trivial code to find the last element.
I might make sense to count it in a global variable.
Then we might remove the check for console_cmdline[i].name[0]
also in the other for cycles and make them better readable.

> +
> +			if (i != last)
> +				swap(console_cmdline[i], console_cmdline[last]);

I was not aware of the swap() function. It is great to know ;-)

Otherwise, I am find with this approach.

Best Regards,
Petr

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 03/27/2017 05:14 PM, Petr Mladek wrote:
> On Mon 2017-03-20 13:03:00, Aleksey Makarov wrote:

[..]

>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index fd752f0c8ef1..462036e7a767 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1909,8 +1909,28 @@ static int __add_preferred_console(char *name, int idx, char *options,
>>  	     i < MAX_CMDLINECONSOLES && c->name[0];
>>  	     i++, c++) {
>>  		if (strcmp(c->name, name) == 0 && c->index == idx) {
>> -			if (!brl_options)
>> -				preferred_console = i;
>> +			int last;
>> +
>> +			if (brl_options)
>> +				return 0;
>> +
>> +			/*
>> +			 * Maintain an invariant that will help to find if
>> +			 * the matching console is preferred, see
>> +			 * register_console():
>> +			 *
>> +			 * The last non-braille console is always
>> +			 * the preferred one.
>> +			 */
>> +			for (last = MAX_CMDLINECONSOLES - 1;
>> +			     last >= 0 && !console_cmdline[last].name[0];
>> +			     last--)
>> +				;
>
> This is a rather non-trivial code to find the last element.
> I might make sense to count it in a global variable.
> Then we might remove the check for console_cmdline[i].name[0]
> also in the other for cycles and make them better readable.

Having an additional variable console_cmdline_last pointing to the last element
would require maintaining consistency between this variable and
contents of console_cmdline.  For the code we have it is not hard, but when code
is changed we need to check this.  Also there exists preferred_console that
has almost the same meaning but it points not to the last element, but to the
last non-braille element.  Also we need to have a special value (-1) for this
variable for empty array. So I personally would instead try to rewrite this:

	for (last = MAX_CMDLINECONSOLES - 1; last >= 0; last--)
		if (console_cmdline[last].name[0])
			break;

Is it better?  If not, I will send a version with console_cmdline_last.

>> +
>> +			if (i != last)
>> +				swap(console_cmdline[i], console_cmdline[last]);
>
> I was not aware of the swap() function. It is great to know ;-)

Yes, same for me.  Thanks to Sergey Senozhatsky.

Thank you for review
Aleksey Makarov

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (03/27/17 19:28), Aleksey Makarov wrote:
[..]
> > > +			/*
> > > +			 * Maintain an invariant that will help to find if
> > > +			 * the matching console is preferred, see
> > > +			 * register_console():
> > > +			 *
> > > +			 * The last non-braille console is always
> > > +			 * the preferred one.
> > > +			 */
> > > +			for (last = MAX_CMDLINECONSOLES - 1;
> > > +			     last >= 0 && !console_cmdline[last].name[0];
> > > +			     last--)
> > > +				;
> > 
> > This is a rather non-trivial code to find the last element.
> > I might make sense to count it in a global variable.
> > Then we might remove the check for console_cmdline[i].name[0]
> > also in the other for cycles and make them better readable.
> 
> Having an additional variable console_cmdline_last pointing to the last element
> would require maintaining consistency between this variable and
> contents of console_cmdline.  For the code we have it is not hard, but when code
> is changed we need to check this.  Also there exists preferred_console that
> has almost the same meaning but it points not to the last element, but to the
> last non-braille element.  Also we need to have a special value (-1) for this
> variable for empty array. So I personally would instead try to rewrite this:
> 
> 	for (last = MAX_CMDLINECONSOLES - 1; last >= 0; last--)
> 		if (console_cmdline[last].name[0])
> 			break;
> 
> Is it better?  If not, I will send a version with console_cmdline_last.

personally I'm fine with the nested loop. the latest version
	"for (last = MAX_CMDLINECONSOLES - 1; last >= 0;..."

is even easier to read.


so we do not just iterate console_cmdline anymore, but also modify it.
this, probably, has impact on the following scenario

CPU0						CPU1

add_preferred_console()			add_preferred_console()
  __add_preferred_console()		  __add_preferred_console()
      swap(i1, last)			    swap(i2, last)

	temp1 = i1
	i1 = last				temp2 = i2
	last = temp1				i2 = last
						last = temp2

so both i1 and i2 will point to 'last' now, IOW, we will have two
identical entries in console_cmdline, while i1 or i2 will be lost.


neither add_preferred_console() nor __add_preferred_console() have any
serialization. and I assume that we can call add_preferred_console()
concurrently, can't we?

	-ss

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Tue 2017-03-28 11:04:04, Sergey Senozhatsky wrote:
> On (03/27/17 19:28), Aleksey Makarov wrote:
> [..]
> > > > +			/*
> > > > +			 * Maintain an invariant that will help to find if
> > > > +			 * the matching console is preferred, see
> > > > +			 * register_console():
> > > > +			 *
> > > > +			 * The last non-braille console is always
> > > > +			 * the preferred one.
> > > > +			 */
> > > > +			for (last = MAX_CMDLINECONSOLES - 1;
> > > > +			     last >= 0 && !console_cmdline[last].name[0];
> > > > +			     last--)
> > > > +				;
> > > 
> > > This is a rather non-trivial code to find the last element.
> > > I might make sense to count it in a global variable.
> > > Then we might remove the check for console_cmdline[i].name[0]
> > > also in the other for cycles and make them better readable.
> > 
> > Having an additional variable console_cmdline_last pointing to the last element
> > would require maintaining consistency between this variable and
> > contents of console_cmdline.  For the code we have it is not hard, but when code
> > is changed we need to check this.  Also there exists preferred_console that
> > has almost the same meaning but it points not to the last element, but to the
> > last non-braille element.  Also we need to have a special value (-1) for this
> > variable for empty array. So I personally would instead try to rewrite this:
> > 
> > 	for (last = MAX_CMDLINECONSOLES - 1; last >= 0; last--)
> > 		if (console_cmdline[last].name[0])
> > 			break;
> > 
> > Is it better?  If not, I will send a version with console_cmdline_last.
> 
> personally I'm fine with the nested loop. the latest version
> 	"for (last = MAX_CMDLINECONSOLES - 1; last >= 0;..."
> 
> is even easier to read.

The number of elements is bumped on a single location, so there
is not much to synchronize. The old approach was fine because
the for cycles were needed anyway, they started on the 0th element,
and NULL ended arrays are rather common practice.

But we are searching the array from the end now. Also we use the
for cycle just to get the number here. This is not a common
practice and it makes the code more complicated and strange from
my point of view.

If you do not like -1, you could use console_cmdline_cnt and
start with 0. I would actually do so because it is a common
approach and easy to understand.

> 
> so we do not just iterate console_cmdline anymore, but also modify it.
> this, probably, has impact on the following scenario
> 
> CPU0						CPU1
> 
> add_preferred_console()			add_preferred_console()
>   __add_preferred_console()		  __add_preferred_console()
>       swap(i1, last)			    swap(i2, last)
> 
> 	temp1 = i1
> 	i1 = last				temp2 = i2
> 	last = temp1				i2 = last
> 						last = temp2
> 
> so both i1 and i2 will point to 'last' now, IOW, we will have two
> identical entries in console_cmdline, while i1 or i2 will be lost.
> 
> 
> neither add_preferred_console() nor __add_preferred_console() have any
> serialization. and I assume that we can call add_preferred_console()
> concurrently, can't we?

Very good point!

Well, if this race exists, it was racy even before. Of course,
the old race was only when new entry was added. It would
be more visible now because also shuffling would be racy.

OK, most add_preferred_console() calls are in functions
that are defined as console_initcall(). They seem to
be defined only when the respective drivers are built in.
It seems that these initcalls are serialized, see console_init().

add_preferred_console() is used also in uart_add_one_port():

   -> uart_add_one_port()
    -> of_console_check()
     -> add_preferred_console()

But there the calls are synchronized as well via
port_mutex.

Finally, __add_preferred_console() is called also from
console_setup(). It is called via do_early_param()
even before the console_initcall() functions. It is
serialized as well.

If I did not miss anything, it would seem that
__add_preferred_console() are called synchronously
and only during boot by design.

Best Regards,
Petr

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (03/28/17 14:56), Petr Mladek wrote:
[..]
> > > Is it better?  If not, I will send a version with console_cmdline_last.
> > 
> > personally I'm fine with the nested loop. the latest version
> > 	"for (last = MAX_CMDLINECONSOLES - 1; last >= 0;..."
> > 
> > is even easier to read.
> 
> The number of elements is bumped on a single location, so there
> is not much to synchronize. The old approach was fine because
> the for cycles were needed anyway, they started on the 0th element,
> and NULL ended arrays are rather common practice.
> 
> But we are searching the array from the end now. Also we use the
> for cycle just to get the number here. This is not a common
> practice and it makes the code more complicated and strange from
> my point of view.

I'm fine with either way :)

[..]
> > neither add_preferred_console() nor __add_preferred_console() have any
> > serialization. and I assume that we can call add_preferred_console()
> > concurrently, can't we?
[..]
> If I did not miss anything, it would seem that
> __add_preferred_console() are called synchronously
> and only during boot by design.

thanks. I think you are right. it's console_initcall or __init.

	-ss

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Thu 2017-03-30 14:55:46, Sergey Senozhatsky wrote:
> On (03/28/17 14:56), Petr Mladek wrote:
> [..]
> > > > Is it better?  If not, I will send a version with console_cmdline_last.
> > > 
> > > personally I'm fine with the nested loop. the latest version
> > > 	"for (last = MAX_CMDLINECONSOLES - 1; last >= 0;..."
> > > 
> > > is even easier to read.
> > 
> > The number of elements is bumped on a single location, so there
> > is not much to synchronize. The old approach was fine because
> > the for cycles were needed anyway, they started on the 0th element,
> > and NULL ended arrays are rather common practice.
> > 
> > But we are searching the array from the end now. Also we use the
> > for cycle just to get the number here. This is not a common
> > practice and it makes the code more complicated and strange from
> > my point of view.
> 
> I'm fine with either way :)

Alekesey, any chance to use the global variable to count used or point
to the last element?

I know that you have already spent a lot of time with it. It was great
work. But the current solution of the cycle looks weird to me.

Best Regards,
Petr

Re: [PATCH v8 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 04/04/2017 02:12 PM, Petr Mladek wrote:
> On Thu 2017-03-30 14:55:46, Sergey Senozhatsky wrote:
>> On (03/28/17 14:56), Petr Mladek wrote:

[..]

> Alekesey, any chance to use the global variable to count used or point
> to the last element?
>
> I know that you have already spent a lot of time with it. It was great
> work. But the current solution of the cycle looks weird to me.

Sorry for the delay.  I will send next version soon.

Thank you
Aleksey Makarov

[PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

If a console was specified by ACPI SPCR table _and_ command line
parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
then log messages appear twice.

The root cause is that the code traverses the list of specified
consoles (the `console_cmdline` array) and stops at the first match.
But it may happen that the same console is referred by the elements
of this array twice:

	pl011,mmio,0x87e024000000,115200 -- from SPCR
	ttyAMA0 -- from command line

but in this case `preferred_console` points to the second entry and
the flag CON_CONSDEV is not set, so bootconsole is not deregistered.

To fix that, introduce an invariant "The last non-braille console
is always the preferred one" on the entries of the console_cmdline
array.  Then traverse it in reverse order to be sure that if
the console is preferred then it will be the first matching entry.
Introduce variable console_cmdline_cnt that keeps the number
of elements of the console_cmdline array (Petr Mladek).  It helps
to get rid of the loop that searches for the end of this array.

Reported-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
---

v8 -> v9:
- Introduce variable console_cmdline_cnt that keeps the number
  of elements of the console_cmdline array (Petr Mladek).  It helps
  to get rid of the loop that searches for the end of this array.
	For the record: I think that this console_cmdline_cnt implementation
	is worse than just a loop that finds the end of the array because 
	1) we have to support consistency between console_cmdline_cnt and
	  console_cmdline_cnt
	2) it makes patch a bit more intrusive

v7 -> v8:
- add an explanation to the comment how console_cmdline can contain entries
  referring to the same console
- move the body of the function introduced in the previous version to cycle
- don't panic() (Sergey Senozhatsky).  Don't check this condition because
  the loop condition guarantees that it holds.
- use swap() (Sergey Senozhatsky)

v6 -> v7:
- return back to v5 
- leave the check for already registered entries and add a function that
  maintains the invariant.

v5 -> v6:
- drop v5 and continue to work on v4:
- introduce _braille_is_braille_console(). It helps to split original loop
  into three parts: 1) search for braille console, 2) check for
  preferred_console, 3) match other entries so that these three parts do not
  intersect.
- introduce for_each_console_cmdline() macros to traverse console_cmdline
  (Petr Mladek)

 kernel/printk/printk.c | 48 ++++++++++++++++++++++++++++++++++++++----------
 1 file changed, 38 insertions(+), 10 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd752f0c8ef1..be657af45758 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -269,6 +269,7 @@ static struct console *exclusive_console;
 #define MAX_CMDLINECONSOLES 8
 
 static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
+static int console_cmdline_cnt;
 
 static int preferred_console = -1;
 int console_set_on_cmdline;
@@ -1905,12 +1906,26 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	 *	See if this tty is not yet registered, and
 	 *	if we have a slot free.
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
-			if (!brl_options)
-				preferred_console = i;
+
+			if (brl_options)
+				return 0;
+
+			/*
+			 * Maintain an invariant that will help to find if
+			 * the matching console is preferred, see
+			 * register_console():
+			 *
+			 * The last non-braille console is always
+			 * the preferred one.
+			 */
+			if (i != console_cmdline_cnt - 1)
+				swap(console_cmdline[i],
+				     console_cmdline[console_cmdline_cnt - 1]);
+
+			preferred_console = console_cmdline_cnt - 1;
+
 			return 0;
 		}
 	}
@@ -1923,6 +1938,7 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	braille_set_options(c, brl_options);
 
 	c->index = idx;
+	console_cmdline_cnt++;
 	return 0;
 }
 /*
@@ -2457,12 +2473,24 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 *	See if this console matches one we selected on
-	 *	the command line.
+	 * See if this console matches one we selected on the command line.
+	 *
+	 * There may be several entries in the console_cmdline array matching
+	 * with the same console, one with newcon->match(), another by
+	 * name/index:
+	 *
+	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
+	 *	ttyAMA0 -- added from command line
+	 *
+	 * Traverse the console_cmdline array in reverse order to be
+	 * sure that if this console is preferred then it will be the first
+	 * matching entry.  We use the invariant that is maintained in
+	 * __add_preferred_console().
 	 */
-	for (i = 0, c = console_cmdline;
-	     i < MAX_CMDLINECONSOLES && c->name[0];
-	     i++, c++) {
+	for (i = console_cmdline_cnt - 1; i >= 0; i--) {
+
+		c = console_cmdline + i;
+
 		if (!newcon->match ||
 		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
 			/* default matching */
-- 
2.12.1

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Andy Shevchenko]

On Wed, Apr 5, 2017 at 11:20 PM, Aleksey Makarov
<aleksey.makarov@linaro.org> wrote:
> If a console was specified by ACPI SPCR table _and_ command line
> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> then log messages appear twice.
>
> The root cause is that the code traverses the list of specified
> consoles (the `console_cmdline` array) and stops at the first match.
> But it may happen that the same console is referred by the elements
> of this array twice:
>
>         pl011,mmio,0x87e024000000,115200 -- from SPCR
>         ttyAMA0 -- from command line
>
> but in this case `preferred_console` points to the second entry and
> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
>
> To fix that, introduce an invariant "The last non-braille console
> is always the preferred one" on the entries of the console_cmdline
> array.  Then traverse it in reverse order to be sure that if
> the console is preferred then it will be the first matching entry.
> Introduce variable console_cmdline_cnt that keeps the number
> of elements of the console_cmdline array (Petr Mladek).  It helps
> to get rid of the loop that searches for the end of this array.

>  #define MAX_CMDLINECONSOLES 8
>
>  static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
> +static int console_cmdline_cnt;

This should be equal to -1 at the beginning, am I right?

>  static int preferred_console = -1;
>  int console_set_on_cmdline;
> @@ -1905,12 +1906,26 @@ static int __add_preferred_console(char *name, int idx, char *options,
>          *      See if this tty is not yet registered, and
>          *      if we have a slot free.
>          */
> -       for (i = 0, c = console_cmdline;
> -            i < MAX_CMDLINECONSOLES && c->name[0];
> -            i++, c++) {
> +       for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
>                 if (strcmp(c->name, name) == 0 && c->index == idx) {
> -                       if (!brl_options)
> -                               preferred_console = i;
> +

> +                       if (brl_options)
> +                               return 0;

Is it invariant or brl_options may appear while looping?

> +
> +                       /*
> +                        * Maintain an invariant that will help to find if
> +                        * the matching console is preferred, see
> +                        * register_console():
> +                        *
> +                        * The last non-braille console is always
> +                        * the preferred one.
> +                        */
> +                       if (i != console_cmdline_cnt - 1)
> +                               swap(console_cmdline[i],
> +                                    console_cmdline[console_cmdline_cnt - 1]);

i'm wondering if you can iterate from the end to beginning as you do below.
It would simplify things.

> +
> +                       preferred_console = console_cmdline_cnt - 1;
> +
>                         return 0;
>                 }
>         }
> @@ -1923,6 +1938,7 @@ static int __add_preferred_console(char *name, int idx, char *options,
>         braille_set_options(c, brl_options);
>
>         c->index = idx;
> +       console_cmdline_cnt++;
>         return 0;
>  }
>  /*
> @@ -2457,12 +2473,24 @@ void register_console(struct console *newcon)
>         }
>
>         /*
> -        *      See if this console matches one we selected on
> -        *      the command line.
> +        * See if this console matches one we selected on the command line.
> +        *
> +        * There may be several entries in the console_cmdline array matching
> +        * with the same console, one with newcon->match(), another by
> +        * name/index:
> +        *
> +        *      pl011,mmio,0x87e024000000,115200 -- added from SPCR
> +        *      ttyAMA0 -- added from command line
> +        *
> +        * Traverse the console_cmdline array in reverse order to be
> +        * sure that if this console is preferred then it will be the first
> +        * matching entry.  We use the invariant that is maintained in
> +        * __add_preferred_console().
>          */
> -       for (i = 0, c = console_cmdline;
> -            i < MAX_CMDLINECONSOLES && c->name[0];
> -            i++, c++) {

> +       for (i = console_cmdline_cnt - 1; i >= 0; i--) {



> +
> +               c = console_cmdline + i;
> +
>                 if (!newcon->match ||
>                     newcon->match(newcon, c->name, c->index, c->options) != 0) {
>                         /* default matching */
> --
> 2.12.1
>



-- 
With Best Regards,
Andy Shevchenko

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 04/06/2017 12:57 AM, Andy Shevchenko wrote:
> On Wed, Apr 5, 2017 at 11:20 PM, Aleksey Makarov
> <aleksey.makarov@linaro.org> wrote:
>> If a console was specified by ACPI SPCR table _and_ command line
>> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
>> then log messages appear twice.
>>
>> The root cause is that the code traverses the list of specified
>> consoles (the `console_cmdline` array) and stops at the first match.
>> But it may happen that the same console is referred by the elements
>> of this array twice:
>>
>>         pl011,mmio,0x87e024000000,115200 -- from SPCR
>>         ttyAMA0 -- from command line
>>
>> but in this case `preferred_console` points to the second entry and
>> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
>>
>> To fix that, introduce an invariant "The last non-braille console
>> is always the preferred one" on the entries of the console_cmdline
>> array.  Then traverse it in reverse order to be sure that if
>> the console is preferred then it will be the first matching entry.
>> Introduce variable console_cmdline_cnt that keeps the number
>> of elements of the console_cmdline array (Petr Mladek).  It helps
>> to get rid of the loop that searches for the end of this array.
>
>>  #define MAX_CMDLINECONSOLES 8
>>
>>  static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
>> +static int console_cmdline_cnt;
>
> This should be equal to -1 at the beginning, am I right?

No, this is not an index of the last element, this is count of
elements of cmdline_console array.  So it is 0 initially.

>>  static int preferred_console = -1;
>>  int console_set_on_cmdline;
>> @@ -1905,12 +1906,26 @@ static int __add_preferred_console(char *name, int idx, char *options,
>>          *      See if this tty is not yet registered, and
>>          *      if we have a slot free.
>>          */
>> -       for (i = 0, c = console_cmdline;
>> -            i < MAX_CMDLINECONSOLES && c->name[0];
>> -            i++, c++) {
>> +       for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
>>                 if (strcmp(c->name, name) == 0 && c->index == idx) {
>> -                       if (!brl_options)
>> -                               preferred_console = i;
>> +
>
>> +                       if (brl_options)
>> +                               return 0;
>
> Is it invariant or brl_options may appear while looping?

I am not sure I understand your question.
If we find that we are registering a braille console that
has already been registered, we just return without updating
preferred console (it is only about regular consoles) and
without swapping it with the last element of the array (because it
is explicitly mentioned in the invariant:  The last
*non-braille* console is always the preferred one)

>> +
>> +                       /*
>> +                        * Maintain an invariant that will help to find if
>> +                        * the matching console is preferred, see
>> +                        * register_console():
>> +                        *
>> +                        * The last non-braille console is always
>> +                        * the preferred one.
>> +                        */
>> +                       if (i != console_cmdline_cnt - 1)
>> +                               swap(console_cmdline[i],
>> +                                    console_cmdline[console_cmdline_cnt - 1]);
>
> i'm wondering if you can iterate from the end to beginning as you do below.
> It would simplify things.

You mean iterate to find the last element?
Yes I can and it is how this was implemented in v8,
Petr Mladek asked to introduce console_cmdline_cnt.

Thank you for review
Aleksey Makarov

>> +
>> +                       preferred_console = console_cmdline_cnt - 1;
>> +
>>                         return 0;
>>                 }
>>         }
>> @@ -1923,6 +1938,7 @@ static int __add_preferred_console(char *name, int idx, char *options,
>>         braille_set_options(c, brl_options);
>>
>>         c->index = idx;
>> +       console_cmdline_cnt++;
>>         return 0;
>>  }
>>  /*
>> @@ -2457,12 +2473,24 @@ void register_console(struct console *newcon)
>>         }
>>
>>         /*
>> -        *      See if this console matches one we selected on
>> -        *      the command line.
>> +        * See if this console matches one we selected on the command line.
>> +        *
>> +        * There may be several entries in the console_cmdline array matching
>> +        * with the same console, one with newcon->match(), another by
>> +        * name/index:
>> +        *
>> +        *      pl011,mmio,0x87e024000000,115200 -- added from SPCR
>> +        *      ttyAMA0 -- added from command line
>> +        *
>> +        * Traverse the console_cmdline array in reverse order to be
>> +        * sure that if this console is preferred then it will be the first
>> +        * matching entry.  We use the invariant that is maintained in
>> +        * __add_preferred_console().
>>          */
>> -       for (i = 0, c = console_cmdline;
>> -            i < MAX_CMDLINECONSOLES && c->name[0];
>> -            i++, c++) {
>
>> +       for (i = console_cmdline_cnt - 1; i >= 0; i--) {
>
>
>
>> +
>> +               c = console_cmdline + i;
>> +
>>                 if (!newcon->match ||
>>                     newcon->match(newcon, c->name, c->index, c->options) != 0) {
>>                         /* default matching */
>> --
>> 2.12.1
>>
>
>
>

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Wed 2017-04-05 23:20:00, Aleksey Makarov wrote:
> If a console was specified by ACPI SPCR table _and_ command line
> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> then log messages appear twice.
> 
> The root cause is that the code traverses the list of specified
> consoles (the `console_cmdline` array) and stops at the first match.
> But it may happen that the same console is referred by the elements
> of this array twice:
> 
> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
> 	ttyAMA0 -- from command line
> 
> but in this case `preferred_console` points to the second entry and
> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> 
> To fix that, introduce an invariant "The last non-braille console
> is always the preferred one" on the entries of the console_cmdline
> array.  Then traverse it in reverse order to be sure that if
> the console is preferred then it will be the first matching entry.
> Introduce variable console_cmdline_cnt that keeps the number
> of elements of the console_cmdline array (Petr Mladek).  It helps
> to get rid of the loop that searches for the end of this array.
> 
> Reported-by: Sudeep Holla <sudeep.holla@arm.com>
> Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>

This version looks fine to me. Just a small nitpick below.
Anyway:

Reviewed-by: Petr Mladek <pmladek@suse.com>

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fd752f0c8ef1..be657af45758 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -269,6 +269,7 @@ static struct console *exclusive_console;
>  #define MAX_CMDLINECONSOLES 8
>  
>  static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
> +static int console_cmdline_cnt;
>  
>  static int preferred_console = -1;
>  int console_set_on_cmdline;
> @@ -1905,12 +1906,26 @@ static int __add_preferred_console(char *name, int idx, char *options,
>  	 *	See if this tty is not yet registered, and
>  	 *	if we have a slot free.
>  	 */
> -	for (i = 0, c = console_cmdline;
> -	     i < MAX_CMDLINECONSOLES && c->name[0];
> -	     i++, c++) {
> +	for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
>  		if (strcmp(c->name, name) == 0 && c->index == idx) {
> -			if (!brl_options)
> -				preferred_console = i;
> +

This extra new line is non-standard and looks slightly weird to me.
I just point it out. I personally do not mind ;-)


> +			if (brl_options)
> +				return 0;
> +
> +			/*
> +			 * Maintain an invariant that will help to find if
> +			 * the matching console is preferred, see
> +			 * register_console():
> +			 *
> +			 * The last non-braille console is always
> +			 * the preferred one.
> +			 */
> +			if (i != console_cmdline_cnt - 1)
> +				swap(console_cmdline[i],
> +				     console_cmdline[console_cmdline_cnt - 1]);
> +
> +			preferred_console = console_cmdline_cnt - 1;
> +
>  			return 0;
>  		}
>  	}
> @@ -2457,12 +2473,24 @@ void register_console(struct console *newcon)
>  	}
>  
>  	/*
> -	 *	See if this console matches one we selected on
> -	 *	the command line.
> +	 * See if this console matches one we selected on the command line.
> +	 *
> +	 * There may be several entries in the console_cmdline array matching
> +	 * with the same console, one with newcon->match(), another by
> +	 * name/index:
> +	 *
> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
> +	 *	ttyAMA0 -- added from command line
> +	 *
> +	 * Traverse the console_cmdline array in reverse order to be
> +	 * sure that if this console is preferred then it will be the first
> +	 * matching entry.  We use the invariant that is maintained in
> +	 * __add_preferred_console().
>  	 */
> -	for (i = 0, c = console_cmdline;
> -	     i < MAX_CMDLINECONSOLES && c->name[0];
> -	     i++, c++) {
> +	for (i = console_cmdline_cnt - 1; i >= 0; i--) {
> +

Same here.

> +		c = console_cmdline + i;
> +
>  		if (!newcon->match ||
>  		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
>  			/* default matching */

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 04/10/2017 05:22 PM, Petr Mladek wrote:
> On Wed 2017-04-05 23:20:00, Aleksey Makarov wrote:
>> If a console was specified by ACPI SPCR table _and_ command line
>> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
>> then log messages appear twice.
>>
>> The root cause is that the code traverses the list of specified
>> consoles (the `console_cmdline` array) and stops at the first match.
>> But it may happen that the same console is referred by the elements
>> of this array twice:
>>
>> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
>> 	ttyAMA0 -- from command line
>>
>> but in this case `preferred_console` points to the second entry and
>> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
>>
>> To fix that, introduce an invariant "The last non-braille console
>> is always the preferred one" on the entries of the console_cmdline
>> array.  Then traverse it in reverse order to be sure that if
>> the console is preferred then it will be the first matching entry.
>> Introduce variable console_cmdline_cnt that keeps the number
>> of elements of the console_cmdline array (Petr Mladek).  It helps
>> to get rid of the loop that searches for the end of this array.
>>
>> Reported-by: Sudeep Holla <sudeep.holla@arm.com>
>> Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
> 
> This version looks fine to me. Just a small nitpick below.
> Anyway:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

Thank you for review.  Can you (or anybody else) ACK it?
I am going to resend the whole series without those empty lines.
May I add your Acked-by:?

Thank you
Aleksey Makarov

>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index fd752f0c8ef1..be657af45758 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -269,6 +269,7 @@ static struct console *exclusive_console;
>>   #define MAX_CMDLINECONSOLES 8
>>   
>>   static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
>> +static int console_cmdline_cnt;
>>   
>>   static int preferred_console = -1;
>>   int console_set_on_cmdline;
>> @@ -1905,12 +1906,26 @@ static int __add_preferred_console(char *name, int idx, char *options,
>>   	 *	See if this tty is not yet registered, and
>>   	 *	if we have a slot free.
>>   	 */
>> -	for (i = 0, c = console_cmdline;
>> -	     i < MAX_CMDLINECONSOLES && c->name[0];
>> -	     i++, c++) {
>> +	for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
>>   		if (strcmp(c->name, name) == 0 && c->index == idx) {
>> -			if (!brl_options)
>> -				preferred_console = i;
>> +
> 
> This extra new line is non-standard and looks slightly weird to me.
> I just point it out. I personally do not mind ;-)
> 
> 
>> +			if (brl_options)
>> +				return 0;
>> +
>> +			/*
>> +			 * Maintain an invariant that will help to find if
>> +			 * the matching console is preferred, see
>> +			 * register_console():
>> +			 *
>> +			 * The last non-braille console is always
>> +			 * the preferred one.
>> +			 */
>> +			if (i != console_cmdline_cnt - 1)
>> +				swap(console_cmdline[i],
>> +				     console_cmdline[console_cmdline_cnt - 1]);
>> +
>> +			preferred_console = console_cmdline_cnt - 1;
>> +
>>   			return 0;
>>   		}
>>   	}
>> @@ -2457,12 +2473,24 @@ void register_console(struct console *newcon)
>>   	}
>>   
>>   	/*
>> -	 *	See if this console matches one we selected on
>> -	 *	the command line.
>> +	 * See if this console matches one we selected on the command line.
>> +	 *
>> +	 * There may be several entries in the console_cmdline array matching
>> +	 * with the same console, one with newcon->match(), another by
>> +	 * name/index:
>> +	 *
>> +	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
>> +	 *	ttyAMA0 -- added from command line
>> +	 *
>> +	 * Traverse the console_cmdline array in reverse order to be
>> +	 * sure that if this console is preferred then it will be the first
>> +	 * matching entry.  We use the invariant that is maintained in
>> +	 * __add_preferred_console().
>>   	 */
>> -	for (i = 0, c = console_cmdline;
>> -	     i < MAX_CMDLINECONSOLES && c->name[0];
>> -	     i++, c++) {
>> +	for (i = console_cmdline_cnt - 1; i >= 0; i--) {
>> +
> 
> Same here.
> 
>> +		c = console_cmdline + i;
>> +
>>   		if (!newcon->match ||
>>   		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
>>   			/* default matching */
> 
> Best Regards,
> Petr
> 

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (04/10/17 21:00), Aleksey Makarov wrote:
> On 04/10/2017 05:22 PM, Petr Mladek wrote:
> > On Wed 2017-04-05 23:20:00, Aleksey Makarov wrote:
[..]
> > > To fix that, introduce an invariant "The last non-braille console
> > > is always the preferred one" on the entries of the console_cmdline
> > > array.  Then traverse it in reverse order to be sure that if
> > > the console is preferred then it will be the first matching entry.
> > > Introduce variable console_cmdline_cnt that keeps the number
> > > of elements of the console_cmdline array (Petr Mladek).  It helps
> > > to get rid of the loop that searches for the end of this array.
> > > 
> > > Reported-by: Sudeep Holla <sudeep.holla@arm.com>
> > > Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
> > 
> > This version looks fine to me. Just a small nitpick below.
> > Anyway:
> > 
> > Reviewed-by: Petr Mladek <pmladek@suse.com>
> 
> Thank you for review.  Can you (or anybody else) ACK it?
> I am going to resend the whole series without those empty lines.
> May I add your Acked-by:?

Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

feel free to resend. I know some setups that have repeating (double)
lines on the serial console, I'll ask people to test the patches.

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Mon 2017-04-10 21:00:35, Aleksey Makarov wrote:
> 
> 
> On 04/10/2017 05:22 PM, Petr Mladek wrote:
> >On Wed 2017-04-05 23:20:00, Aleksey Makarov wrote:
> >>If a console was specified by ACPI SPCR table _and_ command line
> >>parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> >>then log messages appear twice.
> >>
> >>The root cause is that the code traverses the list of specified
> >>consoles (the `console_cmdline` array) and stops at the first match.
> >>But it may happen that the same console is referred by the elements
> >>of this array twice:
> >>
> >>	pl011,mmio,0x87e024000000,115200 -- from SPCR
> >>	ttyAMA0 -- from command line
> >>
> >>but in this case `preferred_console` points to the second entry and
> >>the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> >>
> >>To fix that, introduce an invariant "The last non-braille console
> >>is always the preferred one" on the entries of the console_cmdline
> >>array.  Then traverse it in reverse order to be sure that if
> >>the console is preferred then it will be the first matching entry.
> >>Introduce variable console_cmdline_cnt that keeps the number
> >>of elements of the console_cmdline array (Petr Mladek).  It helps
> >>to get rid of the loop that searches for the end of this array.
> >>
> >>Reported-by: Sudeep Holla <sudeep.holla@arm.com>
> >>Signed-off-by: Aleksey Makarov <aleksey.makarov@linaro.org>
> >
> >This version looks fine to me. Just a small nitpick below.
> >Anyway:
> >
> >Reviewed-by: Petr Mladek <pmladek@suse.com>
> 
> Thank you for review.  Can you (or anybody else) ACK it?
> I am going to resend the whole series without those empty lines.
> May I add your Acked-by:?

Sure. Feel free to use:

Acked-by: Petr Mladek <pmladek@suse.com>

The meaning of the tags is a bit unclear. Acked-by means that
the maintainer agrees with the idea. But it does not necessarily
means that she reviewed the code in details. I agree with the idea
and did the review, so I used the Reviewed-by tag.

Also you do not need to resend the patchset just because the two
empty lines. Sergey agrees. I will wait day or two and push
all three patches into the printk.git if nobody complains
in the meantime. I could remove the two empty lines when doing so.

Thanks a lot for the fix and patience.

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 04/11/2017 10:43 AM, Petr Mladek wrote:
> On Mon 2017-04-10 21:00:35, Aleksey Makarov wrote:
>>
>>
>> On 04/10/2017 05:22 PM, Petr Mladek wrote:
>>> On Wed 2017-04-05 23:20:00, Aleksey Makarov wrote:

[..]

>> Thank you for review.  Can you (or anybody else) ACK it?
>> I am going to resend the whole series without those empty lines.
>> May I add your Acked-by:?
> 
> Sure. Feel free to use:
> 
> Acked-by: Petr Mladek <pmladek@suse.com>
> 
> The meaning of the tags is a bit unclear. Acked-by means that
> the maintainer agrees with the idea. But it does not necessarily
> means that she reviewed the code in details. I agree with the idea
> and did the review, so I used the Reviewed-by tag.
> 
> Also you do not need to resend the patchset just because the two
> empty lines. Sergey agrees. I will wait day or two and push
> all three patches into the printk.git if nobody complains
> in the meantime. I could remove the two empty lines when doing so.

Ok, then I will not resend it.

> Thanks a lot for the fix and patience.

Thank you for reviewing and acking it.
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sabrina Dubroca]

Hi Aleksey,

2017-04-05, 23:20:00 +0300, Aleksey Makarov wrote:
> If a console was specified by ACPI SPCR table _and_ command line
> parameters like "console=ttyAMA0" _and_ "earlycon" were specified,
> then log messages appear twice.
> 
> The root cause is that the code traverses the list of specified
> consoles (the `console_cmdline` array) and stops at the first match.
> But it may happen that the same console is referred by the elements
> of this array twice:
> 
> 	pl011,mmio,0x87e024000000,115200 -- from SPCR
> 	ttyAMA0 -- from command line
> 
> but in this case `preferred_console` points to the second entry and
> the flag CON_CONSDEV is not set, so bootconsole is not deregistered.
> 
> To fix that, introduce an invariant "The last non-braille console
> is always the preferred one" on the entries of the console_cmdline
> array.  Then traverse it in reverse order to be sure that if
> the console is preferred then it will be the first matching entry.
> Introduce variable console_cmdline_cnt that keeps the number
> of elements of the console_cmdline array (Petr Mladek).  It helps
> to get rid of the loop that searches for the end of this array.

That's caused a change of behavior in my qemu setup, with this cmdline

    root=/dev/sda1 console=ttyS1 console=ttyS0

Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
(with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
kernel logs go to ttyS0. I need to swap the two console= parameters to
restore behavior.

There might be some other problem (in qemu?) though, because adding
console=tty0 anywhere on that cmdline makes the logs appear on both
tty0 and one ttyS* (but only one of them, and the ordering of the
ttyS* matters).


Thanks,

-- 
Sabrina

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (05/09/17 10:29), Sabrina Dubroca wrote:
[..]
> That's caused a change of behavior in my qemu setup, with this cmdline
> 
>     root=/dev/sda1 console=ttyS1 console=ttyS0
> 
> Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
> (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
> kernel logs go to ttyS0. I need to swap the two console= parameters to
> restore behavior.
> 
> There might be some other problem (in qemu?) though, because adding
> console=tty0 anywhere on that cmdline makes the logs appear on both
> tty0 and one ttyS* (but only one of them, and the ordering of the
> ttyS* matters).

thanks for the report.

so we have ttyS1 first and ttyS0 last.
after commit in question, register_console() iterates console_cmdline
in reverse order so we see ttyS0 first, then we hit `if (newcon->index < 0)'
condition, set newcon to ttyS0, because we iterate in reverse order now, and
break out. so we enable ttyS0, instead of ttyS1.

previously, we iterated console_cmdline from index 0 and saw ttyS1 first.
so the same `if (newcon->index < 0)' condition would set newcone to ttyS1,
and, thus, we would enable ttyS1, not ttyS0.

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (05/11/17 17:24), Sergey Senozhatsky wrote:
> On (05/09/17 10:29), Sabrina Dubroca wrote:
> [..]
> > That's caused a change of behavior in my qemu setup, with this cmdline
> > 
> >     root=/dev/sda1 console=ttyS1 console=ttyS0
> > 
> > Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
> > (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
> > kernel logs go to ttyS0. I need to swap the two console= parameters to
> > restore behavior.
> > 
> > There might be some other problem (in qemu?) though, because adding
> > console=tty0 anywhere on that cmdline makes the logs appear on both
> > tty0 and one ttyS* (but only one of them, and the ordering of the
> > ttyS* matters).
> 
> thanks for the report.
> 
> so we have ttyS1 first and ttyS0 last.
> after commit in question, register_console() iterates console_cmdline
> in reverse order so we see ttyS0 first, then we hit `if (newcon->index < 0)'
> condition, set newcon to ttyS0, because we iterate in reverse order now, and
> break out. so we enable ttyS0, instead of ttyS1.
> 
> previously, we iterated console_cmdline from index 0 and saw ttyS1 first.
> so the same `if (newcon->index < 0)' condition would set newcone to ttyS1,
> and, thus, we would enable ttyS1, not ttyS0.

Alexey,
can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
and restore the previous register_console() iteration order?

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (05/11/17 17:41), Sergey Senozhatsky wrote:
[..]
> Alexey,
> can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
> and restore the previous register_console() iteration order?

btw, what if someone has configured the system as
console=   non-braille non-braille braille non-braille?
"The last non-braille console is always the preferred one"
is not true in this case.

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 05/11/2017 02:32 PM, Sergey Senozhatsky wrote:
> On (05/11/17 17:41), Sergey Senozhatsky wrote:
> [..]
>> Alexey,
>> can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
>> and restore the previous register_console() iteration order?
> 
> btw, what if someone has configured the system as
> console=   non-braille non-braille braille non-braille?
> "The last non-braille console is always the preferred one"
> is not true in this case.

I don't quite follow what you think is problem here.
The invariant keeps here, the code makes it always true.
In this case the last console is non-braille and it is preferred.
What is the problem?

Thank you
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (05/12/17 00:17), Aleksey Makarov wrote:
> On 05/11/2017 02:32 PM, Sergey Senozhatsky wrote:
> > On (05/11/17 17:41), Sergey Senozhatsky wrote:
> > [..]
> > > Alexey,
> > > can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
> > > and restore the previous register_console() iteration order?
> > 
> > btw, what if someone has configured the system as
> > console=   non-braille non-braille braille non-braille?
> > "The last non-braille console is always the preferred one"
> > is not true in this case.
> 
> I don't quite follow what you think is problem here.

please ignore it, just a long day at the office. sorry.

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 05/11/2017 11:41 AM, Sergey Senozhatsky wrote:
> On (05/11/17 17:24), Sergey Senozhatsky wrote:
>> On (05/09/17 10:29), Sabrina Dubroca wrote:
>> [..]
>>> That's caused a change of behavior in my qemu setup, with this cmdline
>>>
>>>      root=/dev/sda1 console=ttyS1 console=ttyS0
>>>
>>> Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
>>> (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
>>> kernel logs go to ttyS0. I need to swap the two console= parameters to
>>> restore behavior.
>>>
>>> There might be some other problem (in qemu?) though, because adding
>>> console=tty0 anywhere on that cmdline makes the logs appear on both
>>> tty0 and one ttyS* (but only one of them, and the ordering of the
>>> ttyS* matters).
>>
>> thanks for the report.
>>
>> so we have ttyS1 first and ttyS0 last.
>> after commit in question, register_console() iterates console_cmdline
>> in reverse order so we see ttyS0 first, then we hit `if (newcon->index < 0)'
>> condition, set newcon to ttyS0, because we iterate in reverse order now, and
>> break out. so we enable ttyS0, instead of ttyS1.
>>
>> previously, we iterated console_cmdline from index 0 and saw ttyS1 first.
>> so the same `if (newcon->index < 0)' condition would set newcone to ttyS1,
>> and, thus, we would enable ttyS1, not ttyS0.
> 
> Alexey,
> can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
> and restore the previous register_console() iteration order?

I don't quite understand what is the problem.  Give me more time please.
I hope I will be able to look at this on the weekend.

Thank you
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
> On (05/11/17 17:24), Sergey Senozhatsky wrote:
> > On (05/09/17 10:29), Sabrina Dubroca wrote:
> > [..]
> > > That's caused a change of behavior in my qemu setup, with this cmdline
> > > 
> > >     root=/dev/sda1 console=ttyS1 console=ttyS0
> > > 
> > > Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
> > > (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
> > > kernel logs go to ttyS0. I need to swap the two console= parameters to
> > > restore behavior.
> > > 
> > > There might be some other problem (in qemu?) though, because adding
> > > console=tty0 anywhere on that cmdline makes the logs appear on both
> > > tty0 and one ttyS* (but only one of them, and the ordering of the
> > > ttyS* matters).
> > 
> > thanks for the report.
> > 
> > so we have ttyS1 first and ttyS0 last.
> > after commit in question, register_console() iterates console_cmdline
> > in reverse order so we see ttyS0 first, then we hit `if (newcon->index < 0)'
> > condition, set newcon to ttyS0, because we iterate in reverse order now, and
> > break out. so we enable ttyS0, instead of ttyS1.
> > 
> > previously, we iterated console_cmdline from index 0 and saw ttyS1 first.
> > so the same `if (newcon->index < 0)' condition would set newcone to ttyS1,
> > and, thus, we would enable ttyS1, not ttyS0.
> 
> Alexey,
> can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
> and restore the previous register_console() iteration order?

This will not help. ttyS0 is the last console defined on the command
line. Therefore it is the preferred one. It means that it will be
moved to offset 0 and hit first.

I have tried to reproduce the problem and started kernel with
console=ttyS1 console=ttyS0 in qemu. It created:

	console_cmdline = {{
				.name = "ttyS";
				.index = 1;		// from ttyS1
			   },{
				.name = "ttyS"
				.index = 0;		// from ttyS0
			   }};
	preferred_console = 1;		// ttyuS0;


Then register_console() is called twice here. First time
from con_init() that registers:

	static struct console vt_console_driver = {
		.name		= "tty",
		.write		= vt_console_print,
		.device		= vt_console_device,
		.unblank	= unblank_screen,
		.flags		= CON_PRINTBUFFER,
		.index		= -1,
	};

	It does not match and it is not enabled here.


2nd times from univ8250_console_init() that registers:

	static struct console univ8250_console = {
		.name		= "ttyS",
		.write		= univ8250_console_write,
		.device		= uart_console_device,
		.setup		= univ8250_console_setup,
		.match		= univ8250_console_match,
		.flags		= CON_PRINTBUFFER | CON_ANYTIME,
		.index		= -1,
		.data		= &serial8250_reg,
	};

	It matches both console_cmdline entries because index = -1.
	The first tested is selected.


Hmm, I have no idea how to fix this. This is the case where
a registered console matches more entries from the command line.
The fix that caused this regression fixed exactly this situation
and we wanted to make the preferred console first.


In fact, it always was kind of random because both init calls are
defined as

	console_initcall(con_init);
	console_initcall(univ8250_console_init);

They are put into special elf section and called from console_init()
the following way:

	call = __con_initcall_start;
	while (call < __con_initcall_end) {
		(*call)();
		call++;
	}

By other words, the order depends on the linking order which is
kind of weak order enforcement.

I am not sure if we broke some backward compatibility or actually made
it more predictable in the long term.

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Fri 2017-05-12 14:57:29, Petr Mladek wrote:
> On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
> > On (05/11/17 17:24), Sergey Senozhatsky wrote:
> > > On (05/09/17 10:29), Sabrina Dubroca wrote:
> > > [..]
> > > > That's caused a change of behavior in my qemu setup, with this cmdline
> > > > 
> > > >     root=/dev/sda1 console=ttyS1 console=ttyS0
> > > > 
> > > > Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
> > > > (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
> > > > kernel logs go to ttyS0. I need to swap the two console= parameters to
> > > > restore behavior.

Do you actually need to define console=ttyS0 on the cmdline?

IMHO, if register_console() was called for the unix socket, it
would make logs appear on both ttyS0 and ttyS1. It seems
that register_console() is called only for the console that
stores logs into the file.


> > > > adding
> > > > console=tty0 anywhere on that cmdline makes the logs appear on both
> > > > tty0 and one ttyS* (but only one of them, and the ordering of the
> > > > ttyS* matters).

I guess that it worked this way before. I mean that the logs appeared
on both tty0 and one of ttyS*. The only difference should be that
the patch changed the selected ttyS*. So this is still the same problem.


> Hmm, I have no idea how to fix this. This is the case where
> a registered console matches more entries from the command line.
> The fix that caused this regression fixed exactly this situation
> and we wanted to make the preferred console first.
> 
> I am not sure if we broke some backward compatibility or actually made
> it more predictable in the long term.

I think that we actually fixed a very old bug. The last mentioned
console= should be the preferred one and the logs are finally
printed there. Or do I miss anything?

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 05/12/2017 04:46 PM, Petr Mladek wrote:
> On Fri 2017-05-12 14:57:29, Petr Mladek wrote:
>> On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
>>> On (05/11/17 17:24), Sergey Senozhatsky wrote:
>>>> On (05/09/17 10:29), Sabrina Dubroca wrote:
>>>> [..]
>>>>> That's caused a change of behavior in my qemu setup, with this cmdline
>>>>>
>>>>>      root=/dev/sda1 console=ttyS1 console=ttyS0
>>>>>
>>>>> Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
>>>>> (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
>>>>> kernel logs go to ttyS0. I need to swap the two console= parameters to
>>>>> restore behavior.
> 
> Do you actually need to define console=ttyS0 on the cmdline?

Exactly.  You should specify a console on the command line only
if you want kernel logs on it.  It's kernel bug that one of this
consoles does not receive kernel logs, see
Documentation/admin-guide/serial-console.rst

> IMHO, if register_console() was called for the unix socket, it
> would make logs appear on both ttyS0 and ttyS1. It seems
> that register_console() is called only for the console that
> stores logs into the file.

It's not quite accurate sentence.  It's qemu who deals with file/socket and
it is transparent to kernel.

>>>>> adding
>>>>> console=tty0 anywhere on that cmdline makes the logs appear on both
>>>>> tty0 and one ttyS* (but only one of them, and the ordering of the
>>>>> ttyS* matters).
> 
> I guess that it worked this way before. I mean that the logs appeared
> on both tty0 and one of ttyS*. The only difference should be that
> the patch changed the selected ttyS*. So this is still the same problem.
> 
> 
>> Hmm, I have no idea how to fix this. This is the case where
>> a registered console matches more entries from the command line.
>> The fix that caused this regression fixed exactly this situation
>> and we wanted to make the preferred console first.
>>
>> I am not sure if we broke some backward compatibility or actually made
>> it more predictable in the long term.
> 
> I think that we actually fixed a very old bug. The last mentioned
> console= should be the preferred one and the logs are finally
> printed there. Or do I miss anything?

Last mentioned 'console=' (preferred console) is the console that
should become /dev/console.  Its driver is returned by console_device().
In other respects the last mentioned console is not special,
so I believe it is irrelevant to the report.

Thank you
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (05/12/17 14:57), Petr Mladek wrote:
[..]
> I have tried to reproduce the problem and started kernel with
> console=ttyS1 console=ttyS0 in qemu. It created:
> 
> 	console_cmdline = {{
> 				.name = "ttyS";
> 				.index = 1;		// from ttyS1
> 			   },{
> 				.name = "ttyS"
> 				.index = 0;		// from ttyS0
> 			   }};
> 	preferred_console = 1;		// ttyuS0;
> 
> 
> Then register_console() is called twice here. First time
> from con_init() that registers:
> 
> 	static struct console vt_console_driver = {
> 		.name		= "tty",
> 		.write		= vt_console_print,
> 		.device		= vt_console_device,
> 		.unblank	= unblank_screen,
> 		.flags		= CON_PRINTBUFFER,
> 		.index		= -1,
> 	};
> 
> 	It does not match and it is not enabled here.
> 
> 
> 2nd times from univ8250_console_init() that registers:
> 
> 	static struct console univ8250_console = {
> 		.name		= "ttyS",
> 		.write		= univ8250_console_write,
> 		.device		= uart_console_device,
> 		.setup		= univ8250_console_setup,
> 		.match		= univ8250_console_match,
> 		.flags		= CON_PRINTBUFFER | CON_ANYTIME,
> 		.index		= -1,
> 		.data		= &serial8250_reg,
> 	};
> 
> 	It matches both console_cmdline entries because index = -1.
> 	The first tested is selected.

yes, that's what I observed on my host. I didn't try it with qemu,
just 86_64. and the behaviour was different.

[..]
> In fact, it always was kind of random because both init calls are
> defined as
> 
> 	console_initcall(con_init);
> 	console_initcall(univ8250_console_init);
> 
> They are put into special elf section and called from console_init()
> the following way:
> 
> 	call = __con_initcall_start;
> 	while (call < __con_initcall_end) {
> 		(*call)();
> 		call++;
> 	}
> 
> By other words, the order depends on the linking order which is
> kind of weak order enforcement.
> 
> I am not sure if we broke some backward compatibility or actually made
> it more predictable in the long term.

well, we changed the behaviour. some automated scripts somewhere might
get broken. so may be this is the case when "a bug" becomes "a feature".
well, just saying.

	-ss

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 05/12/2017 03:57 PM, Petr Mladek wrote:
> On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
>> On (05/11/17 17:24), Sergey Senozhatsky wrote:
>>> On (05/09/17 10:29), Sabrina Dubroca wrote:
>>> [..]
>>>> That's caused a change of behavior in my qemu setup, with this cmdline
>>>>
>>>>      root=/dev/sda1 console=ttyS1 console=ttyS0
>>>>
>>>> Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
>>>> (with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
>>>> kernel logs go to ttyS0. I need to swap the two console= parameters to
>>>> restore behavior.
>>>>
>>>> There might be some other problem (in qemu?) though, because adding
>>>> console=tty0 anywhere on that cmdline makes the logs appear on both
>>>> tty0 and one ttyS* (but only one of them, and the ordering of the
>>>> ttyS* matters).
>>>
>>> thanks for the report.
>>>
>>> so we have ttyS1 first and ttyS0 last.
>>> after commit in question, register_console() iterates console_cmdline
>>> in reverse order so we see ttyS0 first, then we hit `if (newcon->index < 0)'
>>> condition, set newcon to ttyS0, because we iterate in reverse order now, and
>>> break out. so we enable ttyS0, instead of ttyS1.
>>>
>>> previously, we iterated console_cmdline from index 0 and saw ttyS1 first.
>>> so the same `if (newcon->index < 0)' condition would set newcone to ttyS1,
>>> and, thus, we would enable ttyS1, not ttyS0.
>>
>> Alexey,
>> can we have preferred console at offset 0 (not at console_cmdline_cnt - 1)
>> and restore the previous register_console() iteration order?
> 
> This will not help. ttyS0 is the last console defined on the command
> line. Therefore it is the preferred one. It means that it will be
> moved to offset 0 and hit first.
> 
> I have tried to reproduce the problem and started kernel with
> console=ttyS1 console=ttyS0 in qemu. It created:
> 
> 	console_cmdline = {{
> 				.name = "ttyS";
> 				.index = 1;		// from ttyS1
> 			   },{
> 				.name = "ttyS"
> 				.index = 0;		// from ttyS0
> 			   }};
> 	preferred_console = 1;		// ttyuS0;
> 
> 
> Then register_console() is called twice here. First time
> from con_init() that registers:
> 
> 	static struct console vt_console_driver = {
> 		.name		= "tty",
> 		.write		= vt_console_print,
> 		.device		= vt_console_device,
> 		.unblank	= unblank_screen,
> 		.flags		= CON_PRINTBUFFER,
> 		.index		= -1,
> 	};
> 
> 	It does not match and it is not enabled here.
> 
> 
> 2nd times from univ8250_console_init() that registers:
> 
> 	static struct console univ8250_console = {
> 		.name		= "ttyS",
> 		.write		= univ8250_console_write,
> 		.device		= uart_console_device,
> 		.setup		= univ8250_console_setup,
> 		.match		= univ8250_console_match,
> 		.flags		= CON_PRINTBUFFER | CON_ANYTIME,
> 		.index		= -1,
> 		.data		= &serial8250_reg,
> 	};
> 
> 	It matches both console_cmdline entries because index = -1.
> 	The first tested is selected.
> 
> 
> Hmm, I have no idea how to fix this. This is the case where
> a registered console matches more entries from the command line.
> The fix that caused this regression fixed exactly this situation
> and we wanted to make the preferred console first.

The problem is that when we are registering a new console,
we walk over the `console_cmdline` list and match _only one_ of
the specified consoles, contrary to what stated in
Documentation/admin-guide/serial-console.rst:

	You can specify multiple console= options on the kernel
	command line. Output will appear on *all* of them.

I emphasized all here.  Moreover, it is impossible to fix this
without deep reworking of all the console framework.

So specifying same console twice (with different lines) is pointless --
only one of them will be used for kernel logs.  You don't have to
specify it in command line if you just want to login on it
and don't want to see kernel logs on it.

> In fact, it always was kind of random because both init calls are
> defined as
> 
> 	console_initcall(con_init);
> 	console_initcall(univ8250_console_init);
> 
> They are put into special elf section and called from console_init()
> the following way:
> 
> 	call = __con_initcall_start;
> 	while (call < __con_initcall_end) {
> 		(*call)();
> 		call++;
> 	}
> 
> By other words, the order depends on the linking order which is
> kind of weak order enforcement.

The order in which consoles are registered is not relevant.
It's command line parameters order that matters.

> I am not sure if we broke some backward compatibility or actually made
> it more predictable in the long term.

I believe that we broke the way an old unfixed bug shows itself.

But reproducing this bug requires to specify the same console
in command line twice (with different lines), which is pointless
so I would say it is irrelevant.

Thank you
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Sun 2017-05-14 23:37:50, Aleksey Makarov wrote:
> 
> 
> On 05/12/2017 03:57 PM, Petr Mladek wrote:
> >On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
> >>On (05/11/17 17:24), Sergey Senozhatsky wrote:
> >>>On (05/09/17 10:29), Sabrina Dubroca wrote:
> >>>[..]
> >>>>That's caused a change of behavior in my qemu setup, with this cmdline
> >>>>
> >>>>     root=/dev/sda1 console=ttyS1 console=ttyS0
> >>>>
> >>>>Before, the kernel logs appeared on ttyS1, and I logged in with ttyS0
> >>>>(with my setup, ttyS1 is a file and ttyS0 is unix socket). Now, the
> >>>>kernel logs go to ttyS0. I need to swap the two console= parameters to
> >>>>restore behavior.
> >>>>
> >>>>There might be some other problem (in qemu?) though, because adding
> >>>>console=tty0 anywhere on that cmdline makes the logs appear on both
> >>>>tty0 and one ttyS* (but only one of them, and the ordering of the
> >>>>ttyS* matters).
> >>>
> 
> The problem is that when we are registering a new console,
> we walk over the `console_cmdline` list and match _only one_ of
> the specified consoles, contrary to what stated in
> Documentation/admin-guide/serial-console.rst:
> 
> 	You can specify multiple console= options on the kernel
> 	command line. Output will appear on *all* of them.

and from the other mail:

> Last mentioned 'console=' (preferred console) is the console that
> should become /dev/console.  Its driver is returned by console_device().
> In other respects the last mentioned console is not special,
> so I believe it is irrelevant to the report.

Thanks a lot for explanation. I missed these pieces.

But this also means that your commit cf39bf58afdaabc0b
("printk: fix double printing with earlycon") helps only
when the duplicate of the boot console is defined as the preferred
one.

Well, the reverse order of searching the console_cmdline
might help also in other cases but it is weird approach.


> I emphasized all here.  Moreover, it is impossible to fix this
> without deep reworking of all the console framework.

IMHO, the same is true also for fixing the bug with double
printing correctly. The current fix helps in some situations
but it might break others. The question is how many people will
see the good and "bad" effects.

BTW: I wonder if we really need to add consoles defined
by ACPI SPCR table into the console_cmdline array. I am even
more curious when seeing the following code in
drivers/acpi/spcr.c:

int __init parse_spcr(bool earlycon)
{
[...]
	if (earlycon)
		setup_earlycon(opts);

	err = add_preferred_console(uart, 0, opts + strlen(uart) + 1);
}

It seems that we setup (register) the early console before
we add it to the console_cmdline array. Do we really need
to call add_preferred_console() for these early consoles?

If we do not call add_preferred_console() here, it should fix
the duplicate output as well. Or do I still miss something?

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Aleksey Makarov]

On 05/18/2017 06:49 PM, Petr Mladek wrote:
> On Sun 2017-05-14 23:37:50, Aleksey Makarov wrote:
>> 
>> 
>> On 05/12/2017 03:57 PM, Petr Mladek wrote:
>>> On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
>>>> On (05/11/17 17:24), Sergey Senozhatsky wrote:
>>>>> On (05/09/17 10:29), Sabrina Dubroca wrote: [..]
>>>>>> That's caused a change of behavior in my qemu setup, with
>>>>>> this cmdline
>>>>>> 
>>>>>> root=/dev/sda1 console=ttyS1 console=ttyS0
>>>>>> 
>>>>>> Before, the kernel logs appeared on ttyS1, and I logged in
>>>>>> with ttyS0 (with my setup, ttyS1 is a file and ttyS0 is
>>>>>> unix socket). Now, the kernel logs go to ttyS0. I need to
>>>>>> swap the two console= parameters to restore behavior.
>>>>>> 
>>>>>> There might be some other problem (in qemu?) though,
>>>>>> because adding console=tty0 anywhere on that cmdline makes
>>>>>> the logs appear on both tty0 and one ttyS* (but only one of
>>>>>> them, and the ordering of the ttyS* matters).
>>>>> 
>> 
>> The problem is that when we are registering a new console, we walk
>> over the `console_cmdline` list and match _only one_ of the
>> specified consoles, contrary to what stated in 
>> Documentation/admin-guide/serial-console.rst:
>> 
>> You can specify multiple console= options on the kernel command
>> line. Output will appear on *all* of them.
> 
> and from the other mail:
> 
>> Last mentioned 'console=' (preferred console) is the console that 
>> should become /dev/console.  Its driver is returned by
>> console_device(). In other respects the last mentioned console is
>> not special, so I believe it is irrelevant to the report.
> 
> Thanks a lot for explanation. I missed these pieces.
> 
> But this also means that your commit cf39bf58afdaabc0b ("printk: fix
> double printing with earlycon") helps only when the duplicate of the
> boot console is defined as the preferred one.
> 
> Well, the reverse order of searching the console_cmdline might help
> also in other cases but it is weird approach.
> 
> 
>> I emphasized all here.  Moreover, it is impossible to fix this 
>> without deep reworking of all the console framework.
> 
> IMHO, the same is true also for fixing the bug with double printing
> correctly. The current fix helps in some situations but it might
> break others. The question is how many people will see the good and
> "bad" effects.

I meant that it is difficult to fix the bug that only one line
(first matched) of registered console device receives kernel logs.
That is because of 'index' field of struct console can refer to only one
tty line.

I re-evaluated the "printk: fix double printing with earlycon"
patch and still think it is ok as it breaks only situations
that should not happen, when different lines of the same
console are registered in console_cmdline. But I agree that
someone else with more experience should decide.

- The reason why logs appear twice is that earlycon is not
deregistered after non-early consoles are available.

- Earlycon is not deregistered because in some cases
flag CON_CONSDEV is not set for any of the new non-early
consoles.

- That flag is not set when two entries of console_cmdline
array refer to the same console.  We match the first entry,
it is not preferred and the flag CON_CONSDEV is set only
for preferred console.

- So I changed the order of array walk so that if there
are two entries referring to the same console, last one is matched.
If we specify a console as prefered (last entry in command line)
that means that we expect a driver will eventually register
its console and for that driver we will match the last
entry and the earlycon will be deregistered.

- The subtle question is why we deregister earlycon only
when CON_CONSDEV is set (i. e. only for preferred console).
That check for CON_CONSDEV was initially introduced in

d37bf60de0b4 console: console handover to preferred console

and then refactored in

4d09161196c9 printk: Enable the use of more than one CON_BOOT (early console)
8259cf434202 printk: Ensure that "console enabled" messages are printed on the console

The reason is that some consoles can be registered later or earlier
and if we deregister earlycon when the first non-early console
is registered, we can lose some lines of log.  To prevent that
we specify the console *which is being watched* as preferred
(the last console in the console_cmdline array) and
deregister earlycon only when kernel registers its driver.

> BTW: I wonder if we really need to add consoles defined by ACPI SPCR
> table into the console_cmdline array.

The console_cmdline array is the place where we add descriptions
of consoles that should receive log output.  ACPI SPCR specifies exactly
that information, and I believe it should go to that array.
I don't quite follow your concern.

> I am even more curious when
> seeing the following code in drivers/acpi/spcr.c:
> 
> int __init parse_spcr(bool earlycon) { [...] if (earlycon) 
> setup_earlycon(opts);
> 
> err = add_preferred_console(uart, 0, opts + strlen(uart) + 1); }
> 
> It seems that we setup (register) the early console before we add it
> to the console_cmdline array. Do we really need to call
> add_preferred_console() for these early consoles?

Yes we need.  When we setup an earlycon, we enable output
to that console immediately.  Drivers can register its real
non-early consoles much later so we just add description
of that consoles to the console_cmdline arraly so that
when the driver registers a matching driver, earlycon is replaced
by a regular device.  Or maybe I don't understand your concern here.

> If we do not call add_preferred_console() here, it should fix the
> duplicate output as well. Or do I still miss something?

Yes it will "fix", but the output will be from earlycon.
We want to replace earlycon with non-early console eventually
and that is why we call add_preferred_console() here.

Thank you
Aleksey Makarov

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Fri 2017-05-26 12:37:12, Aleksey Makarov wrote:
> 
> 
> On 05/18/2017 06:49 PM, Petr Mladek wrote:
> >On Sun 2017-05-14 23:37:50, Aleksey Makarov wrote:
> >>
> >>
> >>On 05/12/2017 03:57 PM, Petr Mladek wrote:
> >>>On Thu 2017-05-11 17:41:58, Sergey Senozhatsky wrote:
> I meant that it is difficult to fix the bug that only one line
> (first matched) of registered console device receives kernel logs.
> That is because of 'index' field of struct console can refer to only one
> tty line.

I think that bigger problem is that con->match() functions have
side effects and we could not try matching all consoles
mentioned in console_cmdline. Otherwise, we would be able
to enable all mentioned ttyS* drivers that are listed.


> - The reason why logs appear twice is that earlycon is not
> deregistered after non-early consoles are available.

OK

> - Earlycon is not deregistered because in some cases
> flag CON_CONSDEV is not set for any of the new non-early
> consoles.

This is one explanation. Another reason might be that
an early console is added into console_cmdline by mistake.
By other words, if early consoles are not mentioned in
console_cmdline we could not mismatch them with the normal
console. See below for more on this idea.


> - That flag is not set when two entries of console_cmdline
> array refer to the same console.  We match the first entry,
> it is not preferred and the flag CON_CONSDEV is set only
> for preferred console.
> 
> - So I changed the order of array walk so that if there
> are two entries referring to the same console, last one is matched.
> If we specify a console as prefered (last entry in command line)
> that means that we expect a driver will eventually register
> its console and for that driver we will match the last
> entry and the earlycon will be deregistered.

This still handles the problem only for the preferred (last entry
in command line) console. In theory, there might be more consoles
listed twice.


> - The subtle question is why we deregister earlycon only
> when CON_CONSDEV is set (i. e. only for preferred console).
> That check for CON_CONSDEV was initially introduced in
> 
> d37bf60de0b4 console: console handover to preferred console
> 
> and then refactored in
> 
> 4d09161196c9 printk: Enable the use of more than one CON_BOOT (early console)
> 8259cf434202 printk: Ensure that "console enabled" messages are printed on the console
> 
> The reason is that some consoles can be registered later or earlier
> and if we deregister earlycon when the first non-early console
> is registered, we can lose some lines of log.  To prevent that
> we specify the console *which is being watched* as preferred
> (the last console in the console_cmdline array) and
> deregister earlycon only when kernel registers its driver.

Good to know. Thanks a lot for the archaeology.


> >BTW: I wonder if we really need to add consoles defined by ACPI SPCR
> >table into the console_cmdline array.
> 
> The console_cmdline array is the place where we add descriptions
> of consoles that should receive log output. ACPI SPCR specifies exactly
> that information, and I believe it should go to that array.

Are consoles defined by earlycon= command line parameter
added to console_cmdline? I do not see this anywhere in
the following functions:

  + param_setup_earlycon()
  + setup_earlycon()
  + register_earlycon()
  + early_init_dt_scan_chosen_stdout()
  + of_setup_earlycon()

IMHO, the main question is whether the console defined by
ACPI SPCR is early or normal one. IMHO, it is early console
and it should be handled the same way as the other early
consoles.


> >I am even more curious when
> >seeing the following code in drivers/acpi/spcr.c:
> >
> >int __init parse_spcr(bool earlycon) { [...] if (earlycon)
> >setup_earlycon(opts);

setup_early() calls register_earlycon() when the console is
found in __earlycon_table. Then it calls register_console().

I guess that the console is enabled here because we do not
have preferred cosole when this is called. Therefore it is
enabled by the following code:

	/*
	 *	See if we want to use this console driver. If we
	 *	didn't select a console we take the first one
	 *	that registers here.
	 */
	if (!has_preferred) {
		if (newcon->index < 0)
			newcon->index = 0;
		if (newcon->setup == NULL ||
		    newcon->setup(newcon, NULL) == 0) {
			newcon->flags |= CON_ENABLED;
			if (newcon->device) {
				newcon->flags |= CON_CONSDEV;
				has_preferred = true;
			}

Note that it gets enabled without being listed in console_cmdline.

> >err = add_preferred_console(uart, 0, opts + strlen(uart) + 1); }

Then it is added to the console_cmdline after being enabled.
Let's discuss why below.

> >Do we really need to call add_preferred_console() for
> these early consoles?
> 
> Yes we need.

Why exactly?

> When we setup an earlycon, we enable output
> to that console immediately.  Drivers can register its real
> non-early consoles much later so we just add description
> of that consoles to the console_cmdline arraly so that
> when the driver registers a matching driver, earlycon is replaced
> by a regular device.

console_cmdline is used to match the newly registered consoles.
If it matches and newcon->setup() succeeds, the console is enabled.
Why do we need to match the new consoles with the already
registered and enabled one?

Please, note that the early consoles are disabled using
the "console_drivers" list. They do not need to be listed in
"console_cmdline" to be disabled.

Do I miss something?

Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Thu 2017-06-01 14:03:25, Petr Mladek wrote:
> On Fri 2017-05-26 12:37:12, Aleksey Makarov wrote:
> > The console_cmdline array is the place where we add descriptions
> > of consoles that should receive log output. ACPI SPCR specifies exactly
> > that information, and I believe it should go to that array.
> 
> Are consoles defined by earlycon= command line parameter
> added to console_cmdline? I do not see this anywhere in
> the following functions:
> 
>   + param_setup_earlycon()
>   + setup_earlycon()
>   + register_earlycon()
>   + early_init_dt_scan_chosen_stdout()
>   + of_setup_earlycon()
> 
> IMHO, the main question is whether the console defined by
> ACPI SPCR is early or normal one.

The answer is that it depends. The console defined by ACPI
SPCR is early when just 'earlycon' is defined on the command
line. See param_setup_earlycon() and the use of
earlycon_init_is_deferred. Otherwise, it is supposed to
be a normal console.

We need to call add_preferred_console() in parse_spcr()
to allow using the console as a normal one.

We must also work correctly when the user explicitly defines
the console on the command line, using another alias.

As a result, we could not easily prevent having two matching consoles
in console_cmdline list. And as long as the last mentioned console
has the special status (preferred_console, CON_CONSDEV), it would
make sense to try matching the preferred console first.

Sadly, it causes the change of the behavior of ttyS0 and ttyS1.


Now, systemd seems to handle the console= parameters as well.
According to http://0pointer.de/blog/projects/serial-console.html,
systemd instantiates one serial-getty@.service on the preferred
(last mentioned) console.

This might be a reason to define both console=ttyS0 console=ttyS1
on the command line. People might actually want to get the logs
and the login prompt on different console.

Well, it is a bug that kernel shows the messages only on one
console.


There is one more thing that I found. Early consoles are forcefully
removed in a late_initcall(printk_late_init). It happens when they
use a code that is discarded after all initcalls finishes.
This has two effects.

First, boot consoles are removed even when the preferred one
is not registered. This explains why we need to call both
setup_earlycon() and add_preferred_console() in parse_spcr().

Second, the boot console might be removed before the normal/preferred
one is registered. For example, the normal one might be registered later
by a deferred probe call. As a result, the normal console might miss
that there was an early one, replays the entire log, and you
might see the beginning of the log twice.


All in all, I think that I have finally understood what
Aleksey wanted to say in his great summary, see
https://lkml.kernel.org/r/4e679bec-4804-9791-fc2b-0e96ad67d511@linaro.org
My proposed solution in parse_spcr() do not fly.

And I am still undecided about the Alexey's patch:

  + the patch makes some sense

  + but people might see the changed order as regressions;
    there might be more users, especially because of systemd

  + IMHO, the patch fixed the duplicit output only partly;
    it would not help when the normal console is registered
    later


Best Regards,
Petr

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Petr Mladek]

On Tue 2017-06-06 16:31:49, Petr Mladek wrote:
> On Thu 2017-06-01 14:03:25, Petr Mladek wrote:
> Now, systemd seems to handle the console= parameters as well.
> According to http://0pointer.de/blog/projects/serial-console.html,
> systemd instantiates one serial-getty@.service on the preferred
> (last mentioned) console.
> 
> This might be a reason to define both console=ttyS0 console=ttyS1
> on the command line. People might actually want to get the logs
> and the login prompt on different console.

I have consulted this with a colleague. I am sorry to say but we
believe that this fits into the category of breaking userspace
(systemd, qemu). I would like to revert the patch ASAP,
before rc5. Here is a proposal of the commit message:


>From 142d75792d0df874e80493654311f69f6a1ca798 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 6 Jun 2017 17:20:38 +0200
Subject: [PATCH] Revert "printk: fix double printing with earlycon"

The commit cf39bf58afdaabc ("printk: fix double printing with earlycon")
caused regression to users that define both console=ttyS1 and console=ttyS0
on the command line, see
https://lkml.kernel.org/r/20170509082915.GA13236@bistromath.localdomain

The kernel log messages always appeared only on one serial port. It is
even documented in Documentation/admin-guide/serial-console.rst:

"Note that you can only define one console per device type (serial,
video)."

The above mentioned commit changed the order in which the command line
parameters are searched. As a result, the kernel log messages go to
the last mentioned ttyS* instead of the first one.

We long thought that using two console=ttyS* on the command line
did not make sense. But then we realized that console= parameters
were handled also by systemd, see
http://0pointer.de/blog/projects/serial-console.html

"By default systemd will instantiate one serial-getty@.service on
the main kernel console, if it is not a virtual terminal."

where

"[4] If multiple kernel consoles are used simultaneously, the main
console is the one listed first in /sys/class/tty/console/active,
which is the last one listed on the kernel command line."

This puts the original report into another light. The system is running
in qemu. The first serial port is used to store the messages into a file.
The second one is used to login to the system via a socket. It depends
on systemd and the historic kernel behavior.

By other words, systemd causes that it makes sense to define both
console=ttyS1 console=ttyS0 on the command line. The kernel fix
caused regression related to userspace (systemd) and need to be
reverted.

In addition, it went out that the fix helped only partially.
The messages still were duplicated when the boot console was
removed early by late_initcall(printk_late_init). Then the entire
log was replayed when the same console was registered as a normal one.

This reverts commit cf39bf58afdaabc0b86f141630fb3fd18190294e.
---
 kernel/printk/printk.c | 46 ++++++++++------------------------------------
 1 file changed, 10 insertions(+), 36 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a1aecf44ab07..a1db38abac5b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -269,7 +269,6 @@ static void __up_console_sem(unsigned long ip)
 #define MAX_CMDLINECONSOLES 8
 
 static struct console_cmdline console_cmdline[MAX_CMDLINECONSOLES];
-static int console_cmdline_cnt;
 
 static int preferred_console = -1;
 int console_set_on_cmdline;
@@ -1906,25 +1905,12 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	 *	See if this tty is not yet registered, and
 	 *	if we have a slot free.
 	 */
-	for (i = 0, c = console_cmdline; i < console_cmdline_cnt; i++, c++) {
+	for (i = 0, c = console_cmdline;
+	     i < MAX_CMDLINECONSOLES && c->name[0];
+	     i++, c++) {
 		if (strcmp(c->name, name) == 0 && c->index == idx) {
-			if (brl_options)
-				return 0;
-
-			/*
-			 * Maintain an invariant that will help to find if
-			 * the matching console is preferred, see
-			 * register_console():
-			 *
-			 * The last non-braille console is always
-			 * the preferred one.
-			 */
-			if (i != console_cmdline_cnt - 1)
-				swap(console_cmdline[i],
-				     console_cmdline[console_cmdline_cnt - 1]);
-
-			preferred_console = console_cmdline_cnt - 1;
-
+			if (!brl_options)
+				preferred_console = i;
 			return 0;
 		}
 	}
@@ -1937,7 +1923,6 @@ static int __add_preferred_console(char *name, int idx, char *options,
 	braille_set_options(c, brl_options);
 
 	c->index = idx;
-	console_cmdline_cnt++;
 	return 0;
 }
 /*
@@ -2477,23 +2462,12 @@ void register_console(struct console *newcon)
 	}
 
 	/*
-	 * See if this console matches one we selected on the command line.
-	 *
-	 * There may be several entries in the console_cmdline array matching
-	 * with the same console, one with newcon->match(), another by
-	 * name/index:
-	 *
-	 *	pl011,mmio,0x87e024000000,115200 -- added from SPCR
-	 *	ttyAMA0 -- added from command line
-	 *
-	 * Traverse the console_cmdline array in reverse order to be
-	 * sure that if this console is preferred then it will be the first
-	 * matching entry.  We use the invariant that is maintained in
-	 * __add_preferred_console().
+	 *	See if this console matches one we selected on
+	 *	the command line.
 	 */
-	for (i = console_cmdline_cnt - 1; i >= 0; i--) {
-		c = console_cmdline + i;
-
+	for (i = 0, c = console_cmdline;
+	     i < MAX_CMDLINECONSOLES && c->name[0];
+	     i++, c++) {
 		if (!newcon->match ||
 		    newcon->match(newcon, c->name, c->index, c->options) != 0) {
 			/* default matching */
-- 
1.8.5.6

Re: [PATCH v9 3/3] printk: fix double printing with earlycon

[Sergey Senozhatsky]

On (06/06/17 18:03), Petr Mladek wrote:
[..]
> From 142d75792d0df874e80493654311f69f6a1ca798 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@suse.com>
> Date: Tue, 6 Jun 2017 17:20:38 +0200
> Subject: [PATCH] Revert "printk: fix double printing with earlycon"
> 
> The commit cf39bf58afdaabc ("printk: fix double printing with earlycon")
> caused regression to users that define both console=ttyS1 and console=ttyS0
> on the command line, see
> https://lkml.kernel.org/r/20170509082915.GA13236@bistromath.localdomain
> 
> The kernel log messages always appeared only on one serial port. It is
> even documented in Documentation/admin-guide/serial-console.rst:
> 
> "Note that you can only define one console per device type (serial,
> video)."
> 
> The above mentioned commit changed the order in which the command line
> parameters are searched. As a result, the kernel log messages go to
> the last mentioned ttyS* instead of the first one.
> 
> We long thought that using two console=ttyS* on the command line
> did not make sense. But then we realized that console= parameters
> were handled also by systemd, see
> http://0pointer.de/blog/projects/serial-console.html
> 
> "By default systemd will instantiate one serial-getty@.service on
> the main kernel console, if it is not a virtual terminal."
> 
> where
> 
> "[4] If multiple kernel consoles are used simultaneously, the main
> console is the one listed first in /sys/class/tty/console/active,
> which is the last one listed on the kernel command line."
> 
> This puts the original report into another light. The system is running
> in qemu. The first serial port is used to store the messages into a file.
> The second one is used to login to the system via a socket. It depends
> on systemd and the historic kernel behavior.
> 
> By other words, systemd causes that it makes sense to define both
> console=ttyS1 console=ttyS0 on the command line. The kernel fix
> caused regression related to userspace (systemd) and need to be
> reverted.
> 
> In addition, it went out that the fix helped only partially.
> The messages still were duplicated when the boot console was
> removed early by late_initcall(printk_late_init). Then the entire
> log was replayed when the same console was registered as a normal one.
> 
> This reverts commit cf39bf58afdaabc0b86f141630fb3fd18190294e.

FWIW,

Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>


the whole thing is too fragile and, may be, it deserves a rewrite.

I agree with the decision to revert the patch. a user space visible
regression is a pretty annoying thing; even a rare one. it takes ~1-2
years until kernel release hits major vendors/users so the biggest part
of regressions might be years away, but in the meantime we can grow a
number of new setups that will depend on a new console= behavior. so
I'd prefer to revert early.

Petr, Aleksey, many thanks, good work.

	-ss