Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > linux.kernel > #1637969 > unrolled thread

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

Started bySabrina Dubroca <sd@queasysnail.net>
First post2017-05-09 10:30 +0200
Last post2017-05-18 17:50 +0200
Articles 13 — 5 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.


Contents

  Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sabrina Dubroca <sd@queasysnail.net> - 2017-05-09 10:30 +0200
    Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-11 10:30 +0200
      Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-11 10:50 +0200
        Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-11 13:40 +0200
          Re: [PATCH v9 3/3] printk: fix double printing with earlycon Aleksey Makarov <aleksey.makarov@linaro.org> - 2017-05-11 23:20 +0200
            Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-12 03:20 +0200
        Re: [PATCH v9 3/3] printk: fix double printing with earlycon Aleksey Makarov <aleksey.makarov@linaro.org> - 2017-05-11 23:20 +0200
        Re: [PATCH v9 3/3] printk: fix double printing with earlycon Petr Mladek <pmladek@suse.com> - 2017-05-12 15:00 +0200
          Re: [PATCH v9 3/3] printk: fix double printing with earlycon Petr Mladek <pmladek@suse.com> - 2017-05-12 15:50 +0200
            Re: [PATCH v9 3/3] printk: fix double printing with earlycon Aleksey Makarov <aleksey.makarov@linaro.org> - 2017-05-14 23:10 +0200
          Re: [PATCH v9 3/3] printk: fix double printing with earlycon Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-05-13 13:50 +0200
          Re: [PATCH v9 3/3] printk: fix double printing with earlycon Aleksey Makarov <aleksey.makarov@linaro.org> - 2017-05-14 22:40 +0200
            Re: [PATCH v9 3/3] printk: fix double printing with earlycon Petr Mladek <pmladek@suse.com> - 2017-05-18 17:50 +0200

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

FromSabrina Dubroca <sd@queasysnail.net>
Date2017-05-09 10:30 +0200
SubjectRe: [PATCH v9 3/3] printk: fix double printing with earlycon
Message-ID<tF8GR-7BJ-5@gated-at.bofh.it>
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

[toc] | [next] | [standalone]


#1639240

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-05-11 10:30 +0200
Message-ID<tFRDY-3XM-7@gated-at.bofh.it>
In reply to#1637969
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

[toc] | [prev] | [next] | [standalone]


#1639252

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-05-11 10:50 +0200
Message-ID<tFRXk-44b-13@gated-at.bofh.it>
In reply to#1639240
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

[toc] | [prev] | [next] | [standalone]


#1639320

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-05-11 13:40 +0200
Message-ID<tFUBQ-5JW-17@gated-at.bofh.it>
In reply to#1639252
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

[toc] | [prev] | [next] | [standalone]


#1640049

FromAleksey Makarov <aleksey.makarov@linaro.org>
Date2017-05-11 23:20 +0200
Message-ID<tG3F7-3bi-1@gated-at.bofh.it>
In reply to#1639320

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

[toc] | [prev] | [next] | [standalone]


#1640102

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-05-12 03:20 +0200
Message-ID<tG7pn-5yd-1@gated-at.bofh.it>
In reply to#1640049
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

[toc] | [prev] | [next] | [standalone]


#1640052

FromAleksey Makarov <aleksey.makarov@linaro.org>
Date2017-05-11 23:20 +0200
Message-ID<tG3F7-3bi-5@gated-at.bofh.it>
In reply to#1639252

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

[toc] | [prev] | [next] | [standalone]


#1640435

FromPetr Mladek <pmladek@suse.com>
Date2017-05-12 15:00 +0200
Message-ID<tGikO-4EF-17@gated-at.bofh.it>
In reply to#1639252
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

[toc] | [prev] | [next] | [standalone]


#1640450

FromPetr Mladek <pmladek@suse.com>
Date2017-05-12 15:50 +0200
Message-ID<tGj7c-5fh-9@gated-at.bofh.it>
In reply to#1640435
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

[toc] | [prev] | [next] | [standalone]


#1641220

FromAleksey Makarov <aleksey.makarov@linaro.org>
Date2017-05-14 23:10 +0200
Message-ID<tH8W5-6Sd-11@gated-at.bofh.it>
In reply to#1640450

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

[toc] | [prev] | [next] | [standalone]


#1640883

FromSergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date2017-05-13 13:50 +0200
Message-ID<tGDIB-35B-5@gated-at.bofh.it>
In reply to#1640435
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

[toc] | [prev] | [next] | [standalone]


#1641216

FromAleksey Makarov <aleksey.makarov@linaro.org>
Date2017-05-14 22:40 +0200
Message-ID<tH8t3-6sD-13@gated-at.bofh.it>
In reply to#1640435

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

[toc] | [prev] | [next] | [standalone]


#1644700

FromPetr Mladek <pmladek@suse.com>
Date2017-05-18 17:50 +0200
Message-ID<tIvQB-4Ia-13@gated-at.bofh.it>
In reply to#1641216
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

[toc] | [prev] | [standalone]


Back to top | Article view | linux.kernel


csiph-web