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
  • 1
    "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 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 – user329236 Feb 12 at 14:31
  • Have you looked at the log files ? – X Tian Feb 13 at 15:29
  • 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 at 23:05
  • 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. – user329236 Feb 14 at 0:25
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.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy