Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

Yesterday I upgraded 4.10.6 to 4.10.7 taken from experimental

Linux hermes 4.10.0-trunk-686-pae #1 SMP Debian 4.10.7-1~exp1 
(2017-03-30) i686 GNU/Linux

and had a bit of hope to see this issue fixed because of

commit f9955dcaceae3a6d5c747b065e1d9da1be50b5ba
Author: Takashi Iwai 
Date:   Wed Jan 11 17:09:50 2017 +0100

fbcon: Fix vc attr at deinit

commit 8aac7f34369726d1a158788ae8aff3002d5eb528 upstream.

fbcon can deal with vc_hi_font_mask (the upper 256 chars) and adjust
the vc attrs dynamically when vc_hi_font_mask is changed at
fbcon_init().  When the vc_hi_font_mask is set, it remaps the attrs 
in
the existing console buffer with one bit shift up (for 9 bits), 
while
it remaps with one bit shift down (for 8 bits) when the value is
cleared.  It works fine as long as the font gets updated after fbcon
was initialized.

However, we hit a bizarre problem when the console is switched to
another fb driver (typically from vesafb or efifb to drmfb).  At
switching to the new fb driver, we temporarily rebind the console to
the dummy console, then rebind to the new driver.  During the
switching, we leave the modified attrs as is.  Thus, the new fbcon
takes over the old buffer as if it were to contain 8 bits chars
(although the attrs are still shifted for 9 bits), and effectively
this results in the yellow color texts instead of the original white
color, as found in the bugzilla entry below.

An easy fix for this is to re-adjust the attrs before leaving the
fbcon at con_deinit callback.  Since the code to adjust the attrs is
already present in the current fbcon code, in this patch, we simply
factor out the relevant code, and call it from fbcon_deinit().

Bugzilla: https://bugzilla.suse.com/show_bug.cgi?id=1000619
Signed-off-by: Takashi Iwai 
Signed-off-by: Bartlomiej Zolnierkiewicz 
Cc: Arnd Bergmann 
Signed-off-by: Greg Kroah-Hartman 

in

https://www.kernel.org/pub/linux/kernel/v4.x/ChangeLog-4.10.7

However, no such luck :-)

Perhaps, though, this inspires insight into more
knowledgeable people as to what might be the exact cause ?

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

Anything else I can do to get this issue looked into ?

Thanks,
Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Sun, Mar 26, 2017 at 08:18:16PM +0200, Karsten Hilbert wrote:

> One thing I *haven't* tested yet is whether earlier kernel
> would make a difference -- not that I would think but who
> knows.

Just for kicks I booted all kernels installed on this machine
(all prior experimentation was done under 4.10) -- the
console did not get properly configured under any of 4.3,
4.6, or 4.9.

I did manage to have parallelism detection kick in once though:

[...]
1087 - 2017-03-27 09:54:40.488734408+02:00: 
/cached_setup_font.sh.running created
1087 - 2017-03-27 09:54:40.509440184+02:00: 
/cached_setup_font.sh.running deleted
[reboot]
426 - 2017-03-27 09:57:39.157315082+02:00: 
/cached_setup_font.sh.running created
502 - 2017-03-27 09:57:40.195551438+02:00: 
/cached_setup_font.sh.running exists and contains [426 / 2017-03-27 
09:57:39.157315082+02:00], exiting
426 - 2017-03-27 09:57:40.709767317+02:00: 
/cached_setup_font.sh.running deleted
657 - 2017-03-27 09:57:42.245186312+02:00: 
/cached_setup_font.sh.running created
657 - 2017-03-27 09:57:42.268458964+02:00: 
/cached_setup_font.sh.running deleted

so at least we got this right, technically :-)

These boots were under slightly heavier load: two external
USB mass storage devices being online during the entire
reboot cycle, one of which acts as backup swap while the
other is a backup device being hit by another machine over
the network as soon as the problem machine reaches network
target.

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Sun, Mar 26, 2017 at 08:18:16PM +0200, Karsten Hilbert wrote:
> 
> > Maybe this happened because cached_setup_font.sh was run while / was 
> > still read-only?
> 
> Possibly. Suspecting that is why I chose / in the hope it'll
> get mounted rw real early :-)

I think for early logs /run/initramfs/ can be used.  Also 
/usr/bin/logger might be able to help.

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Sun, Mar 26, 2017 at 08:42:43PM +0300, Anton Zinoviev wrote:

>> I have done some more experimentation and it shows fairly
>> strange results.
> 
> Thanks a lot! :)

That is what I can contribute.

> > Sometimes cached_setup_font.sh does not seem to get run AT
> > ALL -- the log file simply does not exist after a clean boot.
> 
> Maybe this happened because cached_setup_font.sh was run while / was 
> still read-only?

Possibly. Suspecting that is why I chose / in the hope it'll
get mounted rw real early :-)

> > However, as witnessed by this log snippet from the most
> > recent boot, it does not ALWAYS run in parallel:
> 
> Let us clear one point: no matter whether it runs in parallel or not -- 
> the console is never configured properly?  Or sometimes it is?

It is NEVER configured properly anymore.

It used to always work until fairly recently (shortly before
I filed the bug) but now _never_ does, regardless of whether
I can find a log under /.

One thing I *haven't* tested yet is whether earlier kernel
would make a difference -- not that I would think but who
knows.

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Fri, Mar 24, 2017 at 11:52:32AM +0100, Karsten Hilbert wrote:
> I have done some more experimentation and it shows fairly
> strange results.

Thanks a lot! :)

> Sometimes cached_setup_font.sh does not seem to get run AT
> ALL -- the log file simply does not exist after a clean boot.

Maybe this happened because cached_setup_font.sh was run while / was 
still read-only?

On Sun, Mar 26, 2017 at 04:04:45PM +0200, Karsten Hilbert wrote:
> 
> However, as witnessed by this log snippet from the most
> recent boot, it does not ALWAYS run in parallel:

Let us clear one point: no matter whether it runs in parallel or not -- 
the console is never configured properly?  Or sometimes it is?

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

One more data point:

> I edited the file /etc/console-setup/cached_setup_font.sh
> to look like this:

...

> the idea being to prevent it from running in parallel.

...

> When the log file DOES exist it does indeed show
> cached_setup_font.sh to run in parallel "early" in the boot
> process and once more "later":

However, as witnessed by this log snippet from the most
recent boot, it does not ALWAYS run in parallel:

397 - 2017-03-26 15:53:08.218566865+02:00: 
/cached_setup_font.sh.running created
397 - 2017-03-26 15:53:09.054517233+02:00: 
/cached_setup_font.sh.running deleted
465 - 2017-03-26 15:53:09.569959665+02:00: 
/cached_setup_font.sh.running created
465 - 2017-03-26 15:53:09.656989307+02:00: 
/cached_setup_font.sh.running deleted
557 - 2017-03-26 15:53:09.701864078+02:00: 
/cached_setup_font.sh.running created
557 - 2017-03-26 15:53:09.743826537+02:00: 
/cached_setup_font.sh.running deleted

(it took much longer this time for the second process 465 to
be run)

The only thing I can think of maybe having been different
between this boot and other boots was: This time I let Debian
boot all the way into SDDM, then DID NOT switch to a console
right away but rather logged into KDE, and only switched to a
VT once KDE login was finished.

Probably doesn't help much, however. Thought I'd mention though.

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

I have done some more experimentation and it shows fairly
strange results.

I edited the file /etc/console-setup/cached_setup_font.sh
to look like this:

#!/bin/sh

# added
SEMAPHORE="/cached_setup_font.sh.running"
LOG="/console-cached_setup_font.sh-tracing.log"
TS=`date --rfc-3339=ns`
if test ! -f ${SEMAPHORE} ; then
> ${SEMAPHORE} ;
echo "$$ / $TS" > ${SEMAPHORE} ;
echo "$$ - $TS: ${SEMAPHORE} created" >> $LOG ;
else
VAL=`cat ${SEMAPHORE}` ;
echo "$$ - $TS: ${SEMAPHORE} exists and contains [$VAL], exiting" 
>> $LOG ;
exit 0 ;
fi
# ---

setfont '/etc/console-setup/Lat15-Terminus16.psf.gz'

if ls /dev/fb* >/dev/null 2>/dev/null; then
for i in /dev/vcs[0-9]*; do
{ :
setfont '/etc/console-setup/Lat15-Terminus16.psf.gz'
} < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
done
fi

mkdir -p /run/console-setup
> /run/console-setup/font-loaded
for i in /dev/vcs[0-9]*; do
{ :
printf '\033%%G'
} < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
done

# added
rm -f ${SEMAPHORE} >> $LOG
TS=`date --rfc-3339=ns`
echo "$$ - $TS: ${SEMAPHORE} deleted" >> $LOG
# ---

the idea being to prevent it from running in parallel.

Observations after many reboots with neither semaphore nor
log existing:

Sometimes cached_setup_font.sh does not seem to get run AT
ALL -- the log file simply does not exist after a clean boot.

When the log file DOES exist it does indeed show
cached_setup_font.sh to run in parallel "early" in the boot
process and once more "later":

421 - 2017-03-24 11:31:44.262310078+01:00: 
/cached_setup_font.sh.running created
423 - 2017-03-24 11:31:44.262785627+01:00: 
/cached_setup_font.sh.running created
421 - 2017-03-24 11:31:45.721488930+01:00: 
/cached_setup_font.sh.running deleted
423 - 2017-03-24 11:31:45.721489699+01:00: 
/cached_setup_font.sh.running deleted
659 - 2017-03-24 11:31:47.733106958+01:00: 
/cached_setup_font.sh.running created
659 - 2017-03-24 11:31:47.755347426+01:00: 
/cached_setup_font.sh.running deleted

Note how the two early runs even manage to race each other
within a few (4) microseconds:

421 - 2017-03-24 11:31:44.262*3*10078+01:00: 
/cached_setup_font.sh.running created
423 - 2017-03-24 11:31:44.262*7*85627+01:00: 
/cached_setup_font.sh.running created

which means that this code:

#!/bin/sh
# added
SEMAPHORE="/cached_setup_font.sh.running"
LOG="/console-cached_setup_font.sh-tracing.log"
TS=`date --rfc-3339=ns`
if test ! -f ${SEMAPHORE} ; then
> ${SEMAPHORE} ;
echo "$$ / $TS" > ${SEMAPHORE} ;

runs in less than 4 µs because it manages to race inbetween

if test ! -f ${SEMAPHORE} ; then
> ${SEMAPHORE} ;

(that's why I first create the semaphore before taking the
time to pipe data into it).

Here's what journalctl -b records for that time span:

