'ssh-daemon' fails to start

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

On Tue, Feb 19, 2019 at 10:21:26PM +0100, Andreas Enge wrote:

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

On Wed, Feb 20, 2019 at 05:21:58PM -0500, Leo Famulari wrote:

I suppose so. I would be happy to provide further information, but there is

not much to see in the log files.

Andreas

On Wed, Feb 20, 2019 at 11:48:02PM +0100, Andreas Enge wrote:

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.

On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:

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

On Thu, Feb 21, 2019 at 12:08:07AM +0100, Andreas Enge wrote:

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?

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

severity 34580 important

merge 30993 34580

On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:

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

Reinstallation did not help.

On Thu, Mar 14, 2019 at 06:11:21PM -0400, Leo Famulari wrote:

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...

unarchive 34580

--

Brant Gardner

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

Hi Brant,

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

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’.

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:

merge 30993 37309

quit

retitle 30993 'ssh-daemon' fails to start

quit

Hi Brand,

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

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’.

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 Brant,

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

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’.

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:

On Sat, Sep 28, 2019 at 07:38:49AM -0500, Brant Gardner wrote:

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

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

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’.

Hi,

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

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

‘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’.

Hi everyone,

On Sat, 28 Sep 2019 19:44:16 +0200

Ludovic Courtès <ludo@gnu.org> wrote:

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.

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

Hi Danny!

Danny Milosavljevic <dannym@scratchpost.org> skribis:

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’.

Danny Milosavljevic <dannym@scratchpost.org> skribis:

Well, that’s true! :-)

Ludo’.

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@boldquot.gmo en@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@boldquot.gmo en@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@boldquot.gmo && /gnu/store/byxp8n6qsyg2pm1p5x409sag9mbj1b3r-profile/bin/msgfmt -c --statistics --verbose -o en@boldquot.gmo en@boldquot.po

en@boldquot.po:2857: format specifications in 'msgstr[0]' are not a subset of those in 'msgid_plural'

en@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@boldquot.po: 916 translated messages.

make[3]: *** [Makefile:201: en@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:

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:

Hi Brant,

Thanks for sending the log!

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

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

Thanks,

Ludo’.

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@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:

tags 30993 fixed

close 30993

quit

unarchive 37309