GNU bug report logs - #34580
'ssh-daemon' fails to start

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 34580 in the body.
You can then email your comments to 34580 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Andreas Enge <andreas <at> enge.fr>
To: bug-guix <at> gnu.org
Subject: Service ssh-daemon could not be started
Date: Tue, 19 Feb 2019 22:21:26 +0100

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

Message #8 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Leo Famulari <leo <at> famulari.name>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Wed, 20 Feb 2019 17:21:58 -0500

[Message part 1 (text/plain, inline)]

On Tue, Feb 19, 2019 at 10:21:26PM +0100, Andreas Enge wrote:
> 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.

I wonder if this is another instance of <https://bugs.gnu.org/30993>?

[signature.asc (application/pgp-signature, inline)]

Message #11 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Andreas Enge <andreas <at> enge.fr>
To: Leo Famulari <leo <at> famulari.name>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Wed, 20 Feb 2019 23:48:02 +0100

On Wed, Feb 20, 2019 at 05:21:58PM -0500, Leo Famulari wrote:
> I wonder if this is another instance of <https://bugs.gnu.org/30993>?

I suppose so. I would be happy to provide further information, but there is
not much to see in the log files.

Andreas

Message #14 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Leo Famulari <leo <at> famulari.name>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Wed, 20 Feb 2019 17:51:54 -0500

[Message part 1 (text/plain, inline)]

On Wed, Feb 20, 2019 at 11:48:02PM +0100, Andreas Enge wrote:
> I suppose so. I would be happy to provide further information, but there is
> not much to see in the log files.

Yes, there is not much to go on.

For now I am still using Shepherd 0.3 on that machine :/

I plan to reinstall from scratch soon.

[signature.asc (application/pgp-signature, inline)]

Message #17 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Andreas Enge <andreas <at> enge.fr>
To: Leo Famulari <leo <at> famulari.name>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Thu, 21 Feb 2019 00:08:07 +0100

On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:
> On Wed, Feb 20, 2019 at 11:48:02PM +0100, Andreas Enge wrote:
> > I suppose so. I would be happy to provide further information, but there is
> > not much to see in the log files.

I grepped for "ssh" in /var/log/messages.

The failure on boot:
Feb 19 22:02:20 localhost vmunix: [    6.712592] random: ssh-keygen: uninitialized urandom read (32 bytes read)
Feb 19 22:02:10 localhost sshd[359]: Server listening on 0.0.0.0 port 22.
Feb 19 22:02:25 localhost shepherd[1]: Service ssh-daemon could not be started.

And then starting by hand:
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.

It looks as if ssh-keygen takes too long; this is called from
openssh-activation in services/ssh.scm, with a comment
"Generate missing host keys". Are these regenerated at each boot?
If yes, is there a race condition, one action not waiting for the
previous one to finish?

Andreas

Message #20 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Leo Famulari <leo <at> famulari.name>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Wed, 20 Feb 2019 18:56:34 -0500

[Message part 1 (text/plain, inline)]

On Thu, Feb 21, 2019 at 12:08:07AM +0100, Andreas Enge wrote:
> It looks as if ssh-keygen takes too long; this is called from
> openssh-activation in services/ssh.scm, with a comment
> "Generate missing host keys". Are these regenerated at each boot?
> If yes, is there a race condition, one action not waiting for the
> previous one to finish?

The host keys should not be regenerated on each boot.  Wouldn't we
notice if they were, since our SSH clients would complain about them
having changed?

[signature.asc (application/pgp-signature, inline)]

Message #23 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Chris Marusich <cmmarusich <at> gmail.com>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Thu, 21 Feb 2019 22:52:04 -0800

[Message part 1 (text/plain, inline)]

Hi Andreas,

I have nothing to contribute, unfortunately, except to confirm that I
continue to see this problem.  I have seen it for months.  At this
point, I actually can't remember a time when SSH didn't fail to start in
this mysterious manner.

I'll see if I can reproduce the issue in a VM...  No promises, though!

-- 
Chris

[signature.asc (application/pgp-signature, inline)]

Message #30 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Leo Famulari <leo <at> famulari.name>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Thu, 14 Mar 2019 18:11:21 -0400

[Message part 1 (text/plain, inline)]

On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:
> For now I am still using Shepherd 0.3 on that machine :/

Since a few days ago this workaround no longer works :(

> I plan to reinstall from scratch soon.

Reinstallation did not help.

[signature.asc (application/pgp-signature, inline)]

Message #33 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Leo Famulari <leo <at> famulari.name>
To: Andreas Enge <andreas <at> enge.fr>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Fri, 15 Mar 2019 12:35:24 -0400

[Message part 1 (text/plain, inline)]

On Thu, Mar 14, 2019 at 06:11:21PM -0400, Leo Famulari wrote:
> Reinstallation did not help.

Hm, it's working now! It did not work after installing Guix System
0.16.0 but after I updated to the latest (pull & reconfigure) it started
to work. Quite strange...

[signature.asc (application/pgp-signature, inline)]

Message #40 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: 34580 <at> debbugs.gnu.org
Subject: Service ssh-daemon could not be started
Date: Fri, 20 Sep 2019 15:00:40 -0500

[Message part 1 (text/plain, inline)]

Adding my nickel here, I observed the exact same behavior yesterday. I have several Guix System instances, this is currently the only one that has exhibited the problem of ssh failing to start and logging no messages about it.

Networking:

 (static-networking-service
 "enp1s0" "192.168.1.253"
 #:gateway "192.168.1.100"
 #:name-servers '("192.168.1.123" "192.168.1.252"))

The most useful thing I could find in the logs:

Sep 19 15:30:46 localhost sshd[261]: Server listening on 0.0.0.0 port 22.
Sep 19 15:31:19 localhost shepherd[1]: Service ssh-daemon could not be started.
Sep 19 15:39:58 localhost sshd[585]: Server listening on 0.0.0.0 port 22.
Sep 19 15:39:58 localhost sshd[585]: Server listening on :: port 22.
Sep 19 15:39:59 localhost shepherd[1]: Service ssh-daemon has been started.

The 15:30/15:31 lines are the boot messages, the 15:39 messages are my manual call to 'herd start ssh-daemon'.

--
Brant Gardner

[Message part 2 (text/html, inline)]

Message #43 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Brant Gardner" <mail <at> lnklnx.com>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Tue, 24 Sep 2019 10:08:22 +0200

Hi Brant,

"Brant Gardner" <mail <at> lnklnx.com> skribis:

> The most useful thing I could find in the logs:
>
> Sep 19 15:30:46 localhost sshd[261]: Server listening on 0.0.0.0 port 22.
> Sep 19 15:31:19 localhost shepherd[1]: Service ssh-daemon could not be started.
> Sep 19 15:39:58 localhost sshd[585]: Server listening on 0.0.0.0 port 22.
> Sep 19 15:39:58 localhost sshd[585]: Server listening on :: port 22.
> Sep 19 15:39:59 localhost shepherd[1]: Service ssh-daemon has been started.

As I witnessed before, it looks as though ‘sshd’ initially hanged while
trying to bind on the IPv6 address.

So I wonder if we’re just sometimes starting sshd a bit too early
wrt. to some IPv6 networking initialization, or something.  It’d be
great to have the strace output when that happens.

Thanks,
Ludo’.

Message #46 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Tue, 24 Sep 2019 07:20:10 -0500

I'll cheerfully do the experiment, but I don't know how - can you direct me for how to add strace where you need it to a booting system?

--
Brant Gardner

On Tue, Sep 24, 2019, at 03:08, Ludovic Courtès wrote:
> Hi Brant,
> 
> "Brant Gardner" <mail <at> lnklnx.com> skribis:
> 
> > The most useful thing I could find in the logs:
> >
> > Sep 19 15:30:46 localhost sshd[261]: Server listening on 0.0.0.0 port 22.
> > Sep 19 15:31:19 localhost shepherd[1]: Service ssh-daemon could not be started.
> > Sep 19 15:39:58 localhost sshd[585]: Server listening on 0.0.0.0 port 22.
> > Sep 19 15:39:58 localhost sshd[585]: Server listening on :: port 22.
> > Sep 19 15:39:59 localhost shepherd[1]: Service ssh-daemon has been started.
> 
> As I witnessed before, it looks as though ‘sshd’ initially hanged while
> trying to bind on the IPv6 address.
> 
> So I wonder if we’re just sometimes starting sshd a bit too early
> wrt. to some IPv6 networking initialization, or something.  It’d be
> great to have the strace output when that happens.
> 
> Thanks,
> Ludo’.
>

Message #55 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Brant Gardner" <mail <at> lnklnx.com>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Thu, 26 Sep 2019 22:48:58 +0200

[Message part 1 (text/plain, inline)]

Hi Brand,

"Brant Gardner" <mail <at> lnklnx.com> skribis:

> I'll cheerfully do the experiment, but I don't know how - can you direct me for how to add strace where you need it to a booting system?

You could try something like the patch below.  When ‘ssh-daemon’ fails
to start, you’ll have to make sure to grab /tmp/ssh.log.

I’ve just experienced it on a headless machine so I sympathize all the
more now…

HTH!

Ludo’.

[Message part 2 (text/x-patch, inline)]

--- a/gnu/services/ssh.scm
+++ b/gnu/services/ssh.scm
@@ -23,6 +23,7 @@
 (define-module (gnu services ssh)
   #:use-module (gnu packages ssh)
   #:use-module (gnu packages admin)
+  #:use-module (gnu packages linux)
   #:use-module (gnu services)
   #:use-module (gnu services shepherd)
   #:use-module (gnu system pam)
@@ -491,7 +492,8 @@ of user-name/file-like tuples."
     (openssh-configuration-pid-file config))
 
   (define openssh-command
-    #~(list (string-append #$(openssh-configuration-openssh config) "/sbin/sshd")
+    #~(list #$(file-append strace "/bin/strace") "-f" "-s" "300" "-Tt" "-o" "/tmp/ssh.log"
+            (string-append #$(openssh-configuration-openssh config) "/sbin/sshd")
             "-D" "-f" #$(openssh-config-file config)))
 
   (list (shepherd-service

Message #58 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Fri, 27 Sep 2019 09:57:13 -0500

Hi Ludo;

Going to show my ignorance here - I've contributed some packages by making things in a 'guix environment' and then extracting patches, but what you need me to do is activate a configuration change in a 'live' guix install (and on a service rather than a package, also new-ish to me) so it sticks over a reboot.  This is not something I've done before and I'm not finding docs for it, can you direct me?

Thank you,

--
Brant Gardner

On Thu, Sep 26, 2019, at 15:48, Ludovic Courtès wrote:
> Hi Brand,
> 
> "Brant Gardner" <mail <at> lnklnx.com> skribis:
> 
> > I'll cheerfully do the experiment, but I don't know how - can you direct me for how to add strace where you need it to a booting system?
> 
> You could try something like the patch below.  When ‘ssh-daemon’ fails
> to start, you’ll have to make sure to grab /tmp/ssh.log.
> 
> I’ve just experienced it on a headless machine so I sympathize all the
> more now…
> 
> HTH!
> 
> Ludo’.
> 
>

Message #61 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Brant Gardner" <mail <at> lnklnx.com>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 11:45:57 +0200

Hi Brant,

"Brant Gardner" <mail <at> lnklnx.com> skribis:

> Going to show my ignorance here - I've contributed some packages by
> making things in a 'guix environment' and then extracting patches, but
> what you need me to do is activate a configuration change in a 'live'
> guix install (and on a service rather than a package, also new-ish to
> me) so it sticks over a reboot.  This is not something I've done
> before and I'm not finding docs for it, can you direct me?

Sure, sorry for not being clearer.

So you would apply the patch I sent over a fresh checkout of Guix, like
so:

  git clone https://git.savannah.gnu.org/git/guix.git
  cd guix
  patch -p1 < the-patch

Then you need to build Guix from that checkout:

  https://guix.gnu.org/manual/en/html_node/Building-from-Git.html

Finally, you can reconfigure your system from that checkout with:

  sudo -E ./pre-inst-env guix system reconfigure …

Let me know how it goes!

Thanks,
Ludo’.

Message #64 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 07:38:49 -0500

Hi Ludo;

Okay, I did those steps exactly:

  - clone
  - patch -p1 < your-patch
  - ./bootstrap
  - ./configure --localstatedir=/var
  - make check
  - sudo -E ./pre-inst-env guix system reconfigure /path/to/myconfig.scm
  - reboot

I had no issues or errors at any step and on reboot ssh-daemon tried & failed to start so all went according to plan, but /tmp does *not* have a ssh log file in it.

Not sure where this went sideways, any advice?

Thank you,

--
Brant Gardner

On Sat, Sep 28, 2019, at 04:45, Ludovic Courtès wrote:
> Hi Brant,
> 
> "Brant Gardner" <mail <at> lnklnx.com> skribis:
> 
> > Going to show my ignorance here - I've contributed some packages by
> > making things in a 'guix environment' and then extracting patches, but
> > what you need me to do is activate a configuration change in a 'live'
> > guix install (and on a service rather than a package, also new-ish to
> > me) so it sticks over a reboot.  This is not something I've done
> > before and I'm not finding docs for it, can you direct me?
> 
> Sure, sorry for not being clearer.
> 
> So you would apply the patch I sent over a fresh checkout of Guix, like
> so:
> 
>   git clone https://git.savannah.gnu.org/git/guix.git
>   cd guix
>   patch -p1 < the-patch
> 
> Then you need to build Guix from that checkout:
> 
>   https://guix.gnu.org/manual/en/html_node/Building-from-Git.html
> 
> Finally, you can reconfigure your system from that checkout with:
> 
>   sudo -E ./pre-inst-env guix system reconfigure …
> 
> Let me know how it goes!
> 
> Thanks,
> Ludo’.
>

Message #67 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "pelzflorian (Florian Pelz)" <pelzflorian <at> pelzflorian.de>
To: Brant Gardner <mail <at> lnklnx.com>
Cc: Ludovic Courtès <ludo <at> gnu.org>, 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 15:54:57 +0200

On Sat, Sep 28, 2019 at 07:38:49AM -0500, Brant Gardner wrote:
> Hi Ludo;
> 
> Okay, I did those steps exactly:
> 
>   - clone
>   - patch -p1 < your-patch
>   - ./bootstrap
>   - ./configure --localstatedir=/var
>   - make check
>   - sudo -E ./pre-inst-env guix system reconfigure /path/to/myconfig.scm
>   - reboot
> 
> I had no issues or errors at any step and on reboot ssh-daemon tried & failed to start so all went according to plan, but /tmp does *not* have a ssh log file in it.
> 
> Not sure where this went sideways, any advice?
> 
> Thank you,
> 

Perhaps /tmp is the wrong directory to store such an early log?  I
have a Guix virtual machine where ssh-daemon, httpd, php-fpm and
term-auto cannot be started on boot.  /var/log/debug contains:

Sep 28 15:47:00 localhost vmunix: [    0.898260] Write protecting the kernel read-only data: 18432k
Sep 28 15:47:00 localhost vmunix: [    0.900802] Freeing unused kernel image memory: 2036K
Sep 28 15:47:00 localhost vmunix: [    0.902187] Freeing unused kernel image memory: 72K
Sep 28 15:47:00 localhost vmunix: [    0.903142] Run /init as init process
Sep 28 15:47:00 localhost vmunix: [    1.168976] usbcore: registered new interface driver usb-storage
Sep 28 15:47:00 localhost vmunix: [    1.184777] usbcore: registered new interface driver uas
Sep 28 15:47:00 localhost vmunix: [    1.202265] hidraw: raw HID events driver (C) Jiri Kosina
Sep 28 15:47:01 localhost shepherd[1]: Service ssh-daemon could not be started. 
Sep 28 15:47:01 localhost vmunix: [    1.204318] usbcore: registered new interface driver usbhid
Sep 28 15:47:01 localhost vmunix: [    1.204320] usbhid: USB HID core driver
Sep 28 15:47:01 localhost vmunix: [    1.270227] isci: Intel(R) C600 SAS Controller Driver - version 1.2.0
Sep 28 15:47:01 localhost vmunix: [    1.445126] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
Sep 28 15:47:01 localhost vmunix: [    2.387966] random: fast init done
Sep 28 15:47:01 localhost vmunix: [    3.554499] random: ssh-keygen: uninitialized urandom read (32 bytes read)
Sep 28 15:47:01 localhost vmunix: [    4.219031] random: shepherd: uninitialized urandom read (4096 bytes read)
Sep 28 15:47:02 localhost vmunix: [    4.615089] random: crng init done
Sep 28 15:47:02 localhost vmunix: [    5.199788] shepherd[1]: Service root has been started.
Sep 28 15:47:02 localhost vmunix: [    6.559652] shepherd[1]: starting services...
Sep 28 15:47:02 localhost vmunix: [    6.563503] shepherd[1]: Service root-file-system has been started.
Sep 28 15:47:02 localhost vmunix: [    6.567531] shepherd[1]: Service user-file-systems has been started.
Sep 28 15:47:02 localhost vmunix: [    6.656184] shepherd[1]: waiting for udevd...

I do not know if this is a problem with the order in which services,
crng, mounting start.

Regards,
Florian

Message #70 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Brant Gardner" <mail <at> lnklnx.com>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 16:11:20 +0200

"Brant Gardner" <mail <at> lnklnx.com> skribis:

> Okay, I did those steps exactly:
>
>   - clone
>   - patch -p1 < your-patch
>   - ./bootstrap
>   - ./configure --localstatedir=/var
>   - make check
>   - sudo -E ./pre-inst-env guix system reconfigure /path/to/myconfig.scm
>   - reboot
>
> I had no issues or errors at any step and on reboot ssh-daemon tried & failed to start so all went according to plan, but /tmp does *not* have a ssh log file in it.
>
> Not sure where this went sideways, any advice?

Does the PID that ‘herd status ssh-daemon’ reports (under “Running
value”) correspond to ‘strace’?

BTW, it may be that the problem will show up less frequently because
sshd starts more slowly when running under ‘strace’.  That’s the hard
part with timing-related bugs…

Thanks for testing!

Ludo’.

Message #73 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "pelzflorian \(Florian Pelz\)" <pelzflorian <at> pelzflorian.de>
Cc: Brant Gardner <mail <at> lnklnx.com>, 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 19:44:16 +0200

Hi,

"pelzflorian (Florian Pelz)" <pelzflorian <at> pelzflorian.de> skribis:

> Perhaps /tmp is the wrong directory to store such an early log?  

No, that’s fine.  /tmp is accessible at that point.

> I have a Guix virtual machine where ssh-daemon, httpd, php-fpm and
> term-auto cannot be started on boot.

‘term-auto’ is actually something that doesn’t start; it’s confusing, we
should present it differently, maybe as a one-shot service.

Thanks,
Ludo’.

Message #76 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Brant Gardner <mail <at> lnklnx.com>,
 Ludovic Courtès <ludo <at> gnu.org>, "pelzflorian
 \(Florian Pelz\)" <pelzflorian <at> pelzflorian.de>, 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 20:23:29 +0200

[Message part 1 (text/plain, inline)]

Hi everyone,

On Sat, 28 Sep 2019 19:44:16 +0200
Ludovic Courtès <ludo <at> gnu.org> wrote:

> ‘term-auto’ is actually something that doesn’t start; it’s confusing, we
> should present it differently, maybe as a one-shot service.

term-auto automatically provides a shell on the console if that is a serial
console.  Maybe it's not represented ideally, but bootstrapping (and
sometimes using) ARM boards without it is a nightmare.

What it does is check /proc/cmdline for a "console" argument and if it's
a serial console, start a serial getty for login.

If the "console" argument is not a serial console, term-auto will fail
(f.e. in order to prevent shepherd from auto-restarting it).

If you then log out again, it will restart the getty, so it's not one-shot.

Maybe we could somehow automatically load another service into shepherd
(it can be scripted at runtime--including what services are provided, right?).

So we could have a one-shot service "term-auto" which checks /proc/cmdline
(which can't change until the next reboot anyway), and if there's a serial
console, register a new (normal) service "term-ttyACM0" or whatever.  Otherwise
it would just not register the "term-ttyACM0" service.  In both cases, its job
would be done afterwards.  How then do we make shepherd actually start the new
service?

To anyone trying this (including me if I do try it), please don't break it
(when changing it) while the sshd problem is still broken--that would REALLY
lock you out of your machines.

[Message part 2 (application/pgp-signature, inline)]

Message #79 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Brant Gardner <mail <at> lnklnx.com>,
 Ludovic Courtès <ludo <at> gnu.org>, "pelzflorian
 \(Florian Pelz\)" <pelzflorian <at> pelzflorian.de>, 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 20:31:31 +0200

[Message part 1 (text/plain, inline)]

On second thought, maybe it would be easiest to make term-auto "succeed" when
it can't find that serial console.  Shepherd would think everything is a-ok and
nobody would tell it any better :P

[Message part 2 (application/pgp-signature, inline)]

Message #82 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Brant Gardner <mail <at> lnklnx.com>,
 "pelzflorian \(Florian Pelz\)" <pelzflorian <at> pelzflorian.de>,
 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 21:47:10 +0200

Hi Danny!

Danny Milosavljevic <dannym <at> scratchpost.org> skribis:

> So we could have a one-shot service "term-auto" which checks /proc/cmdline
> (which can't change until the next reboot anyway), and if there's a serial
> console, register a new (normal) service "term-ttyACM0" or whatever.  Otherwise
> it would just not register the "term-ttyACM0" service.  In both cases, its job
> would be done afterwards.  How then do we make shepherd actually start the new
> service?

The ‘start’ method should of ‘term-auto’ should be able to register a
new service and to call its ‘start’ method.  I haven’t tried but it
should work.

That would allow us to make ‘term-auto’ one-shot, which would be nicer!

Thanks,
Ludo’.

Message #85 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: Brant Gardner <mail <at> lnklnx.com>,
 "pelzflorian \(Florian Pelz\)" <pelzflorian <at> pelzflorian.de>,
 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 28 Sep 2019 21:47:34 +0200

Danny Milosavljevic <dannym <at> scratchpost.org> skribis:

> On second thought, maybe it would be easiest to make term-auto "succeed" when
> it can't find that serial console.  Shepherd would think everything is a-ok and
> nobody would tell it any better :P

Well, that’s true!  :-)

Ludo’.

Message #88 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: "pelzflorian (Florian Pelz)" <pelzflorian <at> pelzflorian.de>
Cc: Ludovic Courtès <ludo <at> gnu.org>, 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sun, 29 Sep 2019 08:02:41 -0500

I went looking for the pid to answer Ludo's question and didn't find strace, and the ssh command line was wrong so I got suspicious.

After searching a bit, I found the problem: I'm an idiot.  'make' apparently did not succeed after all and I simply failed to catch it.  I went back and re-executed everything, slower this time and paying better attention and found this after 'make check':

make[2]: Entering directory '/home/bgardner/Development/guix/po/guix'
test ! -f ./guix.pot || \
  test -z "cs.gmo da.gmo de.gmo en <at> boldquot.gmo en <at> quot.gmo eo.gmo es.gmo fr.gmo hu.gmo pl.gmo pt_BR.gmo sr.gmo sv.gmo vi.gmo zh_CN.gmo" || make cs.gmo da.gmo de.gmo en <at> boldquot.gmo en <at> quot.gmo eo.gmo es.gmo fr.gmo hu.gmo pl.gmo pt_BR.gmo sr.gmo sv.gmo vi.gmo zh_CN.gmo
make[3]: Entering directory '/home/bgardner/Development/guix/po/guix'
make[3]: 'cs.gmo' is up to date.
make[3]: 'da.gmo' is up to date.
make[3]: 'de.gmo' is up to date.
rm -f en <at> boldquot.gmo && /gnu/store/byxp8n6qsyg2pm1p5x409sag9mbj1b3r-profile/bin/msgfmt -c --statistics --verbose -o en <at> boldquot.gmo en <at> boldquot.po
en <at> boldquot.po:2857: format specifications in 'msgstr[0]' are not a subset of those in 'msgid_plural'
en <at> boldquot.po:2864: format specifications in 'msgstr[0]' are not a subset of those in 'msgid_plural'
/gnu/store/byxp8n6qsyg2pm1p5x409sag9mbj1b3r-profile/bin/msgfmt: found 2 fatal errors
en <at> boldquot.po: 916 translated messages.
make[3]: *** [Makefile:201: en <at> boldquot.gmo] Error 1
make[3]: Leaving directory '/home/bgardner/Development/guix/po/guix'
make[2]: *** [Makefile:238: stamp-po] Error 2
make[2]: Leaving directory '/home/bgardner/Development/guix/po/guix'
make[1]: *** [Makefile:4862: check-recursive] Error 1
make[1]: Leaving directory '/home/bgardner/Development/guix'
make: *** [Makefile:5330: check] Error 2

I've no idea what this 'msgfmt' issue is, however.  Any suggestions?

--
Brant Gardner

On Sat, Sep 28, 2019, at 08:54, pelzflorian (Florian Pelz) wrote:
> On Sat, Sep 28, 2019 at 07:38:49AM -0500, Brant Gardner wrote:
> > Hi Ludo;
> > 
> > Okay, I did those steps exactly:
> > 
> >   - clone
> >   - patch -p1 < your-patch
> >   - ./bootstrap
> >   - ./configure --localstatedir=/var
> >   - make check
> >   - sudo -E ./pre-inst-env guix system reconfigure /path/to/myconfig.scm
> >   - reboot
> > 
> > I had no issues or errors at any step and on reboot ssh-daemon tried & failed to start so all went according to plan, but /tmp does *not* have a ssh log file in it.
> > 
> > Not sure where this went sideways, any advice?
> > 
> > Thank you,
> > 
> 
> Perhaps /tmp is the wrong directory to store such an early log?  I
> have a Guix virtual machine where ssh-daemon, httpd, php-fpm and
> term-auto cannot be started on boot.  /var/log/debug contains:
> 
> Sep 28 15:47:00 localhost vmunix: [    0.898260] Write protecting the 
> kernel read-only data: 18432k
> Sep 28 15:47:00 localhost vmunix: [    0.900802] Freeing unused kernel 
> image memory: 2036K
> Sep 28 15:47:00 localhost vmunix: [    0.902187] Freeing unused kernel 
> image memory: 72K
> Sep 28 15:47:00 localhost vmunix: [    0.903142] Run /init as init 
> process
> Sep 28 15:47:00 localhost vmunix: [    1.168976] usbcore: registered 
> new interface driver usb-storage
> Sep 28 15:47:00 localhost vmunix: [    1.184777] usbcore: registered 
> new interface driver uas
> Sep 28 15:47:00 localhost vmunix: [    1.202265] hidraw: raw HID events 
> driver (C) Jiri Kosina
> Sep 28 15:47:01 localhost shepherd[1]: Service ssh-daemon could not be 
> started. 
> Sep 28 15:47:01 localhost vmunix: [    1.204318] usbcore: registered 
> new interface driver usbhid
> Sep 28 15:47:01 localhost vmunix: [    1.204320] usbhid: USB HID core 
> driver
> Sep 28 15:47:01 localhost vmunix: [    1.270227] isci: Intel(R) C600 
> SAS Controller Driver - version 1.2.0
> Sep 28 15:47:01 localhost vmunix: [    1.445126] EXT4-fs (sda1): 
> mounted filesystem with ordered data mode. Opts: (null)
> Sep 28 15:47:01 localhost vmunix: [    2.387966] random: fast init done
> Sep 28 15:47:01 localhost vmunix: [    3.554499] random: ssh-keygen: 
> uninitialized urandom read (32 bytes read)
> Sep 28 15:47:01 localhost vmunix: [    4.219031] random: shepherd: 
> uninitialized urandom read (4096 bytes read)
> Sep 28 15:47:02 localhost vmunix: [    4.615089] random: crng init done
> Sep 28 15:47:02 localhost vmunix: [    5.199788] shepherd[1]: Service 
> root has been started.
> Sep 28 15:47:02 localhost vmunix: [    6.559652] shepherd[1]: starting 
> services...
> Sep 28 15:47:02 localhost vmunix: [    6.563503] shepherd[1]: Service 
> root-file-system has been started.
> Sep 28 15:47:02 localhost vmunix: [    6.567531] shepherd[1]: Service 
> user-file-systems has been started.
> Sep 28 15:47:02 localhost vmunix: [    6.656184] shepherd[1]: waiting 
> for udevd...
> 
> I do not know if this is a problem with the order in which services,
> crng, mounting start.
> 
> Regards,
> Florian
>

Message #91 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Wed, 09 Oct 2019 09:49:07 -0500

[Message part 1 (text/plain, inline)]

Okay, my apologies for the delay - a few days later I did "git pull" and then all the same steps and now it compiles & makes without issue.  I activated the new configuration & rebooted.

ssh-daemon failed to start and the log showed up, so I *think* we caught it.

The log is attached, I hope this helps!

--
Brant Gardner

On Sat, Sep 28, 2019, at 09:11, Ludovic Courtès wrote:
> "Brant Gardner" <mail <at> lnklnx.com> skribis:
> 
> > Okay, I did those steps exactly:
> >
> >   - clone
> >   - patch -p1 < your-patch
> >   - ./bootstrap
> >   - ./configure --localstatedir=/var
> >   - make check
> >   - sudo -E ./pre-inst-env guix system reconfigure /path/to/myconfig.scm
> >   - reboot
> >
> > I had no issues or errors at any step and on reboot ssh-daemon tried & failed to start so all went according to plan, but /tmp does *not* have a ssh log file in it.
> >
> > Not sure where this went sideways, any advice?
> 
> Does the PID that ‘herd status ssh-daemon’ reports (under “Running
> value”) correspond to ‘strace’?
> 
> BTW, it may be that the problem will show up less frequently because
> sshd starts more slowly when running under ‘strace’.  That’s the hard
> part with timing-related bugs…
> 
> Thanks for testing!
> 
> Ludo’.
>

[ssh.log (text/x-log, attachment)]

Message #94 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Brant Gardner" <mail <at> lnklnx.com>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Fri, 11 Oct 2019 12:14:44 +0200

Hi Brant,

Thanks for sending the log!

"Brant Gardner" <mail <at> lnklnx.com> skribis:

> 284   09:31:59 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4 <0.000013>
> 284   09:31:59 connect(4, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0 <0.000014>
> 284   09:31:59 sendto(4, "<38>Oct  9 09:31:59 sshd[284]: Server listening on 0.0.0.0 port 22.", 67, MSG_NOSIGNAL, NULL, 0) = 67 <3.103979>
> 284   09:32:02 close(4)                 = 0 <0.000016>
> 284   09:32:02 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 4 <0.000024>
> 284   09:32:02 fcntl(4, F_GETFL)        = 0x2 (flags O_RDWR) <0.000011>
> 284   09:32:02 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000011>
> 284   09:32:02 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000011>
> 284   09:32:02 setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0 <0.000011>
> 284   09:32:02 setsockopt(4, SOL_IPV6, IPV6_V6ONLY, [1], 4) = 0 <0.000011>
> 284   09:32:02 bind(4, {sa_family=AF_INET6, sin6_port=htons(22), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, 28) = 0 <0.000014>
> 284   09:32:02 listen(4, 128)           = 0 <0.000012>
> 284   09:32:02 getpid()                 = 284 <0.000011>
> 284   09:32:02 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 5 <0.000013>
> 284   09:32:02 connect(5, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0 <0.000014>
> 284   09:32:02 sendto(5, "<38>Oct  9 09:32:02 sshd[284]: Server listening on :: port 22.", 62, MSG_NOSIGNAL, NULL, 0) = 62 <4.195488>
> 284   09:32:07 close(5)                 = 0 <0.000019>

I’m under the impression that sshd successfully start this time, didn’t it?

Thanks,
Ludo’.

Message #97 received at 34580 <at> debbugs.gnu.org (full text, mbox):

From: "Brant Gardner" <mail <at> lnklnx.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 34580 <at> debbugs.gnu.org
Subject: Re: bug#34580: Service ssh-daemon could not be started
Date: Sat, 12 Oct 2019 07:09:51 -0500

Well, now that I actually test it - yes.  But I said it had not because the 'herd status ssh-daemon' message indicated that it isn't running:

root <at> janus ~# herd status ssh-daemon
Status of ssh-daemon:
  It is stopped.
  It is enabled.
  Provides (ssh-daemon).
  Requires (syslogd loopback).
  Conflicts with ().
  Will be respawned.

Is this maybe a side effect of strace being involved?

--
Brant Gardner

On Fri, Oct 11, 2019, at 05:14, Ludovic Courtès wrote:
> Hi Brant,
> 
> Thanks for sending the log!
> 
> "Brant Gardner" <mail <at> lnklnx.com> skribis:
> 
> > 284   09:31:59 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4 <0.000013>
> > 284   09:31:59 connect(4, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0 <0.000014>
> > 284   09:31:59 sendto(4, "<38>Oct  9 09:31:59 sshd[284]: Server listening on 0.0.0.0 port 22.", 67, MSG_NOSIGNAL, NULL, 0) = 67 <3.103979>
> > 284   09:32:02 close(4)                 = 0 <0.000016>
> > 284   09:32:02 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 4 <0.000024>
> > 284   09:32:02 fcntl(4, F_GETFL)        = 0x2 (flags O_RDWR) <0.000011>
> > 284   09:32:02 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000011>
> > 284   09:32:02 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000011>
> > 284   09:32:02 setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0 <0.000011>
> > 284   09:32:02 setsockopt(4, SOL_IPV6, IPV6_V6ONLY, [1], 4) = 0 <0.000011>
> > 284   09:32:02 bind(4, {sa_family=AF_INET6, sin6_port=htons(22), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, 28) = 0 <0.000014>
> > 284   09:32:02 listen(4, 128)           = 0 <0.000012>
> > 284   09:32:02 getpid()                 = 284 <0.000011>
> > 284   09:32:02 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 5 <0.000013>
> > 284   09:32:02 connect(5, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0 <0.000014>
> > 284   09:32:02 sendto(5, "<38>Oct  9 09:32:02 sshd[284]: Server listening on :: port 22.", 62, MSG_NOSIGNAL, NULL, 0) = 62 <4.195488>
> > 284   09:32:07 close(5)                 = 0 <0.000019>
> 
> I’m under the impression that sshd successfully start this time, didn’t it?
> 
> Thanks,
> Ludo’.
>

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.