diff mbox series

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

Message ID 20170405202006.18234-1-aleksey.makarov@linaro.org
State Accepted
Commit cf39bf58afdaabc0b86f141630fb3fd18190294e
Headers show
Series None | expand

Commit Message

Aleksey Makarov April 5, 2017, 8:20 p.m. UTC
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(-)

-- 
2.12.1

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

Comments

Andy Shevchenko April 5, 2017, 9:57 p.m. UTC | #1
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
--
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
Aleksey Makarov April 6, 2017, 4:44 a.m. UTC | #2
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

>>

>

>

>

--
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
Petr Mladek April 10, 2017, 2:22 p.m. UTC | #3
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
--
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
Aleksey Makarov April 10, 2017, 6 p.m. UTC | #4
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

> 

--
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
Sergey Senozhatsky April 11, 2017, 1:54 a.m. UTC | #5
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
--
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
Sabrina Dubroca May 9, 2017, 8:29 a.m. UTC | #6
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
--
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
Sergey Senozhatsky May 11, 2017, 8:24 a.m. UTC | #7
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
--
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
Sergey Senozhatsky May 11, 2017, 8:41 a.m. UTC | #8
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
--
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
Aleksey Makarov May 11, 2017, 9:13 p.m. UTC | #9
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
--
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
Aleksey Makarov May 11, 2017, 9:17 p.m. UTC | #10
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
--
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
Sergey Senozhatsky May 12, 2017, 1:11 a.m. UTC | #11
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
--
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
Petr Mladek May 12, 2017, 1:46 p.m. UTC | #12
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
--
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
Sergey Senozhatsky May 13, 2017, 11:48 a.m. UTC | #13
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
--
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
Aleksey Makarov May 14, 2017, 8:37 p.m. UTC | #14
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
--
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
Aleksey Makarov May 14, 2017, 9:01 p.m. UTC | #15
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
--
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
Petr Mladek May 18, 2017, 3:49 p.m. UTC | #16
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
--
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
Aleksey Makarov May 26, 2017, 9:37 a.m. UTC | #17
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
--
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
Petr Mladek June 1, 2017, 12:03 p.m. UTC | #18
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
--
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
Petr Mladek June 6, 2017, 2:31 p.m. UTC | #19
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
--
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
Sergey Senozhatsky June 7, 2017, 9:13 a.m. UTC | #20
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
--
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
diff mbox series

Patch

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 */