Subject: [alpine-user] very long boot time with Alpine 3.5.0 fresh install

From: Olivier Goudron <[email-masked]>
Date: Sun, 8 Jan 2017 17:47:24 +0100

Hello,

I have just installed a fresh Alpine Linux 3.5.0 on Intel NUC5CP with 
Intel SSD disk and this new installation take up to 7 minutes to boot.
The system start normally and then stale on chrony / cron.d for most of 
the time and then finish in few seconds.

This is the log (note that time jump to 1 hour in past after the first 
line).
My time zone is Europe/Paris.

Thanks in advance, Olivier Goudron.

Jan  8 17:20:17 alpine-nuc5cp syslog.info syslogd started: BusyBox v1.25.1
Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.170352] random: 
dd: uninitialized urandom read (512 bytes read, 37 bits of entropy 
available)
Jan  8 16:20:17 alpine-nuc5cp daemon.info init: starting pid 2306, tty 
'': '/sbin/openrc default'
Jan  8 16:20:17 alpine-nuc5cp daemon.info chronyd[2355]: chronyd version 
2.4 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SECHASH 
+ASYNCDNS +IPV6 -DEBUG)
Jan  8 16:20:17 alpine-nuc5cp kern.info kernel: [   11.346375] NET: 
Registered protocol family 10
Jan  8 16:20:17 alpine-nuc5cp daemon.warn chronyd[2355]: commandkey 
directive is no longer supported
Jan  8 16:20:17 alpine-nuc5cp daemon.warn chronyd[2355]: Could not open 
keyfile /etc/chrony/chrony.keys
Jan  8 16:20:17 alpine-nuc5cp daemon.info chronyd[2355]: Frequency 
-2.161 +/- 24.874 ppm read from /var/lib/chrony/chrony.drift
Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.348650] random: 
chronyd: uninitialized urandom read (3 bytes read, 37 bits of entropy 
available)
Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.348666] random: 
chronyd: uninitialized urandom read (1024 bytes read, 37 bits of entropy 
available)
Jan  8 16:20:22 alpine-nuc5cp daemon.info chronyd[2355]: System's 
initial offset : 0.303057 seconds slow of true (slew)
Jan  8 16:20:24 alpine-nuc5cp cron.info crond[2382]: crond (busybox 
1.25.1) started, log level 8
Jan  8 16:22:34 alpine-nuc5cp daemon.info chronyd[2355]: Selected source 
213.251.53.11
Jan  8 16:27:39 alpine-nuc5cp kern.notice kernel: [  452.732821] random: 
nonblocking pool is initialized
Jan  8 16:27:39 alpine-nuc5cp auth.info sshd[2410]: Server listening on 
0.0.0.0 port 22.
Jan  8 16:27:39 alpine-nuc5cp auth.info sshd[2410]: Server listening on 
:: port 22.
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2414, tty 
'/dev/tty1': '/sbin/getty 38400 tty1'
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2415, tty 
'/dev/tty2': '/sbin/getty 38400 tty2'
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2418, tty 
'/dev/tty3': '/sbin/getty 38400 tty3'
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2421, tty 
'/dev/tty4': '/sbin/getty 38400 tty4'
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2424, tty 
'/dev/tty5': '/sbin/getty 38400 tty5'
Jan  8 16:27:39 alpine-nuc5cp daemon.info init: starting pid 2427, tty 
'/dev/tty6': '/sbin/getty 38400 tty6'
Jan  8 16:27:54 alpine-nuc5cp auth.info sshd[2430]: Accepted password 
for root from 192.168.0.60 port 54036 ssh2
Jan  8 16:30:00 alpine-nuc5cp cron.info crond[2382]: USER root pid 2437 
cmd run-parts /etc/periodic/15min

---
Unsubscribe:  [email-masked]
Help:         [email-masked]
---

---

From: Johannes Matheis <[email-masked]>
Date: Sun, 08 Jan 2017 20:26:38 +0000

Hello,

On 2017-01-08 16:47, Olivier Goudron wrote:
> The system start normally and then stale on chrony / cron.d for most
> of the time and then finish in few seconds.
> 
> Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.170352]
> random: dd: uninitialized urandom read (512 bytes read, 37 bits of
> entropy available)
> Jan  8 16:20:17 alpine-nuc5cp daemon.info chronyd[2355]: chronyd
> version 2.4 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER
> -SECHASH +ASYNCDNS +IPV6 -DEBUG)
> Jan  8 16:20:17 alpine-nuc5cp daemon.warn chronyd[2355]: Could not
> open keyfile /etc/chrony/chrony.keys
> Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.348650]
> random: chronyd: uninitialized urandom read (3 bytes read, 37 bits of
> entropy available)
> Jan  8 16:20:17 alpine-nuc5cp kern.notice kernel: [   11.348666]
> random: chronyd: uninitialized urandom read (1024 bytes read, 37 bits
> of entropy available)
> Jan  8 16:22:34 alpine-nuc5cp daemon.info chronyd[2355]: Selected
> source 213.251.53.11
> Jan  8 16:27:39 alpine-nuc5cp kern.notice kernel: [  452.732821]
> random: nonblocking pool is initialized
> Jan  8 16:27:39 alpine-nuc5cp auth.info sshd[2410]: Server listening
> on 0.0.0.0 port 22.
> Jan  8 16:27:39 alpine-nuc5cp auth.info sshd[2410]: Server listening
> on :: port 22.
> Jan  8 16:30:00 alpine-nuc5cp cron.info crond[2382]: USER root pid
> 2437 cmd run-parts /etc/periodic/15min

I've noticed similar issues on some of my machines.
Installing haveged works as a workaround for me.

Regards,
jomat

---