Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1

To: 912087@bugs.debian.org, 912087-submitter@bugs.debian.org
Subject: Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
From: Bernhard Übelacker <bernhardu@mailbox.org>
Date: Sun, 28 Oct 2018 11:41:14 +0100
Message-id: <[🔎] fbe20610-4589-f827-69a9-fcdf028ac36d@mailbox.org>
Reply-to: Bernhard Übelacker <bernhardu@mailbox.org>, 912087@bugs.debian.org
In-reply-to: <[🔎] 154070458824.7875.5742628083142648872.reportbug@mitsos>
References: <[🔎] 154070458824.7875.5742628083142648872.reportbug@mitsos> <[🔎] 154070458824.7875.5742628083142648872.reportbug@mitsos> <[🔎] 154070458824.7875.5742628083142648872.reportbug@mitsos>

Dear Maintainer,
just some more information, because I think I see this
difference in my qemu buster amd64 VM too.

Before I could ssh into that machine just after some seconds.

Now it takes some time until that line "random: crng init done"
appears in dmesg.
With logging in in the qemu window this line appears just after a
few seconds, when just trying via ssh it takes much longer.


I tried to find out where it blocks exactly and came to that location:

#0  0x00007fb515b1803a in getentropy (buffer=0x56285633d440, length=length@entry=32) at ../sysdeps/unix/sysv/linux/getentropy.c:45
#1  0x00007fb5161e3603 in syscall_random (buflen=32, buf=<optimized out>) at ../crypto/rand/rand_unix.c:277
#2  rand_pool_acquire_entropy (pool=pool@entry=0x5628563394e0) at ../crypto/rand/rand_unix.c:469
#3  0x00007fb5161e2d8d in rand_drbg_get_entropy (drbg=0x562856339e80, pout=0x7ffd1c2bce60, entropy=<optimized out>, min_len=<optimized out>, max_len=<optimized out>, prediction_resistance=0) at ../crypt$
#4  0x00007fb5161e11b2 in RAND_DRBG_instantiate (drbg=drbg@entry=0x562856339e80, pers=pers@entry=0x7fb516289d20 <ossl_pers_string> "OpenSSL NIST SP 800-90A DRBG", perslen=perslen@entry=28) at ../crypto/$
#5  0x00007fb5161e21a8 in drbg_setup (parent=parent@entry=0x0) at ../crypto/rand/drbg_lib.c:870
#6  0x00007fb5161e222f in do_rand_drbg_init () at ../crypto/rand/drbg_lib.c:899
#7  do_rand_drbg_init_ossl_ () at ../crypto/rand/drbg_lib.c:884
#8  0x00007fb5150c9827 in __pthread_once_slow (once_control=0x7fb5163118f8 <rand_drbg_init>, init_routine=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at pthread_once.c:116
#9  0x00007fb5150c98e5 in __GI___pthread_once (once_control=once_control@entry=0x7fb5163118f8 <rand_drbg_init>, init_routine=init_routine@entry=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at pthread_once.$
#10 0x00007fb516221329 in CRYPTO_THREAD_run_once (once=once@entry=0x7fb5163118f8 <rand_drbg_init>, init=init@entry=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at ../crypto/threads_pthread.c:113
#11 0x00007fb5161e2327 in RAND_DRBG_get0_master () at ../crypto/rand/drbg_lib.c:1010
#12 0x00007fb5161e235d in drbg_status () at ../crypto/rand/drbg_lib.c:992
#13 0x00005628556a253f in seed_rng () at ../../entropy.c:238
#14 0x000056285564b13c in main (ac=2, av=0x56285631b970) at ../../sshd.c:1696

Most of the stack is inside /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
e.g libssl1.1 that got also a new upload at that time.


Attached file describes how I retrieved that stack and some more logging.
(For my qemu machine a workaround would just be
to add "-device virtio-rng-pci", to have proper randomness.)

Kind regards,
Bernhard

apt install tmux psmisc gdb openssh-server-dbgsym libssl1.1-dbgsym

root@debian:~# cat /etc/rc.local 
#!/bin/sh

tmux new-session -d /root/info.sh


root@debian:~# cat /root/info.sh 
#!/bin/bash

while true; do
        sleep 4s;
        echo "-----"
        date
        pstree -p
        gdb -q --pid $(pgrep sshd | head -n1) -ex "set width 0" -ex "set pagination off" -ex bt -ex "info share" -ex detach -ex quit
done > /root/info.txt



bernhard@rechner:~/data/emu/pc/qemu/machines/debian-10-buster-x86_64_minimal$ ssh -p2222 benutzer@$LOCALIP
ssh_exchange_identification: read: Connection reset by peer
bernhard@rechner:~/data/emu/pc/qemu/machines/debian-10-buster-x86_64_minimal$ ssh -p2222 benutzer@$LOCALIP
ssh_exchange_identification: Connection closed by remote host
bernhard@rechner:~/data/emu/pc/qemu/machines/debian-10-buster-x86_64_minimal$ date



-----------
root@debian:~# systemd-analyze blame
         42.567s ssh.service


So 28. Okt 11:10:35 CET 2018
#0  0x00007fca559de03a in getentropy (buffer=0x5639798b5440, length=length@entry=32) at ../sysdeps/unix/sysv/linux/getentropy.c:45
#1  0x00007fca560a9603 in syscall_random (buflen=32, buf=<optimized out>) at ../crypto/rand/rand_unix.c:277
#2  rand_pool_acquire_entropy (pool=pool@entry=0x5639798b14e0) at ../crypto/rand/rand_unix.c:469
#3  0x00007fca560a8d8d in rand_drbg_get_entropy (drbg=0x5639798b1e80, pout=0x7ffd93325640, entropy=<optimized out>, min_len=<optimized out>, max_len=<optimized out>, prediction_resistance=0) at ../crypt$
#4  0x00007fca560a71b2 in RAND_DRBG_instantiate (drbg=drbg@entry=0x5639798b1e80, pers=pers@entry=0x7fca5614fd20 <ossl_pers_string> "OpenSSL NIST SP 800-90A DRBG", perslen=perslen@entry=28) at ../crypto/$
#5  0x00007fca560a81a8 in drbg_setup (parent=parent@entry=0x0) at ../crypto/rand/drbg_lib.c:870
#6  0x00007fca560a822f in do_rand_drbg_init () at ../crypto/rand/drbg_lib.c:899
#7  do_rand_drbg_init_ossl_ () at ../crypto/rand/drbg_lib.c:884
#8  0x00007fca54f8f827 in __pthread_once_slow (once_control=0x7fca561d78f8 <rand_drbg_init>, init_routine=0x7fca560a81d0 <do_rand_drbg_init_ossl_>) at pthread_once.c:116
#9  0x00007fca54f8f8e5 in __GI___pthread_once (once_control=once_control@entry=0x7fca561d78f8 <rand_drbg_init>, init_routine=init_routine@entry=0x7fca560a81d0 <do_rand_drbg_init_ossl_>) at pthread_once.$
#10 0x00007fca560e7329 in CRYPTO_THREAD_run_once (once=once@entry=0x7fca561d78f8 <rand_drbg_init>, init=init@entry=0x7fca560a81d0 <do_rand_drbg_init_ossl_>) at ../crypto/threads_pthread.c:113
#11 0x00007fca560a8327 in RAND_DRBG_get0_master () at ../crypto/rand/drbg_lib.c:1010
#12 0x00007fca560a835d in drbg_status () at ../crypto/rand/drbg_lib.c:992
#13 0x0000563977eef53f in seed_rng () at ../../entropy.c:238
#14 0x0000563977e9813c in main (ac=2, av=0x563979893970) at ../../sshd.c:1696


So 28. Okt 11:12:40 CET 2018
#0  0x00007fb515b1803a in getentropy (buffer=0x56285633d440, length=length@entry=32) at ../sysdeps/unix/sysv/linux/getentropy.c:45
#1  0x00007fb5161e3603 in syscall_random (buflen=32, buf=<optimized out>) at ../crypto/rand/rand_unix.c:277
#2  rand_pool_acquire_entropy (pool=pool@entry=0x5628563394e0) at ../crypto/rand/rand_unix.c:469
#3  0x00007fb5161e2d8d in rand_drbg_get_entropy (drbg=0x562856339e80, pout=0x7ffd1c2bce60, entropy=<optimized out>, min_len=<optimized out>, max_len=<optimized out>, prediction_resistance=0) at ../crypt$
#4  0x00007fb5161e11b2 in RAND_DRBG_instantiate (drbg=drbg@entry=0x562856339e80, pers=pers@entry=0x7fb516289d20 <ossl_pers_string> "OpenSSL NIST SP 800-90A DRBG", perslen=perslen@entry=28) at ../crypto/$
#5  0x00007fb5161e21a8 in drbg_setup (parent=parent@entry=0x0) at ../crypto/rand/drbg_lib.c:870
#6  0x00007fb5161e222f in do_rand_drbg_init () at ../crypto/rand/drbg_lib.c:899
#7  do_rand_drbg_init_ossl_ () at ../crypto/rand/drbg_lib.c:884
#8  0x00007fb5150c9827 in __pthread_once_slow (once_control=0x7fb5163118f8 <rand_drbg_init>, init_routine=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at pthread_once.c:116
#9  0x00007fb5150c98e5 in __GI___pthread_once (once_control=once_control@entry=0x7fb5163118f8 <rand_drbg_init>, init_routine=init_routine@entry=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at pthread_once.$
#10 0x00007fb516221329 in CRYPTO_THREAD_run_once (once=once@entry=0x7fb5163118f8 <rand_drbg_init>, init=init@entry=0x7fb5161e21d0 <do_rand_drbg_init_ossl_>) at ../crypto/threads_pthread.c:113
#11 0x00007fb5161e2327 in RAND_DRBG_get0_master () at ../crypto/rand/drbg_lib.c:1010
#12 0x00007fb5161e235d in drbg_status () at ../crypto/rand/drbg_lib.c:992
#13 0x00005628556a253f in seed_rng () at ../../entropy.c:238
#14 0x000056285564b13c in main (ac=2, av=0x56285631b970) at ../../sshd.c:1696


[So Okt 28 11:10:30 2018] [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:02.0 on minor 0
[So Okt 28 11:12:43 2018] random: crng init done


So 28. Okt 11:12:44 CET 2018
#0  0x00007fa0a23bfa87 in __GI___select (nfds=7, readfds=0x5603ee0307a0, writefds=0x0, exceptfds=0x0, timeout=0x0) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00005603ec690f5f in server_accept_loop (sock_in=0x7ffd3ed7892c, sock_out=0x7ffd3ed78930, newsock=0x7ffd3ed78934, config_s=0x7ffd3ed78958) at ../../sshd.c:1186
#2  0x00005603ec68f09e in main (ac=<optimized out>, av=<optimized out>) at ../../sshd.c:2003



root@debian:~# journalctl -u ssh.service 
-- Logs begin at Sun 2018-10-28 11:10:31 CET, end at Sun 2018-10-28 11:17:01 CET. --
Okt 28 11:10:31 debian systemd[1]: Starting OpenBSD Secure Shell server...
Okt 28 11:12:01 debian systemd[1]: ssh.service: Start-pre operation timed out. Terminating.
Okt 28 11:12:01 debian systemd[1]: ssh.service: Failed with result 'timeout'.
Okt 28 11:12:01 debian systemd[1]: Failed to start OpenBSD Secure Shell server.
Okt 28 11:12:02 debian systemd[1]: ssh.service: Service RestartSec=100ms expired, scheduling restart.
Okt 28 11:12:02 debian systemd[1]: ssh.service: Scheduled restart job, restart counter is at 1.
Okt 28 11:12:02 debian systemd[1]: Stopped OpenBSD Secure Shell server.
Okt 28 11:12:02 debian systemd[1]: Starting OpenBSD Secure Shell server...
Okt 28 11:12:44 debian sshd[797]: Server listening on 0.0.0.0 port 22.
Okt 28 11:12:44 debian sshd[797]: Server listening on :: port 22.
Okt 28 11:12:44 debian systemd[1]: Started OpenBSD Secure Shell server.
Okt 28 11:12:50 debian sshd[809]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.2.2  user=benutzer
Okt 28 11:12:52 debian sshd[809]: Failed password for benutzer from 10.0.2.2 port 56136 ssh2
Okt 28 11:12:54 debian sshd[809]: Accepted password for benutzer from 10.0.2.2 port 56136 ssh2
Okt 28 11:12:54 debian sshd[809]: pam_unix(sshd:session): session opened for user benutzer by (uid=0)




Without debug symbols:
#0  0x00007f7ad544803a in getentropy (buffer=0x5651f1482440, length=<optimized out>) at ../sysdeps/unix/sysv/linux/getentropy.c:45
#1  0x00007f7ad5b13603 in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#2  0x00007f7ad5b12d8d in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#3  0x00007f7ad5b111b2 in RAND_DRBG_instantiate () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#4  0x00007f7ad5b121a8 in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#5  0x00007f7ad5b1222f in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#6  0x00007f7ad49f9827 in __pthread_once_slow (once_control=0x7f7ad5c418f8, init_routine=0x7f7ad5b121d0) at pthread_once.c:116
#7  0x00007f7ad5b51329 in CRYPTO_THREAD_run_once () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#8  0x00007f7ad5b12327 in RAND_DRBG_get0_master () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#9  0x00007f7ad5b1235d in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
#10 0x00005651f0e2453f in seed_rng () at ../../entropy.c:238
#11 0x00005651f0dcd13c in main (ac=2, av=0x5651f1460970) at ../../sshd.c:1696

Reply to:

Follow-Ups:
- Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
  - From: Colin Watson <cjwatson@debian.org>

References:
- Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
  - From: jim_p <pitsiorisj@gmail.com>

Prev by Date: Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
Next by Date: Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
Previous by thread: Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
Next by thread: Bug#912087: openssh-server: Slow startup after the upgrade to 7.9p1
Index(es):
- Date
- Thread