'ssh-daemon' fails to start

  • Done
  • quality assurance status badge
Details
9 participants
  • Andreas Enge
  • Chris Marusich
  • Christopher Lemmer Webber
  • Danny Milosavljevic
  • Leo Famulari
  • Ludovic Courtès
  • Brant Gardner
  • maxim.cournoyer
  • pelzflorian (Florian Pelz)
Owner
unassigned
Submitted by
Andreas Enge
Severity
important
Merged with

Debbugs page

A
A
Andreas Enge wrote on 19 Feb 2019 13:21
Service ssh-daemon could not be started
(address . bug-guix@gnu.org)
20190219212126.GA2371@jurong
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
L
L
Leo Famulari wrote on 20 Feb 2019 14:21
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
20190220222158.GA24808@jasmine.lan
On Tue, Feb 19, 2019 at 10:21:26PM +0100, Andreas Enge wrote:
Toggle quote (7 lines)
> 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?
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlxt0wUACgkQJkb6MLrK
fwjpGhAAqZnbiIgQADsFMC9LU1xdTZ4H5zmhvMkcMI26pNwMzGxsKzlVSLge+er8
lDMPf9JuUv8H2UbLYOrQ4G7vREFAODTO9LU9tBTQZFqaGGsu+mEIhl3j6KXi5CTV
HZMnv28xO5i03ITkWsedrzN2LG9EfzhCpLEhPVObau3pWk/RWcSJCr1eOYz9mA1R
qju36Kprsxzoi6KplTfkGA0USqgP7joJJLGpPLLmg9KTD5+o8wvoAlEd8T0P/flv
ds0SD7xRUck4Uy48naMAS6zt0rloUf8dvRmCWalrMJDSp5HGmhTNaBTgVd2aSzpL
bWa9d9mLHTUwL+VM+XH/60GKTrXSfiqzfH6eieQm38vuAnXC3x8Wj5B4QHYGI0cI
Fw2mxlaoX4rpzqUT1IhYntw9pX5dghmvO3Hc5cNmfqydw3s20HRKont/jPOzVrSb
ZnbbF4siCVi/xxoJ7d7SCrlJUPzHzDZLA8IfqTS2iOIBKitI6J9Z5f1jW0uLxHkf
hPX7jpGCJWq831Pb5winvhS8bX2M0mX9mG4aJXTEQuZum1MgdkZviHtTLuEJi2Ec
Zgq2MYGBlYAlc/10gJwDYgQ1S03ll2Btv8dCIqVCxrTqSYOgxXPHRQ1swi0Onre4
mJ9KlVj7XzV6S0bzsKl5CfWntH3aVMu90KBHAc96YqE+H7EQv90=
=8QoG
-----END PGP SIGNATURE-----


A
A
Andreas Enge wrote on 20 Feb 2019 14:48
(name . Leo Famulari)(address . leo@famulari.name)(address . 34580@debbugs.gnu.org)
20190220224802.GA13647@jurong
On Wed, Feb 20, 2019 at 05:21:58PM -0500, Leo Famulari wrote:
Toggle quote (2 lines)
> 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
L
L
Leo Famulari wrote on 20 Feb 2019 14:51
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
20190220225154.GA26281@jasmine.lan
On Wed, Feb 20, 2019 at 11:48:02PM +0100, Andreas Enge wrote:
Toggle quote (3 lines)
> 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.
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlxt2goACgkQJkb6MLrK
fwhajBAA4iwUDW2utvl/Mv6ODbaZuOE/jWFLiO1Q9VGIWwErBG1fLuLwSLOECdRQ
pj1CoQhL+S3DqfSEUODPZmM13u9pKWOEYifAJtlpkMLY77iJ6okwnGkcNrKj8otC
+EtJIhvCIVDs8f6UDtGM4SMBspBMFxwJukp5H92BHsrr8qD2uD/Xxdwc9ylfKFGY
Sne9lGk5Y2napqBwUlNr5Y0AILBwc7NUiPF+jXMJseHZeFA8GALVNAUsUBUfyA19
OKVhBCQMT12OelpxG2JHA65HhH1cZNtU0RE+x463UCnc1nPD0bjLh+6nZv/30hmY
cV+n0PYvcp6ff/SPurBr4dshrChCVdWgGPpInnm5d1urJyruiw8kkw80RtdyZpba
OVsOvie6rsbw1JH7/ANVMVhM/4WZt2IuEz4nEJP6x+HFMGP/9Nv5N2SnUyq9eu3g
7zTdTbkQ10sGcNl3eQ8yOyEe5jrbh3Ks0JQ9z2H8+63hUsjGpsBGB9+P3BBF+XoV
jWkvkx7iXga3CDNMw5rvLrh/kjFH3vvKIJnvbTZ4z5ufj8h056XCy9vnfiT5o04p
oHcnO543vncZqjgj7Pvvo77DRrvyEGKjJezv2JH0a/4EDkecSchb4UvMNW2HmY6y
G7pHf2JdMdO6Su8ejXxFl5x/6WJ3yqqulnKKnQKDzjsuivgKHEY=
=ZL7S
-----END PGP SIGNATURE-----


A
A
Andreas Enge wrote on 20 Feb 2019 15:08
(name . Leo Famulari)(address . leo@famulari.name)(address . 34580@debbugs.gnu.org)
20190220230807.GA13841@jurong
On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:
Toggle quote (4 lines)
> 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
L
L
Leo Famulari wrote on 20 Feb 2019 15:56
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
20190220235634.GA28504@jasmine.lan
On Thu, Feb 21, 2019 at 12:08:07AM +0100, Andreas Enge wrote:
Toggle quote (6 lines)
> 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?
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlxt6S8ACgkQJkb6MLrK
fwhl/BAAkKQl6qI9DnmxXsA/4J16ZMiH3EEg/yG63V6X2B52sy1KU9kRV4X3P3ZV
OlMwUSchSri1KXwa5EzZtBsRhCs6YJrae13hidtIlTOVtCIWeywejuiKUbDT1BTr
hBpWLQFeNvk8Vmnuot/MyiHMx+7v2dn9K7LV5w/YWu92XZQIkQBh0eWeGWFDOGkn
MGFkt9iEk7XPLEwoyAa82r4Gl4XjKSUye6hUkJU/qh0fwLGXMiL77P9In1pIeARk
k0vh47rTeIsOM0dTXDqePF0S3pCM/zDcNLiKgYFsvVePXNSpXQO9qck5gds/P9mt
MxOZ/ogd4tAhpIP2igFu8SqPflG9HWB44c4vUEgiBYA7bGxXcyB8EhVGDrJH/8gm
iyP6ple0k4+wWfb2kW2YeemmMyKyG36T3AeO85P1jkkDDkzBpSmlAK05kQzrdU12
h1CzBYse0+rg0RrC0aMuKLP6WtG6UjAOMFPY+tbXV71iZdeE1vg/ncoJfd3lKX0q
r1U5vdsejEks2bhjBQjKGJTuiUHuz+xgvT9OC06EzX1JP9atKAHyXIUD6H0ZEn1u
eKqjWf4/nAGp6Sp2mv1lvRTz2E9+jTNTV5BuboRDbVt4NbPQRs559Aotn5cEaTMh
xPI4bkVDJXEV1GZFfqGFpagmpBUCYg9X/A2paubFlKUTxkAeMDc=
=vu2t
-----END PGP SIGNATURE-----


