Bug#906266: Found the problem and a solution

Thu Aug 16 11:09:38 BST 2018

Thanks for the suggestion, Simon. I think I found the problem.

This is the system log from my login (I did the login precisely at 
11:48:00 on purpose):

Aug 16 11:48:00 debian systemd-timesyncd[564]: Synchronized to time 
server 147.156.7.26:123 (2.debian.pool.ntp.org).
Aug 16 11:48:00 debian kernel: [   35.090731] logitech-hidpp-device 
0003:046D:2011.0006: HID++ 1.0 device connected.
Aug 16 11:48:00 debian upowerd[823]: treating change event as add on 
/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.7/2-1.7:1.2/0003:046D:C52B.0003/0003:046D:2011.0006/power_supply/hidpp_battery_0
Aug 16 11:48:00 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:00 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:01 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:01 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:01 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:02 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:02 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:02 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:02 debian gnome-shell[964]: JS ERROR: TypeError: 
this._currentWindow is 
null#012_setCurrentRect at resource:///org/gnome/shell/ui/keyboard.js:536:13#012wrapper at resource:///org/gnome/gjs/modules/_legacy
.js:82:22#012_init/<@resource:///org/gnome/shell/ui/keyboard.js:503:13
Aug 16 11:48:03 debian systemd[1]: Started /run/user/1000 mount wrapper.
Aug 16 11:48:03 debian systemd[1]: Created slice User Slice of UID 1000.
Aug 16 11:48:03 debian systemd[1]: Starting User Manager for UID 1000...
Aug 16 11:48:03 debian systemd[1]: Started Session 5 of user raster.
Aug 16 11:48:03 debian systemd[1222]: Starting D-Bus User Message Bus 
Socket.
Aug 16 11:48:03 debian systemd[1222]: Listening on GnuPG cryptographic 
agent and passphrase cache (access for web browsers).
Aug 16 11:48:03 debian systemd[1222]: Reached target Timers.
Aug 16 11:48:03 debian systemd[1222]: Listening on GnuPG network 
certificate management daemon.
Aug 16 11:48:03 debian systemd[1222]: Reached target Paths.
Aug 16 11:48:03 debian systemd[1222]: Listening on GnuPG cryptographic 
agent and passphrase cache.
Aug 16 11:48:03 debian systemd[1222]: Listening on GnuPG cryptographic 
agent and passphrase cache (restricted).
Aug 16 11:48:03 debian systemd[1222]: Listening on Sound System.
Aug 16 11:48:03 debian systemd[1222]: Listening on GnuPG cryptographic 
agent (ssh-agent emulation).
Aug 16 11:48:03 debian systemd[1222]: Listening on D-Bus User Message 
Bus Socket.
Aug 16 11:48:03 debian systemd[1222]: Reached target Sockets.
Aug 16 11:48:03 debian systemd[1222]: Reached target Basic System.
Aug 16 11:48:03 debian systemd[1222]: Reached target Default.
Aug 16 11:48:03 debian systemd[1222]: Startup finished in 41ms.
Aug 16 11:48:03 debian systemd[1]: Started User Manager for UID 1000.
Aug 16 11:52:14 debian kernel: [  289.016099] random: crng init done
Aug 16 11:52:14 debian kernel: [  289.016102] random: 7 urandom 
warning(s) missed due to ratelimiting
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: (--) Log file 
renamed from "/home/raster/.local/share/xorg/Xorg.pid-1245.log" to 
"/home/raster/.local/share/xorg/Xorg.0.log"
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: X.Org X Server 
1.20.0
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: X Protocol 
Version 11, Revision 0
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: Build 
Operating System: Linux 4.9.0-6-amd64 x86_64 Debian
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: Current 
Operating System: Linux debian 4.17.0-2-amd64 #1 SMP Debian 4.17.14-1 
(2018-08-13) x86_64
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: Kernel command 
line: BOOT_IMAGE=/boot/vmlinuz-4.17.0-2-amd64 
root=UUID=4c9bc424-fc38-42b5-a056-8b48036de8c1 ro quiet
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: Build Date: 01 
July 2018  05:07:24PM
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: xorg-server 
2:1.20.0-3 (https://www.debian.org/support)
Aug 16 11:52:15 debian /usr/lib/gdm3/gdm-x-session[1243]: Current 
version of pixman: 0.34.0

The lines

Aug 16 11:48:03 debian systemd[1]: Started User Manager for UID 1000.
Aug 16 11:52:14 debian kernel: [  289.016099] random: crng init done

show the problem: the random number generator is blocking the login 
process. That explains why moving the mouse reduces the login time: it 
generates entropy for the generator.

With this information I searched in google and, funny enough, the bug 
has been reported in several places, but I couldn't find it here...

https://unix.stackexchange.com/questions/442698/when-i-log-in-it-hangs-until-crng-init-done

https://www.linuxquestions.org/questions/debian-26/debian-hangs-at-boot-with-random-crng-init-done-4175613405/

In these pages they recommend to install the package rng-tools5. I tried 
it and worked, but there also says that it only works in machines with 
hardware support for random numbers, like Intel Ivy Bridge and later 
systems...

-- 
Nos leemos
		         RASTER    (Linux user #228804)
raster at rastersoft.com              http://www.rastersoft.com