Mär 24 11:31:43 hermes systemd[1]: Starting Load/Save RF Kill Switch 
Status...
Mär 24 11:31:44 hermes systemd[1]: Started Load/Save Screen Backlight 
Brightness of backlight:intel_backlight.
Mär 24 11:31:44 hermes systemd[1]: Started Load/Save Screen Backlight 
Brightness of backlight:acpi_video0.
Mär 24 11:31:44 hermes kernel: psmouse serio4: elantech: assuming 
hardware version 2 (with firmware version 0x040101)
Mär 24 11:31:44 hermes kernel: ath: phy0: Enable LNA combining
Mär 24 11:31:44 hermes kernel: ath: phy0: ASPM enabled: 0x42
Mär 24 11:31:44 hermes kernel: ath: EEPROM regdomain: 0x60
Mär 24 11:31:44 hermes kernel: ath: EEPROM indicates we should expect a 
direct regpair map
Mär 24 11:31:44 hermes kernel: ath: Country alpha2 being used: 00
Mär 24 11:31:44 hermes kernel: ath: Regpair used: 0x60
Mär 24 11:31:44 hermes kernel: psmouse serio4: elantech: Synaptics 
capabilities query result 0x7e, 0x13, 0x0d.
Mär 24 11:31:44 hermes kernel: psmouse serio4: elantech: Elan sample 
query result 19, 00, 00
Mär 24 11:31:44 hermes kernel: input: ETPS/2 Elantech Touchpad as 
/devices/platform/i8042/serio4/input/input15
Mär 24 11:31:44 hermes kernel: ieee80211 phy0: Selected rate control 
algorithm 'minstrel_ht'
Mär 24 11:31:44 hermes kernel: ieee80211 phy0: Atheros AR9285 Rev:2 
mem=0xf89b, irq=17
Mär 24 11:31:44 hermes kernel: iTCO_vendor_support: vendor-support=0
Mär 24 11:31:44 hermes kernel: iTCO_wdt: Intel TCO WatchDog Timer 
Driver v1.11
Mär 24 11:31:44 hermes kernel: iTCO_wdt: Found a ICH9M TCO device 
(Version=2, TCOBASE=0x0860)
Mär 24 11:31:44 hermes kernel: iTCO_wdt: initialized. heartbeat=30 

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Thu, Mar 23, 2017 at 11:36:20AM +0100, Karsten Hilbert wrote:
> 
> Directly after boot, during which no VT switch occurred, I
> will see the login manager for KDE. When I now switch to the
> first console and then ALT-RIGHT through my other consoles up
> until vt6 they don't have a getty running just yet (they show
> up as empty black screens).

Actually, this is an indication that console-setup has already 
configured these consoles.  As far as I know, there are only two 
components in a Debian system that open VTs -- getty and console-setup 
(and X for vt7).  If you see a created console without getty, then this 
console exists only because console-setup has done something to it.

If you would repeat this experiment on a system which didn't have 
console-setup installed, then ALT-RIGHT simply wouldn't work, it 
wouldn't switch to a console which didn't exist yet.  And it would be 
impossible to see an empty console without getty running on it.

Ofcourse, this doesn't explain why the configuration doesn't work -- 
because something overwrites it or because the configuration is 
performed too early, while the system is not prepared for it yet.

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Sven Joachim]

On 2017-03-23 14:12 -0300, Felipe Sateler wrote:

> However, I see the following in cached_setup_font:
>
> setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'
>
> if ls /dev/fb* >/dev/null 2>/dev/null; then
> for i in /dev/vcs[0-9]*; do
> { :
> setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'
> } < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
> done
> fi
>
> Might it be that /dev/fb* do not exist during boot, and thus the font
> is not loaded in all ttys?

I had suspected that as well, but could rule it out.  Would have been
quite surprising anyway since I load the nouveau kernel module from the
initramfs, and it provides a framebuffer driver.

Cheers,
   Sven

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Thu, Mar 23, 2017 at 02:12:44PM -0300, Felipe Sateler wrote:
> 
> As mentioned by Michael, this is not done by udev or systemd.

I think systemd runs getty which opens a console.  Then the kernel 
creates virtual consoles on demand.

> > From my tests it seems that the font used
> > for this initialization is the same as the font used on the current
> > console.  Isn't it possible that sometimes this font is set only _after_
> > udev has started the script cached_setup_font.sh by the following rule
> >
> > ACTION=="add", SUBSYSTEM=="vtconsole", KERNEL=="vtcon*", 
> > RUN+="/etc/console-setup/cached_setup_font.sh"
> >
> > however the font of the current console is read _before_ the script
> > cached_setup_font.sh has had a chance to configure the font?
> 
> I don't know of any component that does that.

The kernel?

> However, I see the following in cached_setup_font:
> 
> setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'
> 
> if ls /dev/fb* >/dev/null 2>/dev/null; then
> for i in /dev/vcs[0-9]*; do
> { :
> setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'
> } < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
> done
> fi
> 
> Might it be that /dev/fb* do not exist during boot, and thus the font
> is not loaded in all ttys?


If /dev/fb* doesn't exist then the graphics card is in hardware text 
mode in which case there is one font on all ttys (due to hardware 
limitation).  If /dev/fb* is created afterwards, then udev will run 
cached_setup_font again.

I don't know what is going to happen if:

1. udev runs cached_setup_font while there is no framebuffer

2. the script tests that there is no /dev/fb*

3. before the script completes its work /dev/fb* is created

In this case the rule of udev will trigger for a second time.  However 
since the script hasn't finished yet will then udev run a second copy of 
it?  If not, then this too, might create problems.  On the other hand, 
if udev always runs cached_setup_font again, do both copies run in 
parallel (this shoudn't be a problem for cached_setup_font but it is 
good to know if such possibility exists)?

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Felipe Sateler]

On Thu, Mar 23, 2017 at 10:58 AM, Anton Zinoviev  wrote:
> On Thu, Mar 23, 2017 at 02:37:48PM +0100, Michael Biebl wrote:
>>
>> In Debian, we don't enable the systemd-vconsole component [1].
>
> This is good, but...
>
>> So there should be no console configuration happening from systemd's
>> side.
>
> ...suppose udev creates a new console.

As mentioned by Michael, this is not done by udev or systemd.

> Then it has to be initialized
> with some font, hasn't it?

When it is created, the udev rule should be fired. So
cached_setup_font.sh should be invoked again.

>  From my tests it seems that the font used
> for this initialization is the same as the font used on the current
> console.  Isn't it possible that sometimes this font is set only _after_
> udev has started the script cached_setup_font.sh by the following rule
>
> ACTION=="add", SUBSYSTEM=="vtconsole", KERNEL=="vtcon*", 
> RUN+="/etc/console-setup/cached_setup_font.sh"
>
> however the font of the current console is read _before_ the script
> cached_setup_font.sh has had a chance to configure the font?

I don't know of any component that does that. Systemd-vconsole, as
mentioned by Michael, is not enabled in the debian packages.

However, I see the following in cached_setup_font:

setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'

if ls /dev/fb* >/dev/null 2>/dev/null; then
for i in /dev/vcs[0-9]*; do
{ :
setfont '/etc/console-setup/cached_Lat15-Fixed16.psf.gz'
} < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
done
fi

Might it be that /dev/fb* do not exist during boot, and thus the font
is not loaded in all ttys?

-- 

Saludos,
Felipe Sateler

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Thu, Mar 23, 2017 at 03:30:36PM +0100, Michael Biebl wrote:
> > 
> > ...suppose udev creates a new console.  Then it has to be initialized 
> > with some font, hasn't it?  
> 
> udev does not create any consoles. That's a misconception.

Well, whoever does it... :)

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Michael Biebl]

Am 23.03.2017 um 14:58 schrieb Anton Zinoviev:
> On Thu, Mar 23, 2017 at 02:37:48PM +0100, Michael Biebl wrote:
>>
>> In Debian, we don't enable the systemd-vconsole component [1].
> 
> This is good, but...
> 
>> So there should be no console configuration happening from systemd's
>> side.
> 
> ...suppose udev creates a new console.  Then it has to be initialized 
> with some font, hasn't it?  

udev does not create any consoles. That's a misconception.



-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Thu, Mar 23, 2017 at 02:37:48PM +0100, Michael Biebl wrote:
> 
> In Debian, we don't enable the systemd-vconsole component [1].

This is good, but...

> So there should be no console configuration happening from systemd's
> side.

...suppose udev creates a new console.  Then it has to be initialized 
with some font, hasn't it?  From my tests it seems that the font used 
for this initialization is the same as the font used on the current 
console.  Isn't it possible that sometimes this font is set only _after_ 
udev has started the script cached_setup_font.sh by the following rule

ACTION=="add", SUBSYSTEM=="vtconsole", KERNEL=="vtcon*", 
RUN+="/etc/console-setup/cached_setup_font.sh"

however the font of the current console is read _before_ the script 
cached_setup_font.sh has had a chance to configure the font?

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Michael Biebl]

Am 23.03.2017 um 14:04 schrieb Anton Zinoviev:

> My tests of how systemd works show that it does the following:
> 
> 1. It reads the curent font of the current console.
> 
> 2. Then it does some things to the console(s) (configuration).
> 
> 3. When a new console is created it loads on it the font read in 1.
> 
> Therefore, it seems to me that if cached_setup_font.sh completes its job 
> before 1. then everything should be ok.  And if systemd completes its 
> configuration before cached_setup_font.sh starts its work, then again 
> everything will be ok.  However if both work simultaneously things can 
> go wrong.
> 
> So, if this scenario is possible, a natural question is what can be done 
> in order to make sure the scripts of console-setup do not execute in 
> parallel with systemd while configuring the console.

In Debian, we don't enable the systemd-vconsole component [1].
So there should be no console configuration happening from systemd's
side. Then again, I'm not sure what you mean by
"Then it does some things to the console(s) (configuration)."
Can you be more specific?

Michael

[1]
https://anonscm.debian.org/cgit/pkg-systemd/systemd.git/tree/debian/rules#n116
-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?



signature.asc
Description: OpenPGP digital signature

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Thu, Mar 23, 2017 at 03:04:37PM +0200, Anton Zinoviev wrote:

> Since systemd makes some configuration of the console, maybe the 
> following scenario might explain what we observe:

... lengthy analysis ...

> So, if this scenario is possible, a natural question is what can be done 
> in order to make sure the scripts of console-setup do not execute in 
> parallel with systemd while configuring the console.

This very much sounds like a possible cause for what I am
observing and should be the path to follow first.

Note that this problem has been observed previously (there's
old, resolved bugs around this) which had a similar solution.

A, perhaps fairly drastic, solution might be to delay
setupcon font setting until all getty's have been started ?

Thanks,
Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

[I am sending a CC to pkg-systemd-maintain...@lists.alioth.debian.org]

On Thu, Mar 23, 2017 at 11:07:14AM +0100, Sven Joachim wrote:
> 
> There might be a third possibility which seems to happen on one of my
> systems: the cached_setup_font.sh script does not work correctly when
> run during boot by udev.  Because this is what I am observing here, I
> even added some debug messages to it to see if it is run at all (as
> intended by /lib/udev/rules.d/90-console-setup.rules), and indeed it
> does run but the font still remains unchanged.
> 
> Manually running /etc/console-setup/cached_setup_font.sh (or
> setupcon -f, for that matter) works fine, so I'm a bit at a loss here.

Since systemd makes some configuration of the console, maybe the 
following scenario might explain what we observe:

1. systemd/udev creates a new console.

2. systemd begins the initialization of this console.

3. udev runs /etc/console-setup/cached_setup_font.sh by the following 
rule:

ACTION=="add", SUBSYSTEM=="vtconsole", KERNEL=="vtcon*", 
RUN+="/etc/console-setup/cached_setup_font.sh"