C
C
Chris Marusich wrote on 21 Feb 2019 22:52
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
87k1hsb9ij.fsf@gmail.com
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
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCAAdFiEEy/WXVcvn5+/vGD+x3UCaFdgiRp0FAlxvnBQACgkQ3UCaFdgi
Rp1MiQ/+N5y8mCdhyguKvQ37Wo9AujFjjoywmHvZiUeyXma2n17Q/NH0afzhsz1V
i5ufLYwRH57tUK4vK7z+oSMg7IlZf3OktECYEkEb72y1mOK246dKWWAwqpndU1FC
xXr3Nj9ew4BRPqQFkcSa2D1FUQAM1tN4M128a0Kkfvz5Py1lE18lsr3PRGDrX7IS
/jceO4X2wOHp4bQAsXZaB9uCcDCMtmrR6zfAcTSgid3QhXh2aYP0ExRDJPEA9XCC
Zxk/jVwbqb4JA5nsADFj6cnrCugCOZhtuWE9z+55272JCebm/8hilB4Kz6DHYWWH
JomPdq6TXZ7st7/igoDikk0i91FL91ljRIdk3Dbxi7EzpIMczSVu/Ds/AzLzqoCH
B1MyIMPbWKLjlnNZ4aYydbLI1dpPAJMtL4/G/iXQEb3QPMfaxMGyt0bhj/0VhVCz
bTD9o8EcnW2rsBNcMAlJ0deVaSF2b/hrFqaCuWn4yKW+X20rKtVVHiNZ5Z///8JY
LplfSc4hUrPIqufXfoEtBaJWrIBCJXMzAeLdPr9ms/KP5a8MbsST089327rleAva
vAlpsUAbZbPY2G7/3eR7TXSJGkvIB833xJp8Teu43S6IJP4/LcOiOPGhXMBHpBho
q3T+5Hj/sb8GskyDctGD9fe70+gLN1FKR/nv0gonLtcq7veRHCY=
=S01M
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 9 Mar 2019 10:35
control message for bug #34580
(address . control@debbugs.gnu.org)
87va0r520r.fsf@gnu.org
severity 34580 important
L
L
Ludovic Courtès wrote on 9 Mar 2019 10:35
control message for bug #30993
(address . control@debbugs.gnu.org)
87tvgb520i.fsf@gnu.org
merge 30993 34580
L
L
Leo Famulari wrote on 14 Mar 2019 15:11
Re: bug#34580: Service ssh-daemon could not be started
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
20190314221121.GA23532@jasmine.lan
On Wed, Feb 20, 2019 at 05:51:54PM -0500, Leo Famulari wrote:
Toggle quote (2 lines)
> For now I am still using Shepherd 0.3 on that machine :/

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

Toggle quote (2 lines)
> I plan to reinstall from scratch soon.

Reinstallation did not help.
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlyK0YYACgkQJkb6MLrK
fwijVw/+PParvF4kwUeor5v59MUB88JAp9g0W09ggaNQXmSVNCO7VziFqjGuszma
fzUVDXpEsTzHWQ+a4UMAFqauceLgzIitCfF7f/XMUz76T2mkzGDpslIYnhEoapQi
PPCofl59gp7PwJAaS1dmc/hNPJFqLocTFRGvatzgm1E8UeS59OSoUP/9E+2hr4oj
tiGSnlCr0HCfl2BCH3cGU5esauqVld2y8EuH6zrI79eBASqMsZPxM4Znm+pQLOtY
nLGcSVOhk5BqZFnQ0C7ua3NFobxliDo9yW6/m9KJWzNrLzHQuIKuHO9KBzYPfo7i
iHw/VFlftq7Usv2+gF80sc8YgwJR4z2W79GCAbtcdahypUwhNm60sYq7XPdav/3Q
PMfJS62ft7ajqaVkGrv28N114spnoQkiOdgSz7oqCHsKrIgS8L5XSQbuBnf82ir6
wJFbfyVQJNvDELuVhubhZOcdUjAvE/iQ32H/zWs/H/LnMJU4usxXt7ajaVnOmOTb
V7sjg3EWv81EMiM4YQS3GYDZKh/pZb3XI+V8l4Dw4c5n4VImiycFxQjHgBYfsq6H
rDQAjqDER8Vo4DD7dClpT56TokcF8oFZkb/34oMaNfN7wAQuJPZK1EVOEzXwJS+4
LIotpY1Ux/N+VvIztcz+eumLZjxRAvAnN/nKgoxZwnOwxkgH1ro=
=FH2v
-----END PGP SIGNATURE-----


L
L
Leo Famulari wrote on 15 Mar 2019 09:35
(name . Andreas Enge)(address . andreas@enge.fr)(address . 34580@debbugs.gnu.org)
20190315163524.GA30892@jasmine.lan
On Thu, Mar 14, 2019 at 06:11:21PM -0400, Leo Famulari wrote:
Toggle quote (2 lines)
> 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...
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlyL1EkACgkQJkb6MLrK
fwg5lBAAxTE0zvyiZCQGrXy7KE3n8RAKiTN1cbJABuA3G7QfFb+SxEU5MaRFO+TD
0AbYhoDtXTwq2POckKIorzk/aFHSQUMqkyAJYCbcp/q4TOBceZLcHsW2tqe7ueQy
Tu8LHtLHkRdcISuH8IcieBQzeiBqmukj5zGoy+LvVuwI9va9UDjZVTKzyoGwgMcT
jzxvCyGpJsbw9obTJMBnOhFtQ/dw/ZAXhxOFmldPHWmg/suZNoA4q9HKJr7hKe6j
XcMh4SuJyhIsDv4daDjezVAn8k0VcX60wXFk+pKCEVWk0PTZhesXlRhOImh3BD1J
nxRt32BGDyyjPAQIyrkPP4wGwuQgsLSDCZNZsmg3+Kpn4/w+2A3CCtMC0Fu6miAz
w/tV3ySPT34tWRLKVmmUstYrWP2Fu6lekCrCowKZ+nqUykV768Noccm9/0tbA+6+
AuzY87Wn5pcf3gTNfEkcAgBVc3JQ293dzS3/0OJNuiNY+LS2z+IoMoS+v4qUExOo
tkURxjIg+XbjPZgaR95Ux+FXlWiSEdlUnsazJR/H8FPDu94BXNN7cRTfc4sWI+30
GWzoRZxnPhrC4X+RTAh/r4UJ7qDlyzje7sxPL8eFtAgTDTR2hJ2lnFhk3q1DkELz
90Pe2FyMl/FZSk+iyf9v3Strmnnq7Ga1xB6CtD22mQ87/ha8Ius=
=yyTd
-----END PGP SIGNATURE-----


B
B
Brant Gardner wrote on 20 Sep 2019 09:19
Archived problem report bug#34580 (Service ssh-daemon could no t be started)
(address . control@debbugs.gnu.org)
1ee347ea-f340-4d61-8bfb-53a58139aa2d@www.fastmail.com
unarchive 34580

--
Brant Gardner
Attachment: file
B
B
Brant Gardner wrote on 20 Sep 2019 13:00
Service ssh-daemon could not be started
(address . 34580@debbugs.gnu.org)
e90a946a-3bc4-4db0-9b40-898891b8da71@www.fastmail.com
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
Attachment: file
L
L
Ludovic Courtès wrote on 24 Sep 2019 01:08
(name . Brant Gardner)(address . mail@lnklnx.com)(address . 34580@debbugs.gnu.org)
87pnjqm809.fsf@gnu.org
Hi Brant,

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

Toggle quote (8 lines)
> 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’.
B
B
Brant Gardner wrote on 24 Sep 2019 05:20
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 34580@debbugs.gnu.org)
6d672221-0e2f-40cd-b129-1f893fe13472@www.fastmail.com
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:
Toggle quote (22 lines)
> Hi Brant,
>
> "Brant Gardner" <mail@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’.
>
L
L
Ludovic Courtès wrote on 26 Sep 2019 13:28
control message for bug #30993
(address . control@debbugs.gnu.org)
87r242ls3n.fsf@gnu.org
merge 30993 37309
quit
L
L
Ludovic Courtès wrote on 26 Sep 2019 13:29
(address . control@debbugs.gnu.org)
87pnjmls36.fsf@gnu.org
retitle 30993 'ssh-daemon' fails to start
quit
L
L
Ludovic Courtès wrote on 26 Sep 2019 13:48
Re: bug#34580: Service ssh-daemon could not be started
(name . Brant Gardner)(address . mail@lnklnx.com)(address . 34580@debbugs.gnu.org)
87o8z6kclh.fsf@gnu.org
Hi Brand,

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

Toggle quote (2 lines)
> 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’.
--- 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
B
B
Brant Gardner wrote on 27 Sep 2019 07:57
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 34580@debbugs.gnu.org)
75efee63-c5e4-4d7f-aec2-e1afa3a8ba00@www.fastmail.com
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:
Toggle quote (17 lines)
> Hi Brand,
>
> "Brant Gardner" <mail@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’.
>
>
L
L
Ludovic Courtès wrote on 28 Sep 2019 02:45
(name . Brant Gardner)(address . mail@lnklnx.com)(address . 34580@debbugs.gnu.org)
87pnjkzrca.fsf@gnu.org
Hi Brant,

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

Toggle quote (7 lines)
> 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:

cd guix
patch -p1 < the-patch

Then you need to build Guix from that checkout:


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’.
B
B
Brant Gardner wrote on 28 Sep 2019 05:38
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 34580@debbugs.gnu.org)
754a6968-2d9e-431d-a545-7580fd81b7db@www.fastmail.com
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:
Toggle quote (33 lines)
> Hi Brant,
>
> "Brant Gardner" <mail@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’.
>
P
P
pelzflorian (Florian Pelz) wrote on 28 Sep 2019 06:54
(name . Brant Gardner)(address . mail@lnklnx.com)
20190928135456.xm3ioetdynui7wtt@pelzflorian.localdomain
On Sat, Sep 28, 2019 at 07:38:49AM -0500, Brant Gardner wrote:
Toggle quote (19 lines)
> 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
L
L
Ludovic Courtès wrote on 28 Sep 2019 07:11
(name . Brant Gardner)(address . mail@lnklnx.com)(address . 34580@debbugs.gnu.org)
87impctss7.fsf@gnu.org
"Brant Gardner" <mail@lnklnx.com> skribis:

Toggle quote (14 lines)
> 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’.
L
L
Ludovic Courtès wrote on 28 Sep 2019 10:44
(name . pelzflorian (Florian Pelz))(address . pelzflorian@pelzflorian.de)
87tv8wqpsf.fsf@gnu.org
Hi,

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

Toggle quote (2 lines)
> Perhaps /tmp is the wrong directory to store such an early log?

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

Toggle quote (3 lines)
> 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’.
D
D
Danny Milosavljevic wrote on 28 Sep 2019 11:23
20190928202329.473e4665@scratchpost.org
Hi everyone,

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

Toggle quote (3 lines)
> ‘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.
-----BEGIN PGP SIGNATURE-----

iQEzBAEBCAAdFiEEds7GsXJ0tGXALbPZ5xo1VCwwuqUFAl2PpSEACgkQ5xo1VCww
uqU3Lgf+I/K79kYdp7hNuTpR3yfx7lnZMg59NFs/tt4upy5tOmj9AIPaTXols8wJ
XWiU2uto8wq1HwaljegsWVzORYNqamSmM1Yrs/8qaRPbc/8VsG489s7p9PgEOX1V
Q8GsGPnGvx0hjlKynoxiK+aMmPBaEH9GY1lflqteaYesDxFCwxDQAOSXUN3l69lI
JFH2z07tGetwHaej9uY8QpKSVG2LaUFALOHpeEuHM85RQ8H/Z77aUCK1iUjuNDkA
9/Tom14T3EOW32TrzcqyJRmHRFkvgZ1ROS/izC01eKAlRHzXAvSsnK0r2071dwjQ
68Czdmukc/gefy7BpuuTD2/IqGlHNQ==
=1k93
-----END PGP SIGNATURE-----


D
D
Danny Milosavljevic wrote on 28 Sep 2019 11:31
20190928203131.6971469d@scratchpost.org
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
-----BEGIN PGP SIGNATURE-----

iQEzBAEBCAAdFiEEds7GsXJ0tGXALbPZ5xo1VCwwuqUFAl2PpwMACgkQ5xo1VCww
uqVQnAf8DeI0xRTPwzAaj0bHKBdxpV+wpdwmigOiVbUOCciKL1WnjovWQ5tg/+5h
KGco5ncAATeVBlcqO+SyjuPArBaC8EyIfBKV06ofarEJosoAP0OZ+svl5aQ3Z8bx
Dp/mAdmSHZfCQBAklqcgjCeIAIhHoysvfU37tTkWXOV8ZUUXiIIOB9LV0gkYpI9e
JhiZyvOnTWFIowXHvuGGzMYtcErBt2BFZtWBN5R8GzUAF9a/uoerwsbPJtlIf1oU
0TAGpeBanMhzSZzYYnYqD/JHDoW4+4XTfzlsfc/blKbMccudS0ONdf+Fe6JwxT0d
I/18lfbAGxrKc36nH4XgU+55F2HjdQ==
=WS4y
-----END PGP SIGNATURE-----


L
L
Ludovic Courtès wrote on 28 Sep 2019 12:47
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)
87lfu8p5j5.fsf@gnu.org
Hi Danny!

Danny Milosavljevic <dannym@scratchpost.org> skribis:

Toggle quote (7 lines)
> 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’.
L
L
Ludovic Courtès wrote on 28 Sep 2019 12:47
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)
87h84wp5ih.fsf@gnu.org
Danny Milosavljevic <dannym@scratchpost.org> skribis:

Toggle quote (4 lines)
> 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’.
B
B
Brant Gardner wrote on 29 Sep 2019 06:02
(name . pelzflorian (Florian Pelz))(address . pelzflorian@pelzflorian.de)
dbe0ce85-792c-4471-b1bc-e16e3753010e@www.fastmail.com
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:
Toggle quote (71 lines)
> 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
>
B
B
Brant Gardner wrote on 9 Oct 2019 07:49
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 34580@debbugs.gnu.org)
2dad64c4-a48b-4661-97dc-3804e2aaf03c@www.fastmail.com
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:
Toggle quote (27 lines)
> "Brant Gardner" <mail@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’.
>
Attachment: ssh.log
L
L
Ludovic Courtès wrote on 11 Oct 2019 03:14
(name . Brant Gardner)(address . mail@lnklnx.com)(address . 34580@debbugs.gnu.org)
87o8ynpp0r.fsf@gnu.org
Hi Brant,

Thanks for sending the log!

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

Toggle quote (18 lines)
> 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’.
B
B
Brant Gardner wrote on 12 Oct 2019 05:09
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 34580@debbugs.gnu.org)
b7fa80f0-02b9-4d7e-bfdc-9ecd289a9683@www.fastmail.com
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:
Toggle quote (29 lines)
> Hi Brant,
>
> Thanks for sending the log!
>
> "Brant Gardner" <mail@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’.
>
M
M
maxim.cournoyer wrote on 17 Aug 2020 21:08
control message for bug #30993
(address . control@debbugs.gnu.org)
87wo1wppdk.fsf@hurd.i-did-not-set--mail-host-address--so-tickle-me
tags 30993 fixed
close 30993
quit
C
C
Christopher Lemmer Webber wrote on 27 Nov 2020 14:57
unarchive 37309
(address . control@debbugs.gnu.org)
87y2imjtm0.fsf@dustycloud.org
unarchive 37309
?
Your comment

This issue is archived.

To comment on this conversation send an email to 34580@patchwise.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 34580
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch