Hi,

console-setup just stopped to apply font settings during startup. This
happened before and was fixed about a year ago:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=759657

Maybe not the same reason but the faulty behaviour is back...

Manually running

	systemctl restart console-setup.service

fixes the problem until the next reboot.

Thanks for looking into the issue,
Karsten

Does this system has some read-only file systems?

Anton Zinoviev

Not that I am aware of, no.

Karsten

Hi,

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

Thanks,
Karsten

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

Here you go:

	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 root    73 Mar 22 11:20 cached_setup_terminal.sh
	-rw-r--r--   1 root root    34 Jan 11  2011 compose.ARMSCII-8.inc
	-rw-r--r--   1 root root    31 Jan 11  2011 compose.CP1251.inc
	-rw-r--r--   1 root root    31 Jan 11  2011 compose.CP1255.inc
	-rw-r--r--   1 root root    31 Jan 11  2011 compose.CP1256.inc
	-rw-r--r--   1 root root    41 Jan 11  2011 compose.GEORGIAN-ACADEMY.inc
	-rw-r--r--   1 root root    36 Jan 11  2011 compose.GEORGIAN-PS.inc
	-rw-r--r--   1 root root    32 Jan 11  2011 compose.IBM1133.inc
	-rw-r--r--   1 root root    35 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 root    36 Jan 11  2011 compose.ISO-8859-10.inc
	-rw-r--r--   1 root root    36 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 root    36 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 root    35 Jan 11  2011 compose.ISO-8859-5.inc
	-rw-r--r--   1 root root    35 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 root    35 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 root    31 Jan 11  2011 compose.KOI8-R.inc
	-rw-r--r--   1 root root    31 Jan 11  2011 compose.KOI8-U.inc
	-rw-r--r--   1 root root    32 Jan 11  2011 compose.TIS-620.inc
	-rw-r--r--   1 root root    31 Dec  5  2011 compose.VISCII.inc
	-rw-r--r--   1 root root  1359 Dec  5  2011 remap.inc

	#!/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 ?)

	#!/bin/sh

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

	# 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, 24x12, 28x14 and 32x16), TerminusBold (sizes
	# 14, 16, 20x10, 24x12, 28x14 and 32x16), TerminusBoldVGA (sizes 14
	# and 16) and Fixed (sizes 13, 14, 15, 16 and 18).  Only when
	# CODESET=Ethiopian: Goha (sizes 12, 14 and 16) and
	# GohaClassic (sizes 12, 14 and 16).
	# Set FONTFACE and FONTSIZE to empty strings if you want setupcon to
	# set up the keyboard but to leave the console font unchanged.
	FONTFACE="Terminus"
	FONTSIZE="8x16"

	# You can also directly specify nonstandard font or console map to load.
	# Use space as separator if you want to load more than one font.
	# You can use FONT_MAP in order to specify the Unicode map of the font
	# in case the font doesn't have it embedded.

	# FONT='lat9w-08.psf.gz /usr/local/share/braillefonts/brl-08.psf'
	# FONT_MAP=/usr/share/consoletrans/lat9u.uni
	# CONSOLE_MAP=/usr/local/share/consoletrans/my_special_encoding.acm

	# You can also specify a screen size that setupcon will enforce.  This can not
	# exceed what the current screen resolution can display according to the size of
	# the loaded font.
	#
	# SCREEN_WIDTH=80
	# SCREEN_HEIGHT=25

	if [ -f /etc/default/keyboard ]; then
	    . /etc/default/keyboard
	fi

	# Check /usr/share/doc/keyboard-configuration/README.Debian for
	# documentation on what to do after having modified this file.

	# The following variables describe your keyboard and can have the same
	# values as the XkbModel, XkbLayout, XkbVariant and XkbOptions options
	# in /etc/X11/xorg.conf.

	XKBMODEL="pc105"
	XKBLAYOUT="de"
	XKBVARIANT="nodeadkeys"
	XKBOPTIONS=""

	# If you don't want to use the XKB layout on the console, you can
	# specify an alternative keymap.  Make sure it will be accessible
	# before /usr is mounted.
	# KMAP=/etc/console-setup/defkeymap.kmap.gz
	BACKSPACE="guess"

HTH,
Karsten

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?

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

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.

These look ok as well...

Anton Zinoviev

	systemctl restart console-setup.service

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

See above.

Likely because of the above, too.

I eventually figured as much...

OK, got it.

Feel free to ask for more information you may need.

Thanks,
Karsten

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.

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

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

