Subject: Service ssh-daemon could not be started
From: Andreas Enge <[email-masked]>
To: [email-masked]
Date: Tue, 19 Feb 2019 22:21:26 +0100
List-Id: <debbugs-submit.debbugs.gnu.org>

Hello,

twice in a row at work (on harbourfront) and now twice in a row at home
(on dover) I am in a situation where sshd does not start on Guix machines.
Networking is available (the machines can be pinged), and I have to log
in via a console and execute "herd start ssh-daemon" by hand.

Here is the relevant portion of /var/log/messages for dover:
Feb 19 22:02:23 localhost vmunix: [  108.990196] ipmi_si e0010000.kcs: There appears to be no BMC at this location
Feb 19 22:02:23 localhost vmunix: [  109.021176] shepherd[1]: Service udev has been started.
Feb 19 22:02:23 localhost vmunix: [  109.026910] Adding 467648k swap on /dev/sda4.  Priority:-2 extents:1 across:467648k FS
Feb 19 22:02:23 localhost vmunix: [  109.037138] shepherd[1]: Service swap-/dev/sda4 has been started.
Feb 19 22:02:23 localhost vmunix: [  109.045502] shepherd[1]: Service user-file-systems has been started.
Feb 19 22:02:23 localhost vmunix: [  109.229105] shepherd[1]: Service file-system-/boot/efi has been started.
Feb 19 22:02:23 localhost vmunix: [  109.238721] shepherd[1]: Service file-system-/dev/pts has been started.
Feb 19 22:02:23 localhost vmunix: [  109.248214] shepherd[1]: Service file-system-/dev/shm has been started.
Feb 19 22:02:24 localhost vmunix: [  109.257629] shepherd[1]: Service file-system-/gnu/store has been started.
Feb 19 22:02:06 localhost ntpd[354]: Command line: /gnu/store/rgj9dvakw960p0p44cq6kfwk9a4pzcmw-ntp-4.2.8p12/bin/ntpd -n -c /gnu/store/1l1yf5dss8r9pqxklaax32s6bkah09c6-ntpd.conf -u ntpd
Feb 19 22:02:24 localhost vmunix: [  109.266692] shepherd[1]: Service file-systems has been started.
Feb 19 22:02:24 localhost vmunix: [  109.284615] shepherd[1]: Service urandom-seed has been started.
Feb 19 22:02:24 localhost vmunix: [  109.292825] shepherd[1]: Service user-processes has been started.
Feb 19 22:02:24 localhost vmunix: [  109.301269] shepherd[1]: Service host-name has been started.
Feb 19 22:02:24 localhost vmunix: [  109.318409] shepherd[1]: Service user-homes could not be started.
Feb 19 22:02:24 localhost vmunix: [  110.331371] shepherd[1]: Service nscd has been started.
Feb 19 22:02:24 localhost vmunix: [  110.343051] shepherd[1]: Service guix-daemon has been started.
Feb 19 22:02:24 localhost vmunix: [  116.296395] sky2 0000:02:00.0 enp2s0: enabling interface
Feb 19 22:02:24 localhost vmunix: [  116.301800] IPv6: ADDRCONF(NETDEV_UP): enp2s0: link is not ready
Feb 19 22:02:24 localhost vmunix: [  118.611449] sky2 0000:02:00.0 enp2s0: Link is up at 1000 Mbps, full duplex, flow control rx
Feb 19 22:02:25 localhost vmunix: [  118.619821] IPv6: ADDRCONF(NETDEV_CHANGE): enp2s0: link becomes ready
Feb 19 22:02:25 localhost shepherd[1]: Service mcron has been started. 
Feb 19 22:02:08 localhost dhclient: DHCPACK of 192.168.1.113 from 192.168.1.1
Feb 19 22:02:10 localhost sshd[359]: Server listening on 0.0.0.0 port 22.
Feb 19 22:02:12 localhost nscd: 314 monitored file `/etc/resolv.conf` was moved into place, adding watch
Feb 19 22:02:12 localhost dhclient: bound to 192.168.1.113 -- renewal in 19054 seconds.
Feb 19 22:02:25 localhost shepherd[1]: Service ssh-daemon could not be started. 
Feb 19 22:02:17 localhost ntpd[354]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Feb 19 22:02:20 localhost ntpd[354]: Listen normally on 3 enp2s0 192.168.1.113:123
Feb 19 22:02:20 localhost ntpd[354]: Listen normally on 4 lo [::1]:123
Feb 19 22:02:21 localhost ntpd[354]: Listen normally on 5 enp2s0 [fda3:5c49:ae85:0:e2ff:f7ff:fe00:20b3]:123
Feb 19 22:02:23 localhost ntpd[354]: Listen normally on 6 enp2s0 [2001:910:103f:0:e2ff:f7ff:fe00:20b3]:123
Feb 19 22:02:24 localhost ntpd[354]: Listen normally on 7 enp2s0 [fe80::e2ff:f7ff:fe00:20b3%2]:123
Feb 19 22:02:25 localhost ntpd[354]: Listening on routing socket on fd #24 for interface updates
Feb 19 22:02:25 localhost ntpd[354]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 19 22:02:25 localhost ntpd[354]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Feb 19 22:03:26 localhost shepherd[1]: Respawning term-ttyAMA0. 
Feb 19 22:03:26 localhost shepherd[1]: Service term-ttyAMA0 has been started. 
Feb 19 22:03:48 localhost sshd[380]: Server listening on 0.0.0.0 port 22.
Feb 19 22:03:48 localhost sshd[380]: Server listening on :: port 22.
Feb 19 22:03:48 localhost shepherd[1]: Service ssh-daemon has been started. 

Besides the notice that "Service ssh-daemon could not be started" I do not see
much information. The second time corresponds to the starting by hand.
Maybe it is a problem that " sshd[359]: Server listening on 0.0.0.0 port 22."
at 22:02:10 before the IP address arrives via dhcp 2 seconds later?

Andreas