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

Groups > linux.kernel > #1640435 > unrolled thread

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

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

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

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] | [next] | [standalone]

#1640450

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

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

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

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

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