Attached.

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

Karsten

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

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

It does, yes.

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

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

Karsten

Attached find a script running setupcon and the output thereof.

Karsten

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

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

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

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

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

... lengthy analysis ...

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

Am 23.03.2017 um 14:04 schrieb Anton Zinoviev:

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

This is good, but...

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

Am 23.03.2017 um 14:58 schrieb Anton Zinoviev:

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

Well, whoever does it... :)

Anton Zinoviev

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

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

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?

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

The kernel?


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

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

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

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=0xf89b0000, 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 sec (nowayout=0)
	Mär 24 11:31:45 hermes mtp-probe[477]: checking bus 7, device 2: "/sys/devices/pci0000:00/0000:00:1a.7/usb7/7-3"
	Mär 24 11:31:45 hermes mtp-probe[477]: bus: 7, device: 2 was not an MTP device
	Mär 24 11:31:45 hermes systemd[1]: Reached target Sound Card.
	Mär 24 11:31:45 hermes mtp-probe[541]: checking bus 4, device 3: "/sys/devices/pci0000:00/0000:00:1d.0/usb4/4-2"
	Mär 24 11:31:45 hermes mtp-probe[541]: bus: 4, device: 3 was not an MTP device
	Mär 24 11:31:46 hermes systemd[1]: Started Load/Save RF Kill Switch Status.
	Mär 24 11:31:46 hermes systemd[1]: Found device ST9320325AS 5.
	Mär 24 11:31:46 hermes systemd[1]: Activating swap /dev/disk/by-uuid/d6e3928c-5468-449e-a777-af84dbc668ff...
	Mär 24 11:31:47 hermes kernel: Adding 6014972k swap on /dev/sda5.  Priority:1 extents:1 across:6014972k FS
	Mär 24 11:31:47 hermes systemd[1]: Activated swap /dev/disk/by-uuid/d6e3928c-5468-449e-a777-af84dbc668ff.
	Mär 24 11:31:47 hermes systemd[1]: Reached target Swap.
	Mär 24 11:31:47 hermes systemd[1]: Reached target System Initialization.
	Mär 24 11:31:47 hermes systemd[1]: Listening on CUPS Scheduler.
	Mär 24 11:31:47 hermes systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
	Mär 24 11:31:47 hermes systemd[1]: Listening on D-Bus System Message Bus Socket.
	Mär 24 11:31:47 hermes systemd-udevd[290]: Process '/sbin/crda' failed with exit code 249.
	Mär 24 11:31:47 hermes systemd[1]: apt-daily.timer: Adding 8h 27min 31.003476s random time.
	Mär 24 11:31:47 hermes systemd[1]: Started Daily apt activities.
	Mär 24 11:31:47 hermes systemd[1]: Listening on GPS (Global Positioning System) Daemon Sockets.
	Mär 24 11:31:47 hermes systemd[1]: Listening on PC/SC Smart Card Daemon Activation Socket.
	Mär 24 11:31:47 hermes systemd[1]: Listening on ACPID Listen Socket.
	Mär 24 11:31:47 hermes systemd[1]: Listening on ACPI fakekey daemon FIFO.
	Mär 24 11:31:47 hermes systemd[1]: Reached target Sockets.
	Mär 24 11:31:47 hermes systemd[1]: Started Daily Cleanup of Temporary Directories.
	Mär 24 11:31:47 hermes systemd[1]: Reached target Timers.
	Mär 24 11:31:47 hermes systemd[1]: Started ACPI Events Check.
	Mär 24 11:31:47 hermes systemd[1]: Reached target Paths.
	Mär 24 11:31:47 hermes systemd[1]: Reached target Basic System.
	Mär 24 11:31:47 hermes systemd[1]: Started Regular background program processing daemon.
	Mär 24 11:31:47 hermes systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
	Mär 24 11:31:47 hermes systemd[1]: Starting Save/Restore Sound Card State...
	Mär 24 11:31:47 hermes systemd[1]: Started Run anacron jobs.
	Mär 24 11:31:47 hermes systemd[1]: Starting Restore /etc/resolv.conf if the system crashed before the ppp link was shut down...
	Mär 24 11:31:47 hermes cron[694]: (CRON) INFO (pidfile fd = 3)
	Mär 24 11:31:48 hermes anacron[701]: Anacron 2.3 started on 2017-03-24

