Re: lightdm (testing): Long waiting time after login

[songbird]

Dino wrote:
> This is a multi-part message in MIME format.
> --------------D295C2A19D414A0F9C32AEE8
> Content-Type: multipart/alternative;
> boundary="------------51A034E61483D85CC097E79C"
>
>
> --------------51A034E61483D85CC097E79C
> Content-Type: text/plain; charset=utf-8; format=flowed
> Content-Transfer-Encoding: 7bit
>
> This time with attachment...
>
> Am 16.05.2018 um 09:28 schrieb wo...@hllmnn.de:
>>
>> I just did a fresh install of testing with XFCE. After entering the
>> login credentials the screen was black for 30-60 seconds before the
>> desktop environment showed up. Assuming a bug in XFCE, I performed
>> another fresh install with MATE, but a similar effect occured: after
>> login the background image is shown for 30-60 seconds before the
>> desktop is fully loaded.
>>
>> A look into /var/log/lightdm/lightdm.log showed that the delay happens
>> before VT is activated. The log file is attached.
>>
>> Might this be a bug in lightdm or could a misconfiguragtion from my
>> side cause this issue?
...
> [+7.71s] DEBUG: Session pid=691: Running command /etc/X11/Xsession default
> [+7.71s] DEBUG: Creating shared data directory /var/lib/lightdm/data/USERNAME
> [+7.71s] DEBUG: Session pid=691: Logging to .xsession-errors
> [+40.89s] DEBUG: Activating VT 7
> [+40.89s] DEBUG: Activating login1 session 2
> [+40.89s] DEBUG: Seat seat0 changes active session to
> [+40.89s] DEBUG: Seat seat0 changes active session to 2
> [+40.89s] DEBUG: Session 2 is already active

what does .xsession-errors say?

what type of device are you installing to?

my recent installs with netinst for testing and having MATE
comes up ok (within a few seconds), but things may have changed
in packages.

does a stable netinst give same results?


songbird

[Dino]

.xsession-errors contains one warning (file is attached), but I don't
think that it causes the delay.

The device I'm installing to is an UDOO X86
(https://www.udoo.org/udoo-x86/). Basically, it's standard hardware with
an Intel CPU. I already had an installation of testing a few months ago
that didn't show this behaviour.

A stable netinst works just fine, the desktop is loaded almost
immediately. Hence, I assume a package changed recently is the reason
for this.

[Dominic Knight]

Maybe;
systemd-analyze critical-chain
&
systemd-analyze blame
will give a clue as to what is taking its time?

Dom.

[Ben Caradoc-Davies]

On 16/05/18 19:28, wo...@hllmnn.de wrote:
> I just did a fresh install of testing with XFCE. After entering the login
> credentials the screen was black for 30-60 seconds before the desktop
> environment showed up. Assuming a bug in XFCE, I performed another fresh install
> with MATE, but a similar effect occured: after login the background image is
> shown for 30-60 seconds before the desktop is fully loaded.

What happens if you wiggle your mouse or provide keyboard activity while
waiting? For example, if you wiggle your mouse vigorously for two
seconds or press the Alt key 20 times? Does the wait end sooner?

In Linux 4.16, the getrandom system call (without the GRND_NONBLOCK
flag) blocks until sufficient entropy is available in the pool. This is
the documented behaviour, and Linux 4.16 now enforces it to fix
CVE-2018-1108. This has caught out several services that try to use
getrandom (without the GRND_NONBLOCK flag) at early boot, including
plymouth (via fontconfig) and gdm3. What you see might have the same
cause. For details of my investigation, see:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=897572

Wiggling your mouse or providing keyboard activity adds entropy to the
pool. If this reduces the waiting time, you might be affected by the
same bug.

Kind regards,

--
Ben Caradoc-Davies <b...@transient.nz>
Director
Transient Software Limited <https://transient.nz/>
New Zealand

[Dino]

The output of systemd-analyze looks fine, I think. It really seems like
the bug reported at
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=897572 is causing the
trouble.

[Dino]

Hi Ben,

Yes, you're right! When I wiggle the mouse the wait ends sooner. Indeed,
if I don't move the mouse at all and don't press any key the screen just
stays blank (I waited approx. 5 minutes and it still was black).

I attached the output of dmesg | grep "random". As you can see, "crng
init done" appears after the 5 minutes I waited.

Since there is no "splash" in my kernel command line in grub, I added
"noplymouth" to it, but that didn't help. Maybe it's another package
that calls getrandom without GRND_NONBLOCK. Let me know if I can support
the investigation somehow.

Kind regards,
Dino

[Curt]

On 2018-05-17, Dino <wo...@hllmnn.de> wrote:
>
> Yes, you're right! When I wiggle the mouse the wait ends sooner. Indeed,
> if I don't move the mouse at all and don't press any key the screen just
> stays blank (I waited approx. 5 minutes and it still was black).
>

https://wiki.archlinux.org/index.php/LightDM#LightDM_freezes_on_login_attempt

https://bbs.archlinux.org/viewtopic.php?id=179031*

Perhaps related to your issue.

[Ben Caradoc-Davies]

On 17/05/18 21:02, Dino wrote:
> Yes, you're right! When I wiggle the mouse the wait ends sooner. Indeed,
> if I don't move the mouse at all and don't press any key the screen just
> stays blank (I waited approx. 5 minutes and it still was black).
> I attached the output of dmesg | grep "random". As you can see, "crng
> init done" appears after the 5 minutes I waited.

Yes, this seems to confirm my suspicion that something is blocking by
calling getrandom without GRND_NONBLOCK.

> Since there is no "splash" in my kernel command line in grub, I added
> "noplymouth" to it, but that didn't help. Maybe it's another package
> that calls getrandom without GRND_NONBLOCK. Let me know if I can support
> the investigation somehow.

The situation you describe does not implicate plymouth, because the
pause occurs after you enter your credentials. This is a tricky one,
because it could be lightdm, or systemd which is a known offender, xorg,
or anything else in your session. This is a tricky problem to diagnose
because, as soon as you start typing, your login will complete. I
suggest reporting this against lightdm to get maintainer advice. The
Debian Xfce and lightdm maintainer has commented on #897572 and is aware
of the getrandom issue, but I could not find any lightdm issue for it.

Which iso image did you use to install testing?

[Dino]

Seems like there is a related lightdm issue:
https://github.com/CanonicalLtd/lightdm/issues/17
I added a comment pointing to the #897572 bug report. In addition, I
also installed GDM to see whether the same problem occurs. Indeed, not
even the login screen is shown before I have pressed some keys.

To install testing I used the latest weekly build of the netinstaller
with non-free firmware (firmware-testing-amd64-netinst.iso).

Best regards,
Dino

[songbird]

it looks like the issue is known to many in various lists
i'm reading (kernel, debian-kernel) and is being worked on
but in the meantime i'm not sure how to get around it.

that i'm not seeing it using MATE desktop i'm not sure why
but i've gone a convoluted route sometimes and perhaps i don't
have parts installed that you have... then again i'm also
using auto logon feature.

do you have automatic logon set in your lightdm configuration?


songbird

[Dino]

Yes, auto logon is configured since I want to use the PC as an embedded
system. Therefore, I'm also looking for a workaround because I cannot
connect a mouse or a keyboard.

Surprisingly, this behaviour does not occur on my desktop running
testing with all packages upgraded to the same versions...

Dino

[Ben Caradoc-Davies]

On 19/05/18 01:57, Dino wrote:
> Surprisingly, this behaviour does not occur on my desktop running
> testing with all packages upgraded to the same versions...

If you have a wired network device and are on a busy network, your
network device might generate enough entropy. One other possibility is
that the hang occurs in some software that is not installed on your desktop.

I can reproduce the hang in a VM with a testing system installed from
the 14 May weekly testing iso. I will try using a custom kernel with a
printk in getrandom to confirm the guilty process, as I did for #897572.

[Ben Caradoc-Davies]

On 19/05/18 09:59, Ben Caradoc-Davies wrote:
> I can reproduce the hang in a VM with a testing system installed from
> the 14 May weekly testing iso. I will try using a custom kernel with a
> printk in getrandom to confirm the guilty process, as I did for #897572.

The cause is xfce4-session. I will file a bug report.

Test kernel:
Linux getrandom-testing 4.16.0-1-amd64 #1 SMP Debian
4.16.5-1+getrandom+printk+dump+stack (2018-05-08) x86_64 GNU/Linux

This kernel is 4.16.5-1 plus these two patches (against torvalds/linux
master but they apply cleanly against the stable tree):
https://github.com/bencaradocdavies/linux/commit/f0dfb0b7b72e38093aeaa67fe1116b409c1db3dc
https://github.com/bencaradocdavies/linux/commit/19e47d7049c6ca94b98cf8c00bbeb2384a9c43b9
https://github.com/bencaradocdavies/linux/tree/getrandom-printk-dump-stack

The evidence seen in the journalctl when booting with "debug" and not
"quiet" on the kernel command line:

May 19 11:09:39 getrandom-testing kernel: random: xfce4-session:
getrandom without GRND_NONBLOCK while crng not ready
May 19 11:09:39 getrandom-testing kernel: CPU: 0 PID: 587 Comm:
xfce4-session Not tainted 4.16.0-1-amd64 #1 Debian
4.16.5-1+getrandom+printk+dump+stack
May 19 11:09:39 getrandom-testing kernel: Hardware name: QEMU Standard
PC (i440FX + PIIX, 1996), BIOS 1.11.1-1 04/01/2014
May 19 11:09:39 getrandom-testing kernel: Call Trace:
May 19 11:09:39 getrandom-testing kernel: dump_stack+0x5c/0x85
May 19 11:09:39 getrandom-testing kernel: SyS_getrandom+0xab/0xc0
May 19 11:09:39 getrandom-testing kernel: do_syscall_64+0x6c/0x130
May 19 11:09:39 getrandom-testing kernel:
entry_SYSCALL_64_after_hwframe+0x3d/0xa2
May 19 11:09:39 getrandom-testing kernel: RIP: 0033:0x7fdb3e1038f9
May 19 11:09:39 getrandom-testing kernel: RSP: 002b:00007ffd434e7ba8
EFLAGS: 00000246 ORIG_RAX: 000000000000013e
May 19 11:09:39 getrandom-testing kernel: RAX: ffffffffffffffda RBX:
0000000000000028 RCX: 00007fdb3e1038f9
May 19 11:09:39 getrandom-testing kernel: RDX: 0000000000000000 RSI:
0000000000000028 RDI: 00007ffd434e7cb0
May 19 11:09:39 getrandom-testing kernel: RBP: 00007fdb41e02a00 R08:
0000000000000000 R09: 0000000000000000
May 19 11:09:39 getrandom-testing kernel: R10: 00007fdb3d4f0140 R11:
0000000000000246 R12: 00007ffd434e7cb0
May 19 11:09:39 getrandom-testing kernel: R13: 0000000000000002 R14:
0000000000000010 R15: 0000558569895400

[Ben Caradoc-Davies]

On 19/05/18 11:28, Ben Caradoc-Davies wrote:
> The cause is xfce4-session. I will file a bug report.

Bug#899080: xfce4-session hangs in getrandom if crng not ready
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=899080

I think this is a symptom of Bug#898088 in libbsd0:

Bug#898088: arc4random_buf() may block for a long time
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=898088

xfce4-session uses IceGenerateMagicCookie and thus arc4random_buf to
generate MIT-MAGIC-COOKIE-1.

I will merge these issues. You can also watch for updates on the source
package page:
https://tracker.debian.org/pkg/libbsd

[Ben Caradoc-Davies]

On 19/05/18 13:07, Ben Caradoc-Davies wrote:
> On 19/05/18 11:28, Ben Caradoc-Davies wrote:
>> The cause is xfce4-session. I will file a bug report.
> Bug#899080: xfce4-session hangs in getrandom if crng not ready
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=899080
> I think this is a symptom of Bug#898088 in libbsd0:
> Bug#898088: arc4random_buf() may block for a long time
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=898088
> xfce4-session uses IceGenerateMagicCookie and thus arc4random_buf to
> generate MIT-MAGIC-COOKIE-1.

Fixed in libbsd/0.8.7-1.1 on unstable:
https://tracker.debian.org/news/958795/accepted-libbsd-087-11-source-into-unstable/
"Switch Linux getrandom() usage to non-blocking mode, continuing to use
fallback mechanims if unsuccessful. Closes: #898088"

I installed libbsd0_0.8.7-1.1_amd64.deb on a buster VM and it no longer
hangs after lightdm credentials are entered (the xfce4-session hang
reported in #899080):
http://ftp.debian.org/debian/pool/main/libb/libbsd/libbsd0_0.8.7-1.1_amd64.deb

Packages for other architectures here:
http://ftp.debian.org/debian/pool/main/libb/libbsd

[Dino]

Hi Ben,

I can confirm that libbsd/0.8.7-1.1 fixes the problem here, too.

Thanks a lot for your investigation!

Best,
Dino

[Ben Caradoc-Davies]

On 22/05/18 19:50, Dino wrote:
> I can confirm that libbsd/0.8.7-1.1 fixes the problem here, too.

Great!

I also found that xfce4-terminal hangs in getrandom if started
immediately after boot and lightdm login. This one is not fixed by the
libsdb upgrade. I have reported it:

Bug#899271: xfce4-terminal hangs in getrandom if crng not ready
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=899271

[Glenn English]

On Tue, May 22, 2018 at 10:47 PM, Ben Caradoc-Davies <b...@transient.nz> wrote:
> On 22/05/18 19:50, Dino wrote:
>>
>> I can confirm that libbsd/0.8.7-1.1 fixes the problem here, too.
>
>
> Great!
>
> I also found that xfce4-terminal hangs in getrandom if started immediately
> after boot and lightdm login. This one is not fixed by the libsdb upgrade. I
> have reported it:
>
> Bug#899271: xfce4-terminal hangs in getrandom if crng not ready
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=899271

I may be wrong, but I don't think it's XFCE4. I'm running Buster and
XFCE4 and Slim on a couple computers, and there's no problem with
Slim.

IIRC (and I may not RC) I noticed that hang in the few minutes between
the XFCE4 install and the lightdm replacement.

--
Glenn English

[Ben Caradoc-Davies]

On 24/05/18 04:48, Glenn English wrote:
> On Tue, May 22, 2018 at 10:47 PM, Ben Caradoc-Davies <b...@transient.nz> wrote:
>> I also found that xfce4-terminal hangs in getrandom if started immediately
>> after boot and lightdm login. This one is not fixed by the libsdb upgrade. I
>> have reported it:
> Bug#899271: xfce4-terminal hangs in getrandom if crng not ready
>> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=899271
> I may be wrong, but I don't think it's XFCE4. I'm running Buster and
> XFCE4 and Slim on a couple computers, and there's no problem with
> Slim.

I know that I am right and I have the kernel printk and stack dump and
xfce4-terminal ltrace -S to prove it. :-)

It looks like the hang is in g_object_new from Gnome gobject.

That said, you are also right: I do not see this on my sid desktop
because, by the time I have typed in my LUKS passphrase and logged in
and my network adapter has connected, the system has sufficient entropy
and getrandom does not hang. I *only* see the hang on a buster VM
without LUKS, with shorter username and password, and the VM will get a
lot less network traffic. Under these circumstances, with xfce4-terminal
started in the Xfce session, the hang occurs every time. My
investigation into a plymouth hang in getrandom (#897572) showed that
11-18 keystrokes are sufficient to stop getrandom from hanging, so if
your username + Tab + password + Enter is long enough, you should be
safe. :-D

[Glenn English]

On Wed, May 23, 2018 at 10:11 PM, Ben Caradoc-Davies <b...@transient.nz> wrote:

>> Bug#899271: xfce4-terminal hangs in getrandom if crng not ready

What in heaven's name is a terminal emulator doing in getrandom? Have
you tried with a different terminal? There seem to be several in
XFCE4.

> I know that I am right and I have the kernel printk and stack dump and
> xfce4-terminal ltrace -S to prove it. :-)

Like I said, I may be wrong :-)

--
Glenn English

[Ben Caradoc-Davies]

On 25/05/18 01:42, Glenn English wrote:
> On Wed, May 23, 2018 at 10:11 PM, Ben Caradoc-Davies <b...@transient.nz> wrote:
>>> Bug#899271: xfce4-terminal hangs in getrandom if crng not ready
> What in heaven's name is a terminal emulator doing in getrandom?

Indeed. It seems that gnutls_rnd is called when creating a
VteFileStream. I added a gdb backtrace to the bug report.

> Have
> you tried with a different terminal? There seem to be several in
> XFCE4.

My fallback terminal is good old xterm. With tiny fonts, xterm is
especially useful for those occasions when I just have to have 16
terminals on the screen at once.