4. Now cached_setup_font.sh and systemd execute in parallel.  If 
cached_setup_font.sh wins, it will configure the console font first and 
then systemd will load another font.

My tests of how systemd works show that it does the following:

1. It reads the curent font of the current console.

2. Then it does some things to the console(s) (configuration).

3. When a new console is created it loads on it the font read in 1.

Therefore, it seems to me that if cached_setup_font.sh completes its job 
before 1. then everything should be ok.  And if systemd completes its 
configuration before cached_setup_font.sh starts its work, then again 
everything will be ok.  However if both work simultaneously things can 
go wrong.

So, if this scenario is possible, a natural question is what can be done 
in order to make sure the scripts of console-setup do not execute in 
parallel with systemd while configuring the console.

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Thu, Mar 23, 2017 at 11:07:14AM +0100, Sven Joachim wrote:

> >> > ls -l /etc/console-setup/
> >> 
> >>-rwxr-xr-x   1 root root   465 Mar 22 11:20 cached_setup_font.sh
> >>-rwxr-xr-x   1 root root   358 Mar 22 11:20 cached_setup_keyboard.sh
> >>-rwxr-xr-x   1 root root73 Mar 22 11:20 cached_setup_terminal.sh
> >
> > Hm, the times of these three are too recent. I can see two possibilities:
> >
> >   1. either the bug no longer exists in this system, in which case we 
> > have to find out what caused these files to be created, or
> >
> >   2. the bug still exists and each time the system boots, it recreates 
> > these three files.  In this case we have to find out the cause of this.
> 
> There might be a third possibility which seems to happen on one of my
> systems: the cached_setup_font.sh script does not work correctly when
> run during boot by udev.  Because this is what I am observing here, I
> even added some debug messages to it to see if it is run at all (as
> intended by /lib/udev/rules.d/90-console-setup.rules), and indeed it
> does run but the font still remains unchanged.

This very much hints at a dependency problems, does it not ? 
Does your system exhibiting this behaviour run systemd ?

> Manually running /etc/console-setup/cached_setup_font.sh (or
> setupcon -f, for that matter) works fine, so I'm a bit at a loss here.

I'll constrain my "fixup" script to "-f" now to see whether
that will consistently fix what I am seeing (IOW whether we
can constrain the problem to font setting, which is likely).

I have sometimes noted the following which seems to suggest
that some dependency may come up late:

Directly after boot, during which no VT switch occurred, I
will see the login manager for KDE. When I now switch to the
first console and then ALT-RIGHT through my other consoles up
until vt6 they don't have a getty running just yet (they show
up as empty black screens). The second round through all of
them exhibit the getty login prompt. This happens only very
rarely but it _does_ come up every so often. This fact does
seem to hint a gettys being spawned in a delayed fashion.

I have observed something else, but only ONCE so far:

After running setupcon to fix the font problem one console
(sitting at the login prompt) did not get the message - it
stayed in the old, wrong font. Re-running setupcon fixed that
console, too. Other consoles - which reset to the correct
font upon the first setupcon invocation - where either logged
in or sitting at the login prompt as well, so it's not
whether they were logged in or not.

Might there be a race between getty spawning and setupcon
running ?

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Sven Joachim]

On 2017-03-22 15:02 +0200, Anton Zinoviev wrote:

> On Wed, Mar 22, 2017 at 01:00:17PM +0100, Karsten Hilbert wrote:
>> 
>> > ls -l /etc/console-setup/
>> 
>>  -rwxr-xr-x   1 root root   465 Mar 22 11:20 cached_setup_font.sh
>>  -rwxr-xr-x   1 root root   358 Mar 22 11:20 cached_setup_keyboard.sh
>>  -rwxr-xr-x   1 root root73 Mar 22 11:20 cached_setup_terminal.sh
>
> Hm, the times of these three are too recent. I can see two possibilities:
>
>   1. either the bug no longer exists in this system, in which case we 
> have to find out what caused these files to be created, or
>
>   2. the bug still exists and each time the system boots, it recreates 
> these three files.  In this case we have to find out the cause of this.

There might be a third possibility which seems to happen on one of my
systems: the cached_setup_font.sh script does not work correctly when
run during boot by udev.  Because this is what I am observing here, I
even added some debug messages to it to see if it is run at all (as
intended by /lib/udev/rules.d/90-console-setup.rules), and indeed it
does run but the font still remains unchanged.

Manually running /etc/console-setup/cached_setup_font.sh (or
setupcon -f, for that matter) works fine, so I'm a bit at a loss here.

Cheers,
   Sven

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Wed, Mar 22, 2017 at 08:48:16PM +0200, Anton Zinoviev wrote:

> > 2017-03-22 13:05:13.364493514 +0100 /etc/console-setup/cached_setup_font.sh
> > 2017-03-22 13:05:13.364493514 +0100 
> > /etc/console-setup/cached_setup_keyboard.sh
> > 2017-03-22 13:05:13.364493514 +0100 
> > /etc/console-setup/cached_setup_terminal.sh
> > 2017-03-22 12:54:59.368053266 +0100 
> > /etc/console-setup/cached_UTF-8_del.kmap.gz
> > 2017-03-22 12:53:10.459239057 +0100 /etc/default/console-setup
> > 2017-03-07 09:26:01.171789164 +0100 /etc/default/keyboard
> 
> It seems something has changed /etc/default/console-setup. If this file 
> is changed, then boot scripts of console-setup will recreate the 
> cached_* files in /etc.
> 
> Do you know what has caused this file to be changed?

That was me, again, because I hoped that setting

# Change to "yes" and setupcon will explain what is being doing
VERBOSE_OUTPUT="yes"

from "no" to "yes" would generate helpful debugging output.
However, I haven't been able to find any :-/

> Something unrelated that might explain the bug is this: maybe this 
> system runs X

It does, yes.

> but doesn't have framebuffer on the console?

Oh, it does:

dmseg:
[   20.377384] fbcon: inteldrmfb (fb0) is primary device
...
[   21.054248] Console: switching to colour frame buffer device 170x48
[   21.084983] i915 :00:02.0: fb0: inteldrmfb frame buffer device


fbset -v -i

Linux Frame Buffer Device Configuration Version 2.1 (23/06/1999)
(C) Copyright 1995-1999 by Geert Uytterhoeven

Opening frame buffer device `/dev/fb0'
Using current video mode from `/dev/fb0'

mode "1366x768"
geometry 1366 768 1366 768 32
timings 0 0 0 0 0 0 0
accel true
rgba 8/16,8/8,8/0,0/0
endmode

Getting further frame buffer information
Frame buffer device information:
Name: inteldrmfb
Address : 0xd0048000
Size: 4227072
Type: PACKED PIXELS
Visual  : TRUECOLOR
XPanStep: 1
YPanStep: 1
YWrapStep   : 0
LineLength  : 5504
Accelerator : No

> BTW, instead of `systemctl restart console-setup.service` you can use 
> the command `setupcon`.

OK, I will resort to that in order to minimize what is involved.

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Wed, Mar 22, 2017 at 05:56:04PM +0100, Karsten Hilbert wrote:

> 2017-03-22 13:05:13.364493514 +0100 /etc/console-setup/cached_setup_font.sh
> 2017-03-22 13:05:13.364493514 +0100 
> /etc/console-setup/cached_setup_keyboard.sh
> 2017-03-22 13:05:13.364493514 +0100 
> /etc/console-setup/cached_setup_terminal.sh
> 2017-03-22 12:54:59.368053266 +0100 
> /etc/console-setup/cached_UTF-8_del.kmap.gz
> 2017-03-22 12:53:10.459239057 +0100 /etc/default/console-setup
> 2017-03-07 09:26:01.171789164 +0100 /etc/default/keyboard

It seems something has changed /etc/default/console-setup. If this file 
is changed, then boot scripts of console-setup will recreate the 
cached_* files in /etc.

Do you know what has caused this file to be changed?  Its time seems to 
be only few minutes before the time of the reboot.  I can't think of 
anything in the scripts of console-setup that can cause changes in this 
file.

Something unrelated that might explain the bug is this: maybe this 
system runs X but doesn't have framebuffer on the console?  In this case 
the problem is hardware related and the best solution is to use 
framebuffer.

BTW, instead of `systemctl restart console-setup.service` you can use 
the command `setupcon`.

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Wed, Mar 22, 2017 at 04:49:27PM +0200, Anton Zinoviev wrote:

> Thanks. :) Well, can you report the state of the affairs before you run
> 
>   systemctl restart console-setup.service
> 
> ls --full-time /etc/default/{console-setup,keyboard} 
> /etc/console-setup/cached_*

Attached.

Full times directly after a reboot before manually restarting
console-setup.

Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346
-rwxr-xr-x 1 root root  465 2017-03-22 13:05:13.364493514 +0100 
/etc/console-setup/cached_setup_font.sh
-rwxr-xr-x 1 root root  358 2017-03-22 13:05:13.364493514 +0100 
/etc/console-setup/cached_setup_keyboard.sh
-rwxr-xr-x 1 root root   73 2017-03-22 13:05:13.364493514 +0100 
/etc/console-setup/cached_setup_terminal.sh
-rw-r--r-- 1 root root 4377 2017-03-22 12:54:59.368053266 +0100 
/etc/console-setup/cached_UTF-8_del.kmap.gz
-rw-r--r-- 1 root root 2061 2017-03-22 12:53:10.459239057 +0100 
/etc/default/console-setup
-rw-r--r-- 1 root root  587 2017-03-07 09:26:01.171789164 +0100 
/etc/default/keyboard

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Wed, Mar 22, 2017 at 03:19:57PM +0100, Karsten Hilbert wrote:
> On Wed, Mar 22, 2017 at 03:02:28PM +0200, Anton Zinoviev wrote:
> > 
> >   2. the bug still exists and each time the system boots, it recreates 
> > these three files.  In this case we have to find out the cause of this.
> 
> The latter: currently, after each boot, I manually run
> 
>   systemctl restart console-setup.service
> 
> which fixes the console problem for me until the next boot.
> That's why those files are from today.

This will update thethree files /etc/console-setup/cached_setup* if the 
times of /etc/default/{keyboard,console-setup} are more recent.  On the 
other hand, times of the files in /etc/default/* are not supposed to 
change.
 
> >  And what about the files 
> > /etc/default/{keyboard,console-setup} -- do their times change too?
> 
> Likely because of the above, too.

Actualy these files should change only if console-setup is upgraded or 
the admin runs dpkg-reconfigure.

> Feel free to ask for more information you may need.

Thanks. :) Well, can you report the state of the affairs before you run

systemctl restart console-setup.service

ls --full-time /etc/default/{console-setup,keyboard} /etc/console-setup/cached_*

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Wed, Mar 22, 2017 at 03:02:28PM +0200, Anton Zinoviev wrote:

> > > ls -l /etc/console-setup/
> > 
> > -rwxr-xr-x   1 root root   465 Mar 22 11:20 cached_setup_font.sh
> > -rwxr-xr-x   1 root root   358 Mar 22 11:20 cached_setup_keyboard.sh
> > -rwxr-xr-x   1 root root73 Mar 22 11:20 cached_setup_terminal.sh
> 
> Hm, the times of these three are too recent. I can see two possibilities:
>
>   1. either the bug no longer exists in this system, in which case we 
> have to find out what caused these files to be created, or
> 
>   2. the bug still exists and each time the system boots, it recreates 
> these three files.  In this case we have to find out the cause of this.

The latter: currently, after each boot, I manually run

systemctl restart console-setup.service

which fixes the console problem for me until the next boot.
That's why those files are from today.

> Can you check if the times of these three files change each time the 
> system boots?

See above.

>  And what about the files 
> /etc/default/{keyboard,console-setup} -- do their times change too?

Likely because of the above, too.

> > (the line starting with ">" strikes me as odd - should it not
> >  be on the "mkdir -p" line ?)
> 
> This line creates an empty file /run/console-setup/font-loaded which is 

I eventually figured as much...

> used by /lib/udev/rules.d/90-console-setup.rules to make sure the script 
> /etc/console-setup/cached_setup_terminal.sh is not run before 
> /etc/console-setup/cached_setup_font.sh.

OK, got it.

> These look ok as well...

Feel free to ask for more information you may need.

Thanks,
Karsten
-- 
GPG key ID E4071346 @ eu.pool.sks-keyservers.net
E167 67FD A291 2BEA 73BD  4537 78B9 A9F9 E407 1346

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Wed, Mar 22, 2017 at 01:00:17PM +0100, Karsten Hilbert wrote:
> 
> > ls -l /etc/console-setup/
> 
>   -rwxr-xr-x   1 root root   465 Mar 22 11:20 cached_setup_font.sh
>   -rwxr-xr-x   1 root root   358 Mar 22 11:20 cached_setup_keyboard.sh
>   -rwxr-xr-x   1 root root73 Mar 22 11:20 cached_setup_terminal.sh

Hm, the times of these three are too recent. I can see two possibilities:

  1. either the bug no longer exists in this system, in which case we 
have to find out what caused these files to be created, or

  2. the bug still exists and each time the system boots, it recreates 
these three files.  In this case we have to find out the cause of this.

Can you check if the times of these three files change each time the 
system boots?  And what about the files 
/etc/default/{keyboard,console-setup} -- do their times change too?

> > cat /etc/console-setup/cached_setup_font.sh
> > cat /etc/console-setup/cached_setup_terminal.sh

These look ok to me.  I was kind of hoping to find something wrong here...

>   > /run/console-setup/font-loaded
> 
> (the line starting with ">" strikes me as odd - should it not
>  be on the "mkdir -p" line ?)

This line creates an empty file /run/console-setup/font-loaded which is 
used by /lib/udev/rules.d/90-console-setup.rules to make sure the script 
/etc/console-setup/cached_setup_terminal.sh is not run before 
/etc/console-setup/cached_setup_font.sh.

> > cat /etc/default/console-setup
> > cat /etc/default/keyboard

These look ok as well...

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

On Wed, Mar 22, 2017 at 02:18:51PM +0300, Anton Zinoviev wrote:

> > is there anything I can do/provide to help get this resolved ?
> 
> Yes, thanks!  The output of the following commands:

Here you go:

> ls -l /etc/console-setup/

total 164
drwxr-xr-x   2 root root  4096 Mar  7 09:26 .
drwxr-xr-x 194 root root 12288 Mar 22 11:16 ..
-rw-r--r--   1 root root  2417 Mar  2  2011 Lat15-Fixed16.psf.gz
-rw-r--r--   1 root root  2328 Mar 11  2011 Lat15-Terminus16.psf.gz
-rw-r--r--   1 root root  2351 Nov 12  2010 Lat15-TerminusBold16.psf.gz
-rw-r--r--   1 root root  4086 Mar 11  2011 cached.kmap.gz
-rw-r--r--   1 root root  4377 Mar  7 09:26 cached_UTF-8_del.kmap.gz
-rwxr-xr-x   1 root root   465 Mar 22 11:20 cached_setup_font.sh
-rwxr-xr-x   1 root root   358 Mar 22 11:20 cached_setup_keyboard.sh
-rwxr-xr-x   1 root root73 Mar 22 11:20 cached_setup_terminal.sh
-rw-r--r--   1 root root34 Jan 11  2011 compose.ARMSCII-8.inc
-rw-r--r--   1 root root31 Jan 11  2011 compose.CP1251.inc
-rw-r--r--   1 root root31 Jan 11  2011 compose.CP1255.inc
-rw-r--r--   1 root root31 Jan 11  2011 compose.CP1256.inc
-rw-r--r--   1 root root41 Jan 11  2011 compose.GEORGIAN-ACADEMY.inc
-rw-r--r--   1 root root36 Jan 11  2011 compose.GEORGIAN-PS.inc
-rw-r--r--   1 root root32 Jan 11  2011 compose.IBM1133.inc
-rw-r--r--   1 root root35 Jan 11  2011 compose.ISIRI-3342.inc
-rw-r--r--   1 root root  3596 May 22  2016 compose.ISO-8859-1.inc
-rw-r--r--   1 root root36 Jan 11  2011 compose.ISO-8859-10.inc
-rw-r--r--   1 root root36 Jan 11  2011 compose.ISO-8859-11.inc
-rw-r--r--   1 root root  3737 May 22  2016 compose.ISO-8859-13.inc
-rw-r--r--   1 root root  3020 Mar  2  2016 compose.ISO-8859-14.inc
-rw-r--r--   1 root root  3552 May 22  2016 compose.ISO-8859-15.inc
-rw-r--r--   1 root root36 Jan 11  2011 compose.ISO-8859-16.inc
-rw-r--r--   1 root root  2893 May 22  2016 compose.ISO-8859-2.inc
-rw-r--r--   1 root root  3387 May 22  2016 compose.ISO-8859-3.inc
-rw-r--r--   1 root root  2805 May 22  2016 compose.ISO-8859-4.inc
-rw-r--r--   1 root root35 Jan 11  2011 compose.ISO-8859-5.inc
-rw-r--r--   1 root root35 Jan 11  2011 compose.ISO-8859-6.inc
-rw-r--r--   1 root root  1217 May 22  2016 compose.ISO-8859-7.inc
-rw-r--r--   1 root root35 Jan 11  2011 compose.ISO-8859-8.inc
-rw-r--r--   1 root root  3617 May 22  2016 compose.ISO-8859-9.inc
-rw-r--r--   1 root root31 Jan 11  2011 compose.KOI8-R.inc
-rw-r--r--   1 root root31 Jan 11  2011 compose.KOI8-U.inc
-rw-r--r--   1 root root32 Jan 11  2011 compose.TIS-620.inc
-rw-r--r--   1 root root31 Dec  5  2011 compose.VISCII.inc
-rw-r--r--   1 root root  1359 Dec  5  2011 remap.inc

> cat /etc/console-setup/cached_setup_font.sh

#!/bin/sh

setfont '/etc/console-setup/Lat15-Terminus16.psf.gz' 

if ls /dev/fb* >/dev/null 2>/dev/null; then
for i in /dev/vcs[0-9]*; do
{ :
setfont '/etc/console-setup/Lat15-Terminus16.psf.gz' 
} < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
done
fi

mkdir -p /run/console-setup
> /run/console-setup/font-loaded
for i in /dev/vcs[0-9]*; do
{ :
printf '\033%%G' 
} < /dev/tty${i#/dev/vcs} > /dev/tty${i#/dev/vcs}
done


(the line starting with ">" strikes me as odd - should it not
 be on the "mkdir -p" line ?)

> cat /etc/console-setup/cached_setup_terminal.sh

#!/bin/sh

{ :
printf '\033%%G' 
} < /dev/tty${1#vcs} > /dev/tty${1#vcs}

> cat /etc/default/console-setup

# Change to "yes" and setupcon will explain what is being doing
VERBOSE_OUTPUT="no"

# Setup these consoles.  Most people do not need to change this.
ACTIVE_CONSOLES="/dev/tty[1-6]"

# Put here your encoding.  Valid charmaps are: UTF-8 ARMSCII-8 CP1251
# CP1255 CP1256 GEORGIAN-ACADEMY GEORGIAN-PS IBM1133 ISIRI-3342
# ISO-8859-1 ISO-8859-2 ISO-8859-3 ISO-8859-4 ISO-8859-5 ISO-8859-6
# ISO-8859-7 ISO-8859-8 ISO-8859-9 ISO-8859-10 ISO-8859-11 ISO-8859-13
# ISO-8859-14 ISO-8859-15 ISO-8859-16 KOI8-R KOI8-U TIS-620 VISCII
CHARMAP="UTF-8"

# The codeset determines which symbols are supported by the font.
# Valid codesets are: Arabic Armenian CyrAsia CyrKoi CyrSlav Ethiopian
# Georgian Greek Hebrew Lao Lat15 Lat2 Lat38 Lat7 Thai Uni1 Uni2 Uni3
# Vietnamese.  Read README.fonts for explanation.
CODESET="Lat15"

# Valid font faces are: VGA (sizes 8, 14 and 16), Terminus (sizes
# 12x6, 14, 16, 20x10, 

Bug#857132: console-setup: additional info needed ?

[Anton Zinoviev]

On Wed, Mar 22, 2017 at 11:29:48AM +0100, Karsten Hilbert wrote:
> 
> is there anything I can do/provide to help get this resolved ?

Yes, thanks!  The output of the following commands:

ls -l /etc/console-setup/
cat /etc/console-setup/cached_setup_font.sh
cat /etc/console-setup/cached_setup_terminal.sh
cat /etc/default/console-setup
cat /etc/default/keyboard

Anton Zinoviev

Bug#857132: console-setup: additional info needed ?

[Karsten Hilbert]

Package: console-setup
Version: 1.163
Followup-For: Bug #857132

Hi,

is there anything I can do/provide to help get this resolved ?

Thanks,
Karsten

-- System Information:
Debian Release: 9.0
  APT prefers testing
  APT policy: (990, 'testing'), (500, 'stable-updates'), (500, 'unstable'), 
(500, 'stable'), (1, 'experimental')
Architecture: i386 (i686)

Kernel: Linux 4.10.0-trunk-686-pae (SMP w/2 CPU cores)
Locale: LANG=de_DE.UTF-8, LC_CTYPE=de_DE.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages console-setup depends on:
ii  console-setup-linux 1.163
ii  debconf 1.5.60
ii  keyboard-configuration  1.163
ii  xkb-data2.19-1

console-setup recommends no packages.

Versions of packages console-setup suggests:
ii  locales   2.24-9
ii  lsb-base  9.20161125

Versions of packages keyboard-configuration depends on:
ii  debconf 1.5.60
ii  liblocale-gettext-perl  1.07-3+b1

Versions of packages console-setup-linux depends on:
ii  init-system-helpers 1.47
ii  initscripts 2.88dsf-59.9
ii  kbd 2.0.3-2+b1
ii  keyboard-configuration  1.163

console-setup-linux suggests no packages.

Versions of packages console-setup is related to:
pn  console-common
pn  console-data  
pn  console-tools 
pn  gnome-control-center  
ii  kbd   2.0.3-2+b1
ii  systemd   232-19

-- debconf information excluded