Here are console related messages:

	Mär 24 11:31:35 hermes kernel: console [tty0] enabled
	Mär 24 11:31:35 hermes kernel: NMI watchdog: enabled on all CPUs, permanently consumes one hw-PMU counter.
	Mär 24 11:31:35 hermes kernel: mtrr: your CPUs had inconsistent variable MTRR settings
	Mär 24 11:31:36 hermes systemd[1]: Started Set the console keyboard layout.
	Mär 24 11:31:36 hermes systemd[1]: Starting Set console font and keymap...
	Mär 24 11:31:37 hermes systemd[1]: Started Set console font and keymap.
	Mär 24 11:31:41 hermes kernel: [drm] Replacing VGA console driver
	Mär 24 11:32:21 hermes rc.local[1010]: adjusting default console log level
	Mär 24 11:34:26 hermes /usr/sbin/gpm[806]: Request on 6 (console 2)
	Mär 24 11:44:29 hermes /usr/sbin/gpm[806]: Request on 7 (console 6)
	...
	Mär 24 11:31:43 hermes kernel: fbcon: inteldrmfb (fb0) is primary device
	...
	Mär 24 11:31:43 hermes kernel: Console: switching to colour frame buffer device 170x48
	Mär 24 11:31:43 hermes kernel: i915 0000:00:02.0: fb0: inteldrmfb frame buffer device

Anything else I can try ?

HTH,
Karsten

One more data point:

...

...

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

Thanks a lot! :)

Maybe this happened because cached_setup_font.sh was run while / was
still read-only?
the console is never configured properly?  Or sometimes it is?

Anton Zinoviev

That is what I can contribute.

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

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

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

Anton Zinoviev

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

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

Thanks,
Karsten

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 <tiwai@suse.de>
	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 <tiwai@suse.de>
	    Signed-off-by: Bartlomiej Zolnierkiewicz <b.zolnierkie@samsung.com>
	    Cc: Arnd Bergmann <arnd@arndb.de>
	    Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

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

Hello,

it's been also over a year since I've been plagued by this issue but I
managed to solve it by purging the console-setup cache every time on
shutdown with the following service file:

Thanks! This helped solve the problem.

The only thing that slightly corrected, it replaced "rm /etc/console-setup/cached_*" by "/bin/rm /etc/console-setup/cached_*"

An interesting moment here: font is applied correctly when you use HD
resolution (3440x1440) in my case, you need UEFI boot for Nvdia and change
to auto resolution grub. Only when you use low resolution the problem shows
itself. Also apparently default font does not support cyrillic unicode...
LOL.

-- 
Hallo,
Bitte nehmen Sie meine Entschuldigung an. Ich möchte nicht in Ihre
Privatsphäre eindringen, ich bin Felix Joel, Rechtsanwalt von Beruf.
Ich habe Ihnen eine frühere Mail geschrieben, aber ohne Antwort, und
in meiner ersten Mail habe ich Ihnen von meinem verstorbenen Mandanten
erzählt, der denselben Nachnamen trägt wie Sie. Seit seinem Tod habe
ich mehrere Briefe von seiner Bank erhalten, in denen er vor seinem
Tod eine Einzahlung getätigt hat. Die Bank hat mich gebeten, seine
nächsten Angehörigen oder einen seiner Verwandten anzugeben, die
Anspruch auf sein Geld erheben können, oder es wird beschlagnahmt und
seitdem Ich konnte keinen seiner Verwandten ausfindig machen. Ich
beschloss, Sie wegen dieser Behauptung zu kontaktieren, daher haben
Sie denselben Nachnamen wie er. kontaktieren sie mich dringend für
weitere details.
Aufrichtig,
Rechtsanwalt Felix Joel.

Hello, I found your email on my contact list, i think we must have met
before on a social network, my name is Ulyana Soroka i am from USA, i will
be coming for vacation in your country. Would you like us to meet?



Have a nice moment!

Hi,

I have had this font loading problem with all versions of Debian since
version 9. I have seen the font selected in '/etc/default/console-setup'
be loaded on a very few system boots when using a normal kernel, but never
when using a PREEMPT_RT kernel [in real hardware, not VMs]. I have also
confirmed that whenever the plymouth package is installed and the system
is configured to boot with the graphical boot splash, the selected font
can not be loaded while the splash is visible, but can be loaded if the
splash is hidden for a small period of time (just enough for setfont to
work it's magic).

In my humble opinion, there are two main reasons that cause the font
loading problem:

1) The rules implemented in file '/lib/udev/rules.d/90-console-setup.rules'
   violate one of the udev conditions for the RUN assignment option as
   expressed in the udev manpage: