Subject: bug#34580: closed (Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0)

From: [email-masked] (GNU bug Tracking System)
Date: Tue, 14 May 2019 18:22:03 +0000

Your bug report

#30993: Service ssh-daemon could not be started

which was filed against the guix package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
30993: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=30993
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0
From: Leo Famulari <[email-masked]>
To: Ludovic Courtès <[email-masked]>
Cc: [email-masked]
Date: Tue, 14 May 2019 14:21:06 -0400
List-Id: <debbugs-submit.debbugs.gnu.org>

On Tue, May 14, 2019 at 03:33:59PM +0200, Ludovic Courtès wrote:
> There are reasons to believe that this issue is fixed by the Shepherd 0.6.1:
> 
>   https://issues.guix.info/issue/35550
> 
> Could you check somehow if the bug shows up again?

The bug disappeared for me a couple of reboots after reinstalling the
Guix System on my affected machine. That reinstallation provided
Shepherd 0.5, although 0.5 was also tested unsuccessfully before
reinstalling.

The issue does not manifest for me with Shepherd 0.6, 0.6.1 or Guix 1.0.

So... I think the bug was probably some kind of race condition or TOCTOU
problem that went away with a less fragmented or full filesystem (I was
really pushing the limits in that regard).

It's great that Shepherd 0.6.1 improved the PID file handling, assuming
that was the culprit.

I am closing this bug, but we can reopen it later if necessary.

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