0

I just upgraded from Stretch to Buster, and the two services apache2 and ssh delayed in loading at the boot, in some cases I had to login or to start them manually to make them work. I didn't have any issues with mariadb or any other services run at boot. It's just terminal; no desktop environment installed. What's going on?

I tried also a clean install of Stretch without installing apache and ssh at the beginning, then I upgraded to Buster, installed apache and ssh and everything works as it is supposed to.

Here you can see a part of the log I exported from journactl from the 'broken machine':

Feb 13 21:55:56 vm-debian-buster systemd[1]: Starting OpenBSD Secure Shell server...
Feb 13 21:55:56 vm-debian-buster systemd[1]: Starting The Apache HTTP Server...
Feb 13 21:55:56 vm-debian-buster systemd[1]: Starting MariaDB 10.3.12 database server...
Feb 13 21:55:56 vm-debian-buster systemd[1]: Started Permit User Sessions.
Feb 13 21:55:56 vm-debian-buster kernel: battery: ACPI: Battery Slot [BAT0] (battery present)
Feb 13 21:55:56 vm-debian-buster systemd[1]: Started Getty on tty1.
Feb 13 21:55:56 vm-debian-buster systemd[1]: Reached target Login Prompts.
Feb 13 21:55:56 vm-debian-buster kernel: snd_intel8x0 0000:00:1f.4: intel8x0_measure_ac97_clock: measured 58452 usecs (2807 samples)
Feb 13 21:55:56 vm-debian-buster kernel: snd_intel8x0 0000:00:1f.4: clocking to 48000
Feb 13 21:55:56 vm-debian-buster systemd[1]: Reached target Sound Card.
Feb 13 21:55:57 vm-debian-buster mysqld[500]: 2019-02-13 21:55:57 0 [Note] /usr/sbin/mysqld (mysqld 10.3.12-MariaDB-2) starting as process 500 ...
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[533]: Upgrading MySQL tables if necessary.
Feb 13 21:55:57 vm-debian-buster systemd[1]: Started MariaDB 10.3.12 database server.
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[537]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[537]: Looking for 'mysql' as: /usr/bin/mysql
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[537]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[537]: This installation of MySQL is already upgraded to 10.3.12-MariaDB, use --force if you still need to run mysql_upgrade
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[546]: Checking for insecure root accounts.
Feb 13 21:55:57 vm-debian-buster /etc/mysql/debian-start[550]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Aria tables
Feb 13 21:56:01 vm-debian-buster login[416]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Feb 13 21:56:01 vm-debian-buster systemd[1]: Created slice User Slice of UID 0.
Feb 13 21:56:01 vm-debian-buster systemd[1]: Starting User Runtime Directory /run/user/0...
Feb 13 21:56:01 vm-debian-buster systemd-logind[409]: New session 1 of user root.
Feb 13 21:56:01 vm-debian-buster systemd[1]: Started User Runtime Directory /run/user/0.
Feb 13 21:56:01 vm-debian-buster systemd[1]: Starting User Manager for UID 0...
Feb 13 21:56:01 vm-debian-buster systemd[586]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Feb 13 21:56:01 vm-debian-buster systemd[586]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Feb 13 21:56:01 vm-debian-buster systemd[586]: Listening on GnuPG cryptographic agent and passphrase cache.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Reached target Paths.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Reached target Timers.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Listening on GnuPG network certificate management daemon.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Feb 13 21:56:01 vm-debian-buster systemd[586]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Feb 13 21:56:01 vm-debian-buster systemd[586]: Reached target Sockets.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Reached target Basic System.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Reached target Default.
Feb 13 21:56:01 vm-debian-buster systemd[586]: Startup finished in 31ms.
Feb 13 21:56:01 vm-debian-buster systemd[1]: Started User Manager for UID 0.
Feb 13 21:56:01 vm-debian-buster systemd[1]: Started Session 1 of user root.
Feb 13 21:56:01 vm-debian-buster login[596]: ROOT LOGIN  on '/dev/tty1'
Feb 13 21:56:03 vm-debian-buster dhclient[377]: DHCPDISCOVER on enp0s5 to 255.255.255.255 port 67 interval 7
Feb 13 21:56:03 vm-debian-buster sh[321]: DHCPDISCOVER on enp0s5 to 255.255.255.255 port 67 interval 7
Feb 13 21:56:05 vm-debian-buster dhclient[377]: DHCPOFFER of 192.168.1.39 from 192.168.1.1
Feb 13 21:56:05 vm-debian-buster sh[321]: DHCPOFFER of 192.168.1.39 from 192.168.1.1
Feb 13 21:56:05 vm-debian-buster sh[321]: DHCPREQUEST for 192.168.1.39 on enp0s5 to 255.255.255.255 port 67
Feb 13 21:56:05 vm-debian-buster dhclient[377]: DHCPREQUEST for 192.168.1.39 on enp0s5 to 255.255.255.255 port 67
Feb 13 21:56:06 vm-debian-buster dhclient[377]: DHCPACK of 192.168.1.39 from 192.168.1.1
Feb 13 21:56:06 vm-debian-buster sh[321]: DHCPACK of 192.168.1.39 from 192.168.1.1
Feb 13 21:56:06 vm-debian-buster dhclient[377]: bound to 192.168.1.39 -- renewal in 32966 seconds.
Feb 13 21:56:06 vm-debian-buster sh[321]: bound to 192.168.1.39 -- renewal in 32966 seconds.
Feb 13 21:56:06 vm-debian-buster sh[321]: enp0s5=enp0s5
Feb 13 21:56:27 vm-debian-buster systemd-timesyncd[297]: Synchronized to time server 91.220.110.117:123 (2.debian.pool.ntp.org).
Feb 13 21:57:26 vm-debian-buster systemd[1]: ssh.service: Start-pre operation timed out. Terminating.
Feb 13 21:57:26 vm-debian-buster systemd[1]: apache2.service: Start operation timed out. Terminating.
Feb 13 21:57:26 vm-debian-buster systemd[1]: ssh.service: Control process exited, code=killed, status=15/TERM
Feb 13 21:57:26 vm-debian-buster systemd[1]: ssh.service: Failed with result 'timeout'.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Failed to start OpenBSD Secure Shell server.
Feb 13 21:57:26 vm-debian-buster systemd[1]: apache2.service: Control process exited, code=killed, status=15/TERM
Feb 13 21:57:26 vm-debian-buster systemd[1]: apache2.service: Failed with result 'timeout'.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Failed to start The Apache HTTP Server.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Reached target Multi-User System.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Reached target Graphical Interface.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Starting Update UTMP about System Runlevel Changes...
Feb 13 21:57:26 vm-debian-buster systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Started Update UTMP about System Runlevel Changes.
Feb 13 21:57:26 vm-debian-buster systemd[1]: Startup finished in 3.315s (kernel) + 1min 30.755s (userspace) = 1min 34.071s.
Feb 13 21:57:27 vm-debian-buster systemd[1]: ssh.service: Service RestartSec=100ms expired, scheduling restart.
Feb 13 21:57:27 vm-debian-buster systemd[1]: ssh.service: Scheduled restart job, restart counter is at 1.
Feb 13 21:57:27 vm-debian-buster systemd[1]: Stopped OpenBSD Secure Shell server.
Feb 13 21:57:27 vm-debian-buster systemd[1]: Starting OpenBSD Secure Shell server...
Feb 13 21:57:59 vm-debian-buster kernel: random: crng init done
Feb 13 21:57:59 vm-debian-buster kernel: random: 7 urandom warning(s) missed due to ratelimiting
Feb 13 21:57:59 vm-debian-buster sshd[626]: Server listening on 0.0.0.0 port 22.
Feb 13 21:57:59 vm-debian-buster sshd[626]: Server listening on :: port 22.
Feb 13 21:57:59 vm-debian-buster systemd[1]: Started OpenBSD Secure Shell server.
Feb 13 22:07:54 vm-debian-buster sshd[641]: Accepted password for root from 192.168.1.37 port 53507 ssh2
Feb 13 22:07:54 vm-debian-buster sshd[641]: pam_unix(sshd:session): session opened for user root by (uid=0)
Feb 13 22:07:54 vm-debian-buster systemd-logind[409]: New session 3 of user root.
Feb 13 22:07:54 vm-debian-buster systemd[1]: Started Session 3 of user root.
Feb 13 22:09:01 vm-debian-buster CRON[652]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 13 22:09:01 vm-debian-buster CRON[653]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Feb 13 22:09:01 vm-debian-buster systemd[1]: Starting Clean php session files...
Feb 13 22:09:01 vm-debian-buster CRON[652]: pam_unix(cron:session): session closed for user root
Feb 13 22:09:02 vm-debian-buster systemd[1]: phpsessionclean.service: Succeeded.
Feb 13 22:09:02 vm-debian-buster systemd[1]: Started Clean php session files.
Feb 13 22:11:16 vm-debian-buster systemd[1]: Starting Cleanup of Temporary Directories...
Feb 13 22:11:16 vm-debian-buster systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Feb 13 22:11:16 vm-debian-buster systemd[1]: Started Cleanup of Temporary Directories.
Feb 13 22:17:01 vm-debian-buster CRON[734]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 13 22:17:01 vm-debian-buster CRON[735]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Feb 13 22:17:01 vm-debian-buster CRON[734]: pam_unix(cron:session): session closed for user root
G-Man Says 'Reinstate Monica'
  • 22,870
  • 2
    "delayed" is different from "in some cases I had to start them manually"; what exactly is happening with their startup sequence? – Jeff Schaller Feb 12 '19 at 14:06
  • sometimes they start with long delay, sometimes they don't start at all so I need to login, check the services status with the command service --status-all (to exclude network problem), if they are off i run the command systemctl start apache2 or ssh. before the upgrade everything was ok without delay or without the necessity to login –  Feb 12 '19 at 14:31
  • Have you looked at the log files ? – X Tian Feb 13 '19 at 15:29
  • I checked with journalctl many times and everything seemed fine. I checked again now and I got many errors. I'm going to update the question and attach the log file. –  Feb 13 '19 at 22:32
  • 1
    my guess: the newer kernel delays /dev/(u)random initial read operations: Feb 13 21:57:59 vm-debian-buster kernel: random: crng init done and ssh starts right after. – A.B Feb 13 '19 at 23:05
  • @RuiFRibeiro I'd rather see it as a duplicate to: When I log in, it hangs until crng init done – A.B Feb 13 '19 at 23:15
  • @A.B I'll clone the machine and try it out –  Feb 13 '19 at 23:19
  • 1
    haveged solved the problem on the 'broken machine' with kernel 4.19.0-1-amd64, but on the machine with 'clean install' the kernel has been updated to 4.19.0-2-amd64. kernel problem? apt update can solve the problem on the 'broken machine' too. –  Feb 14 '19 at 00:25

1 Answers1

0

Problem solved. I read the post linked by @AB in the comments. When I log in, it hangs until crng init done

and I found out I had the same problem. I checked the kernel version between the 'broken machine' and 'clean install machine' I noticed they were different. I rant the command apt update and there were a lot upgradable packages included kernel, apache and ssh. After the update everything came back to normality.