'ssh-daemon' fails to start

Done

Details

8 participants

Martin Castillo
Clément Lassieur
Christopher Lemmer Webber
Taegil Bae
Leo Famulari
Ludovic Courtès
Brant Gardner
maxim.cournoyer

Owner: unassigned

Submitted by: Leo Famulari

Severity: important

Merged with

Leo Famulari wrote on 29 Mar 2018 22:08

OpenSSH sshd killed by Shepherd 0.4.0

Recipients:(address . bug-guix@gnu.org)

Message-ID:20180329200803.GA15842@jasmine.lan

Since the update to Shepherd 0.4.0, I've found that OpenSSH's sshd is
killed almost immediately after it starts with signal 15. I confirmed
the issue started with the Shepherd upgrade by bisecting our Git
history.

I can reproduce the issue from commit
b6beda1d6b9093a8493b5c3cde33ed522242c451 (gnu: Add botan.).

One interesting tidbit is that the PID file '/var/run/sshd.pid' is not
created anymore. And if I create an empty PID file by hand, it is
removed after trying to start the ssh-daemon service. Also, the sshd
user's home '/var/run/sshd' does not exist, and is similarly removed if
it does exist.

I ran the OpenSSH system test `make check-system TESTS=openssh` and it
failed when it could not find the PID file. It passed on another
non-GuixSD machine. The failing machine is relatively slow and lacks
KVM: a ThinkPad x200s.

After boot, trying to start the service again with `herd start
ssh-daemon` gives the same result.

I modified the sshd invocation to print some debug output ('-d -E
/tmp/sshd.log') and this is what it shows:

------
debug1: sshd version OpenSSH_7.6, OpenSSL 1.0.2o  27 Mar 2018
debug1: private host key #0: ssh-rsa SHA256:REDACTED
debug1: private host key #1: ssh-dss SHA256:REDACTED
debug1: private host key #2: ecdsa-sha2-nistp256 SHA256:REDACTED
debug1: private host key #3: ssh-ed25519 SHA256:REDACTED
debug1: rexec_argv[0]='/gnu/store/az7vib8gk16fybhshh5xpkljmgxyrs4k-openssh-7.6p1/sbin/sshd'
debug1: rexec_argv[1]='-D'
debug1: rexec_argv[2]='-d'
debug1: rexec_argv[3]='-E'
debug1: rexec_argv[4]='/tmp/sshd.log'
debug1: rexec_argv[5]='-f'
debug1: rexec_argv[6]='/gnu/store/miy7xg5j4fg3mn04mcl27awmcl6s97ss-sshd_config'
debug1: Set /proc/self/oom_score_adj from 0 to -1000
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
Received signal 15; terminating.
------

My system configuration file, the shepherd log messages, and the OpenSSH
system test logs are attached. Any ideas?

Mar 29 15:47:32 localhost shepherd[1]: Service syslogd has been started. 
Mar 29 15:47:33 localhost shepherd[1]: Service loopback has been started. 
Mar 29 15:47:34 localhost shepherd[1]: Service virtual-terminal has been started. 
Mar 29 15:47:35 localhost shepherd[1]: Service term-tty6 has been started. 
Mar 29 15:47:35 localhost shepherd[1]: Service term-tty5 has been started. 
Mar 29 15:47:36 localhost shepherd[1]: Service term-tty4 has been started. 
Mar 29 15:47:38 localhost shepherd[1]: Service term-tty3 has been started. 
Mar 29 15:47:39 localhost shepherd[1]: Service term-tty2 has been started. 
Mar 29 15:47:41 localhost shepherd[1]: Service term-tty1 has been started. 
Mar 29 15:47:43 localhost shepherd[1]: Service term-auto could not be started. 
Mar 29 15:47:44 localhost shepherd[1]: Service console-font-tty1 has been started. 
Mar 29 15:47:46 localhost shepherd[1]: Service console-font-tty2 has been started. 
Mar 29 15:47:48 localhost shepherd[1]: Service console-font-tty3 has been started. 
Mar 29 15:47:49 localhost shepherd[1]: Service console-font-tty4 has been started. 
Mar 29 15:47:50 localhost shepherd[1]: Service console-font-tty5 has been started. 
Mar 29 15:47:50 localhost shepherd[1]: Service console-font-tty6 has been started. 
Mar 29 15:47:51 localhost shepherd[1]: Service dbus-system has been started. 
Mar 29 15:47:51 localhost shepherd[1]: Service networking has been started. 
Mar 29 15:47:52 localhost shepherd[1]: Service ntpd has been started. 
Mar 29 15:47:56 localhost shepherd[1]: Service ssh-daemon could not be started. 
Mar 29 15:47:59 localhost shepherd[1]: Service gpm has been started. 
Mar 29 15:48:29 localhost vmunix: [    5.486795] shepherd[1]: Service root has been started.
Mar 29 15:48:29 localhost vmunix: [    7.379651] shepherd[1]: starting services...
Mar 29 15:48:29 localhost vmunix: [    7.381562] shepherd[1]: Service root-file-system has been started.
Mar 29 15:48:29 localhost vmunix: [    7.383337] shepherd[1]: Service user-file-systems has been started.
Mar 29 15:48:29 localhost vmunix: [    7.625406] shepherd[1]: Service file-system-/home has been started.
Mar 29 15:48:29 localhost vmunix: [    7.627645] shepherd[1]: Service file-system-/dev/pts has been started.
Mar 29 15:48:29 localhost vmunix: [    7.629909] shepherd[1]: Service file-system-/dev/shm has been started.
Mar 29 15:48:29 localhost vmunix: [    7.632089] shepherd[1]: Service file-system-/gnu/store has been started.
Mar 29 15:48:29 localhost vmunix: [    7.633924] shepherd[1]: Service file-systems has been started.
Mar 29 15:48:29 localhost vmunix: [    7.731477] shepherd[1]: waiting for udevd...
Mar 29 15:48:29 localhost vmunix: [    8.331344] shepherd[1]: Service udev has been started.
Mar 29 15:48:30 localhost vmunix: [    8.446599] shepherd[1]: Service urandom-seed has been started.
Mar 29 15:48:30 localhost vmunix: [    8.448462] shepherd[1]: Service user-processes has been started.
Mar 29 15:48:30 localhost vmunix: [    8.450424] shepherd[1]: Service host-name has been started.
Mar 29 15:48:30 localhost vmunix: [    8.546746] shepherd[1]: Service user-homes could not be started.
Mar 29 15:48:30 localhost vmunix: [    9.554051] shepherd[1]: Service nscd has been started.
Mar 29 15:48:30 localhost vmunix: [    9.606182] shepherd[1]: Service guix-daemon has been started.
Mar 29 15:49:21 localhost shepherd[1]: Respawning term-tty2. 
Mar 29 15:49:21 localhost shepherd[1]: Service term-tty2 has been started. 
Mar 29 15:49:28 localhost shepherd[1]: Respawning term-tty1. 
Mar 29 15:49:28 localhost shepherd[1]: Service term-tty1 has been started.

;; This is an operating system configuration template ;; for a "bare bones" setup, with no X11 display server. (use-modules (gnu)) (use-service-modules networking dbus ssh sysctl) (use-package-modules certs curl ssh rsync tmux version-control vim) (operating-system (host-name "computer") (timezone "America/New_York") (locale "en_US.UTF-8") (kernel-arguments '(;; Console resolution "gfxpayload=1440x900x16,1440x900" ;; console cursor. stops the blinking but the colors are bad "vt.cur.default=0x520032" "consoleblank=120" "quiet")) ;; Assuming /dev/sdX is the target hard disk, and "my-root" is ;; the label of the target root file system. (bootloader (grub-configuration (target "/dev/sda") (terminal-outputs '(console)))) (file-systems (cons* (file-system (device "my-root") (title 'label) (mount-point "/") (type "ext4")) (file-system (device "home") (title 'label) (mount-point "/home") (type "ext4")) %base-file-systems)) ;; This is where user accounts are specified. The "root" ;; account is implicit, and is initially created with the ;; empty password. (users (cons (user-account (name "leo") (comment "") (group "users") ;; Adding the account to the "wheel" group ;; makes it a sudoer. Adding it to "audio" ;; and "video" allows the user to play sound ;; and access the webcam. (supplementary-groups '("wheel" "netdev" "audio")) (home-directory (string-append "/home/" name))) %base-user-accounts)) ;; Globally-installed packages. (packages (cons* curl git openssh mosh nss-certs rsync tmux vim %base-packages)) (services (cons* (dbus-service) (gpm-service) (service openssh-service-type (openssh-configuration (password-authentication? #f))) (ntp-service) (wicd-service) (modify-services %base-services (guix-service-type config => (guix-configuration (inherit config) (substitute-urls '("https://berlin.guixsd.org https://mirror.hydra.gnu.org"))))))))

Attachment: check.log

Ludovic Courtès wrote on 6 Apr 2018 10:21

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 30993@debbugs.gnu.org)

Message-ID:877epk3fuy.fsf@gnu.org

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (14 lines)> Since the update to Shepherd 0.4.0, I've found that OpenSSH's sshd is
> killed almost immediately after it starts with signal 15. I confirmed
> the issue started with the Shepherd upgrade by bisecting our Git
> history.
>
> I can reproduce the issue from commit
> b6beda1d6b9093a8493b5c3cde33ed522242c451 (gnu: Add botan.).
>
> One interesting tidbit is that the PID file '/var/run/sshd.pid' is not
> created anymore. And if I create an empty PID file by hand, it is
> removed after trying to start the ssh-daemon service. Also, the sshd
> user's home '/var/run/sshd' does not exist, and is similarly removed if
> it does exist.

Weird. On my laptop /var/run/sshd.pid exists and contains the right

PID. /var/run/sshd does not exist, though.

When I run the config you posted in ‘guix system vm’, ‘ssh-daemon’ is

correctly started and I see a correct ssh.pid and /var/run/sshd exists

as well.

Toggle quote (5 lines)

> I ran the OpenSSH system test `make check-system TESTS=openssh` and it

> failed when it could not find the PID file. It passed on another

> non-GuixSD machine. The failing machine is relatively slow and lacks

> KVM: a ThinkPad x200s.

FWIW on my x86_64 laptop, I’ve run it several times in a row (using

“guix build /gnu/store/…-openssh.drv --check”), and it always succeeds.

Toggle quote (24 lines)> I modified the sshd invocation to print some debug output ('-d -E
> /tmp/sshd.log') and this is what it shows:
>
> ------
> debug1: sshd version OpenSSH_7.6, OpenSSL 1.0.2o  27 Mar 2018
> debug1: private host key #0: ssh-rsa SHA256:REDACTED
> debug1: private host key #1: ssh-dss SHA256:REDACTED
> debug1: private host key #2: ecdsa-sha2-nistp256 SHA256:REDACTED
> debug1: private host key #3: ssh-ed25519 SHA256:REDACTED
> debug1: rexec_argv[0]='/gnu/store/az7vib8gk16fybhshh5xpkljmgxyrs4k-openssh-7.6p1/sbin/sshd'
> debug1: rexec_argv[1]='-D'
> debug1: rexec_argv[2]='-d'
> debug1: rexec_argv[3]='-E'
> debug1: rexec_argv[4]='/tmp/sshd.log'
> debug1: rexec_argv[5]='-f'
> debug1: rexec_argv[6]='/gnu/store/miy7xg5j4fg3mn04mcl27awmcl6s97ss-sshd_config'
> debug1: Set /proc/self/oom_score_adj from 0 to -1000
> debug1: Bind to port 22 on 0.0.0.0.
> Server listening on 0.0.0.0 port 22.
> debug1: Bind to port 22 on ::.
> Server listening on :: port 22.
> Received signal 15; terminating.
> ------

Hmm, where could that SIGTERM come from?  ‘make-kill-destructor’ uses it
when a service is stopped, and otherwise it’s sent when we’re shutting
the system down.  But here?…

Thanks,
Ludo’.

Leo Famulari wrote on 6 Apr 2018 14:41

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 30993@debbugs.gnu.org)

Message-ID:20180406124101.GB1883@jasmine.lan

On Fri, Apr 06, 2018 at 10:21:09AM +0200, Ludovic Courtès wrote:

[...]

Toggle quote (10 lines)> > Server listening on 0.0.0.0 port 22.
> > debug1: Bind to port 22 on ::.
> > Server listening on :: port 22.
> > Received signal 15; terminating.
> > ------
> 
> Hmm, where could that SIGTERM come from?  ‘make-kill-destructor’ uses it
> when a service is stopped, and otherwise it’s sent when we’re shutting
> the system down.  But here?…

Indeed, that is the question. Does anyone have advice for debugging?

I still have this issue and so I'm continuing to use Shepherd 0.3.2.

Ludovic Courtès wrote on 6 Apr 2018 16:32

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87r2nsz9pi.fsf@gnu.org

severity 30993 important

Ludovic Courtès wrote on 6 Apr 2018 16:37

Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 30993@debbugs.gnu.org)

Message-ID:87po3cz9i3.fsf@gnu.org

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (16 lines)> On Fri, Apr 06, 2018 at 10:21:09AM +0200, Ludovic Courtès wrote:
> [...]
>> > Server listening on 0.0.0.0 port 22.
>> > debug1: Bind to port 22 on ::.
>> > Server listening on :: port 22.
>> > Received signal 15; terminating.
>> > ------
>> 
>> Hmm, where could that SIGTERM come from?  ‘make-kill-destructor’ uses it
>> when a service is stopped, and otherwise it’s sent when we’re shutting
>> the system down.  But here?…
>
> Indeed, that is the question. Does anyone have advice for debugging?
>
> I still have this issue and so I'm continuing to use Shepherd 0.3.2.

For you the bug is 100% reproducible with 0.4.0 and never happens with

0.3.2? Even in a ‘guix system vm’?

Ludo’.

Martin Castillo wrote on 1 May 2018 15:13

Recipients:(address . bug-guix@gnu.org)

Message-ID:a61fd87e-8f57-bae7-7747-e4be02161a4d@uni-bremen.de

(resending because I forgot to CC the list)

On 06.04.2018 14:41, Leo Famulari wrote:

Toggle quote (9 lines)

>> Hmm, where could that SIGTERM come from? ‘make-kill-destructor’ uses it

>> when a service is stopped, and otherwise it’s sent when we’re shutting

>> the system down. But here?…

> Indeed, that is the question. Does anyone have advice for debugging?

> I still have this issue and so I'm continuing to use Shepherd 0.3.2.

Maybe one could somehow strace herd, or change the make-kill-destructor

to log every time it is being executed?

I'm not that fluent in guile so maybe someone else could do that?

Ludovic Courtès wrote on 1 May 2018 22:43

Recipients:(name . Martin Castillo)(address . castilma@uni-bremen.de)(address . 30993@debbugs.gnu.org)

Message-ID:87r2mvnm29.fsf@gnu.org

Martin Castillo <castilma@uni-bremen.de> skribis:

Toggle quote (15 lines)> (resending because I forgot to CC the list)
>
> On 06.04.2018 14:41, Leo Famulari wrote:
>>> Hmm, where could that SIGTERM come from?  ‘make-kill-destructor’ uses it
>>> when a service is stopped, and otherwise it’s sent when we’re shutting
>>> the system down.  But here?…
>>
>> Indeed, that is the question. Does anyone have advice for debugging?
>>
>> I still have this issue and so I'm continuing to use Shepherd 0.3.2.
>>
>
> Maybe one could somehow strace herd, or change the make-kill-destructor
> to log every time it is being executed?

‘herd status sshd’ displays the last time sshd was respawned, but the
info ‘herd’ receives actually includes the dates of all the respawns,
not just the last one.  Is that what you’re asking for?

Thanks,
Ludo’.

Martin Castillo wrote on 3 May 2018 17:16

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 30993@debbugs.gnu.org)

Message-ID:b1b51eb6-77f1-0b53-4f18-3a83fe7ef24c@uni-bremen.de

On 01.05.2018 22:43, Ludovic Courtès wrote:

Toggle quote (8 lines)

>> Maybe one could somehow strace herd, or change the make-kill-destructor

>> to log every time it is being executed?

> ‘herd status sshd’ displays the last time sshd was respawned, but the

> info ‘herd’ receives actually includes the dates of all the respawns,

> not just the last one. Is that what you’re asking for?

My idea was that maybe make-kill-destructor is being called from

somewhere else. If this is being

logged, one could rule that out.

Another wild idea would be sshd killing itself for some reason. stracing

sshd would tell us, if that's the case. How would one do that? Does

shepherd provide some debugging functions?

Or does linux provide a way to log all sent signals so one could find

the sending process?

Martin

GPG: 7FDE 7190 2F73 2C50 236E 403D CC13 48F1 E644 08EC

Leo Famulari wrote on 3 May 2018 18:38

Recipients:(name . Martin Castillo)(address . castilma@uni-bremen.de)

Message-ID:20180503163808.GA1019@jasmine.lan

On Thu, May 03, 2018 at 05:16:32PM +0200, Martin Castillo wrote:

Toggle quote (22 lines)> 
> 
> On 01.05.2018 22:43, Ludovic Courtès wrote:
> >> Maybe one could somehow strace herd, or change the make-kill-destructor
> >> to log every time it is being executed?
> > 
> > ‘herd status sshd’ displays the last time sshd was respawned, but the
> > info ‘herd’ receives actually includes the dates of all the respawns,
> > not just the last one.  Is that what you’re asking for?
> > 
> 
> My idea was that maybe make-kill-destructor is being called from
> somewhere else. If this is being
> logged, one could rule that out.
> 
> Another wild idea would be sshd killing itself for some reason. stracing
> sshd would tell us, if that's the case. How would one do that? Does
> shepherd provide some debugging functions?
> 
> Or does linux provide a way to log all sent signals so one could find
> the sending process?

I haven't had time to debug this yet, and Shepherd 0.3 still works.

Since nobody else can reproduce the bug, and since I expect OpenSSH to

be commonly used, I suspect some non-deterministic Guile mis-compilation

or filesystem corruption — the system in question is using ext4.

Martin Castillo wrote on 4 May 2018 04:01

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:FB84BAEB-5F14-45C2-9BD6-8FF8CFA5BAD5@uni-bremen.de

Sorry, I forgot to mention that I have the same problem. But I had it already with shepherd 0.3.

Leo Famulari wrote on 6 May 2018 21:50

Recipients:(name . Martin Castillo)(address . castilma@uni-bremen.de)

Message-ID:20180506195050.GD8038@jasmine.lan

On Fri, May 04, 2018 at 04:01:52AM +0200, Martin Castillo wrote:

Toggle quote (2 lines)

> Sorry, I forgot to mention that I have the same problem. But I had it already with shepherd 0.3.

Interesting. Did it ever work for you on that system?

Martin Castillo wrote on 7 May 2018 21:10

bug#30993: OpenSSH sshd killed by Shepherd 0.4.0

Recipients:(name . Leo Famulari)(address . leo@famulari.name)

Message-ID:fb962e2b-2b18-7adc-ff6d-5fbb0a56c8b4@uni-bremen.de

On 06.05.2018 21:50, Leo Famulari wrote:

Toggle quote (6 lines)> On Fri, May 04, 2018 at 04:01:52AM +0200, Martin Castillo wrote:
>> Sorry,  I forgot to mention that I have the same problem. But I had it already with shepherd 0.3.
> 
> Interesting. Did it ever work for you on that system?
> 
> that system?

Do you mean shepherd 0.3? Yes. And once(or so) with shepherd 0.4.

I reported that here [0]. Some of the mentioned files needed small

changes for the current guix, but ssh works with all of them, strangely.

I attached my current configuration, where I need to start the daemon

manually (herd start ssh-daemon) after each boot.

Martin

[0]: https://lists.gnu.org/archive/html/help-guix/2018-01/msg00112.html

Attachment: cur.scm

Ludovic Courtès wrote on 15 Jun 2018 11:07

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87602kwh7e.fsf@gnu.org

tags 30993 unreproducible

Leo Famulari wrote on 18 Jul 2018 20:29

(no subject)

Recipients:(address . control@debbugs.gnu.org)

Message-ID:20180718182910.GA23198@jasmine.lan

merge 32197 30993

Clément Lassieur wrote on 19 Jul 2018 15:15

Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0

Recipients:

Message-ID:87sh4f5ptn.fsf@lassieur.org

Heya,

Martin Castillo <castilma@uni-bremen.de> writes:

Toggle quote (15 lines)> On 06.05.2018 21:50, Leo Famulari wrote:
>> On Fri, May 04, 2018 at 04:01:52AM +0200, Martin Castillo wrote:
>>> Sorry,  I forgot to mention that I have the same problem. But I had it already with shepherd 0.3.
>> 
>> Interesting. Did it ever work for you on that system?
>> 
>> that system?
> Do you mean shepherd 0.3? Yes. And once(or so) with shepherd 0.4.
>
> I reported that here [0]. Some of the mentioned files needed small
> changes for the current guix, but ssh works with all of them, strangely.
>
> I attached my current configuration, where I need to start the daemon
> manually (herd start ssh-daemon) after each boot.

I don't think you're having the same bug.  Martin can manually start the
daemon, whereas Leo can't.  So Martin seems to have
https://debbugs.gnu.org/cgi/bugreport.cgi?bug=32197,for which a commit
has been pushed by Julien.

Martin, could you please test it?  (You just need to 'guix pull' and try
again.)  Leo, if you confirm my analysis, could you please unmerge the
bugs?

Thanks,
Clément

Clément Lassieur wrote on 19 Jul 2018 16:24

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87pnzj5mms.fsf@lassieur.org

unmerge 30993

Clément Lassieur wrote on 19 Jul 2018 16:26

Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0

Recipients:

Message-ID:87muun5mj0.fsf@lassieur.org

Clément Lassieur <clement@lassieur.org> writes:

Toggle quote (2 lines)

> Leo, if you confirm my analysis, could you please unmerge the bugs?

I did it, because Eric confirmed the fix.

Clément

Leo Famulari wrote on 19 Jul 2018 18:57

Recipients:(name . Clément Lassieur)(address . clement@lassieur.org)

Message-ID:20180719165730.GA8867@jasmine.lan

On Thu, Jul 19, 2018 at 04:26:59PM +0200, Clément Lassieur wrote:

Toggle quote (6 lines)

> Clément Lassieur <clement@lassieur.org> writes:

> > Leo, if you confirm my analysis, could you please unmerge the bugs?

> I did it, because Eric confirmed the fix.

Thanks, sorry for the confusion!

Martin Castillo wrote on 23 Jul 2018 19:08

Recipients:

Message-ID:a5d68301-2219-4e4a-0350-a906e4d4a379@uni-bremen.de

On 19.07.2018 15:15, Clément Lassieur wrote:

Toggle quote (9 lines)

> [...]

> Martin, could you please test it? (You just need to 'guix pull' and try

> again.) Leo, if you confirm my analysis, could you please unmerge the

> bugs?

> Thanks,

> Clément

It still does not work for me.

Attached are my guix version, dmesg|grep shepherd output, config.scm and

my qemu invocation (metal).

I run that system in qemu, but it is installed directly on my harddrive.

Martin

GPG: 7FDE 7190 2F73 2C50 236E 403D CC13 48F1 E644 08EC

Attachment: config.scm

[   11.764507] shepherd[1]: Service root has been started.
[   14.719803] shepherd[1]: starting services...
[   14.722728] shepherd[1]: Service root-file-system has been started.
[   14.725482] shepherd[1]: Service user-file-systems has been started.
[   14.729274] shepherd[1]: Service file-system-/dev/pts has been started.
[   14.732863] shepherd[1]: Service file-system-/dev/shm has been started.
[   14.736110] shepherd[1]: Service file-system-/gnu/store has been started.
[   14.750763] shepherd[1]: Service file-system-/run/systemd has been started.
[   14.757029] shepherd[1]: Service file-system-/run/user has been started.
[   14.760723] shepherd[1]: Service file-system-/sys/fs/cgroup has been started.
[   14.765708] shepherd[1]: Service file-system-/sys/fs/cgroup/elogind has been started.
[   14.776834] shepherd[1]: Service file-system-/sys/fs/cgroup/cpuset has been started.
[   14.790800] shepherd[1]: Service file-system-/sys/fs/cgroup/cpu has been started.
[   14.795139] shepherd[1]: Service file-system-/sys/fs/cgroup/cpuacct has been started.
[   14.810192] shepherd[1]: Service file-system-/sys/fs/cgroup/memory has been started.
[   14.814319] shepherd[1]: Service file-system-/sys/fs/cgroup/devices has been started.
[   14.827923] shepherd[1]: Service file-system-/sys/fs/cgroup/freezer has been started.
[   14.834046] shepherd[1]: Service file-system-/sys/fs/cgroup/blkio has been started.
[   14.838283] shepherd[1]: Service file-system-/sys/fs/cgroup/perf_event has been started.
[   14.841524] shepherd[1]: Service file-systems has been started.
[   14.966786] shepherd[1]: waiting for udevd...
[   15.627793] shepherd[1]: Service udev has been started.
[   15.679916] shepherd[1]: Service urandom-seed has been started.
[   15.684068] shepherd[1]: Service user-processes has been started.
[   15.688369] shepherd[1]: Service host-name has been started.
[   15.719811] shepherd[1]: Service user-homes could not be started.
[   16.737051] shepherd[1]: Service nscd has been started.
[   16.780356] shepherd[1]: Service guix-daemon has been started.

guix (GNU Guix) 264967c883d32606c18b378f717c303e7490c942
Copyright (C) 2018 the Guix authors
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

# runs qemu as mcd but with read and write access to sda

mount |egrep -q 'sd(a|b)3'  && echo guix-root is maybe mounted. Aborting. && exit

set -v
sudo sh -c 'exec sudo -u mcd -C 6 sh -c "
  exec qemu-system-x86_64 -m 1800 -smp 2 -enable-kvm \
		-net nic,model=virtio \
		-net user,hostfwd=tcp::5560-:2222,hostfwd=tcp::5559-:22 \
		-add-fd fd=5,set=2,opaque=rdwr:$(readlink -f /dev/disk/by-id/ata-Hitachi_HDT721010SLA360_STF6L7MS20ALEK) \
		-drive file=/dev/fdset/2,index=0,media=disk" \
		5<>/dev/disk/by-id/ata-Hitachi_HDT721010SLA360_STF6L7MS20ALEK '

Attachment: signature.asc

Ludovic Courtès wrote on 28 Aug 2018 11:47

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 30993@debbugs.gnu.org)

Message-ID:874lfen7q7.fsf@gnu.org

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (8 lines)

> Since the update to Shepherd 0.4.0, I've found that OpenSSH's sshd is

> killed almost immediately after it starts with signal 15. I confirmed

> the issue started with the Shepherd upgrade by bisecting our Git

> history.

> I can reproduce the issue from commit

> b6beda1d6b9093a8493b5c3cde33ed522242c451 (gnu: Add botan.).

I’m “happy” to say that I experienced this on a server—not having ssh

access to a remote server is fairly annoying, I definitely sympathize…

What I see is this:

Toggle snippet (15 lines)

Aug 6 07:56:40 localhost shepherd[1]: Service loopback has been started.

[...]

Aug 6 07:56:51 localhost sshd[606]: Server listening on 0.0.0.0 port 22.

[...]

Aug 6 07:57:05 localhost shepherd[1]: Service ssh-daemon could not be started.

[...]

Aug 6 07:57:46 localhost vmunix: [ 10.049791] random: ssh-keygen: uninitialized urandom read (32 bytes read)

(Note that the last message was pulled from /dev/kmsg by syslogd, but

it’s about an event that actually occurred before the first message.)

It waited for ~15 seconds, although ‘%pid-file-timeout’ in (shepherd

service) is only 5 seconds.

The SIGTERM you were seeing very likely comes from this bit:

Toggle snippet (9 lines)

(match (read-pid-file pid-file

#:max-delay pid-file-timeout)

(#f

(catch-system-error (kill pid SIGTERM))

#f)

((? integer? pid)

pid))

On another machine:

Toggle snippet (8 lines)

Aug 28 09:10:49 localhost sshd[435]: Server listening on 0.0.0.0 port 22.

Aug 28 09:10:49 localhost sshd[435]: Server listening on :: port 22.

[...]

Aug 28 09:10:50 localhost shepherd[1]: Service ssh-daemon has been started.

I wonder if this has to do with IPv6 (the failing case lacks the “Server

listening on ::” line), or if it’s just sshd occasionally taking a long

time to start.

Is it easily reproducible for you? Did you eventually gather more

details?

Thanks,

Ludo’.

Ludovic Courtès wrote on 7 Nov 2018 22:34

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87r2fwshbc.fsf@gnu.org

merge 30993 33299

Ludovic Courtès wrote on 7 Nov 2018 22:36

Re: bug#33299: shepherd: Service ssh-daemon could not be started.

Recipients:(name . swedebugia)(address . swedebugia@riseup.net)

Message-ID:87muqksh7i.fsf@gnu.org

Hello,

swedebugia <swedebugia@riseup.net> skribis:

Toggle quote (5 lines)

> This morning I started my GuixSD VM as usual.

> Openssh server was not running even though it was enabled and should

> have been respawned. Hmm.

This seems to be the same issue as described in

https://issues.guix.info/issue/30993 (I’ve now merged both).

It’s a serious problem…

Thanks for reporting it,

Ludo’.

Taegil Bae wrote on 17 Nov 2018 10:46

issue: ssh-daemon could not be started

Recipients:(address . 30993@debbugs.gnu.org)

Message-ID:CA+k_ch+bxxA5Gm1_ZThn117quO31MfsQxU=UACXjbZOoLUDvvg@mail.gmail.com

Hi,

I have experienced this issue on a slow machine (Thinkpad T60). By

placing avahi-daemon after ssh-daemon, I fixed this issue. I added

ssh-daemon into the requirement of avahi-shepherd-service, and

reconfigured the system.

On the machine, openssh and dropbear both had this issue. I checked

that this trick works for the two ssh server. On another machine(Qemu

VM, faster), openssh only had the trouble. Through several

reconfiguring the system, it was fixed with the original

configuration. I think that it was because the reconfigurations

reordered the services.

Taegil

Ludovic Courtès wrote on 19 Nov 2018 22:22

Recipients:(name . Taegil Bae)(address . esrevinu@gmail.com)(address . 30993@debbugs.gnu.org)

Message-ID:87efbgvk3o.fsf@gnu.org

Hello,

Taegil Bae <esrevinu@gmail.com> skribis:

Toggle quote (5 lines)

> I have experienced this issue on a slow machine (Thinkpad T60). By

> placing avahi-daemon after ssh-daemon, I fixed this issue. I added

> ssh-daemon into the requirement of avahi-shepherd-service, and

> reconfigured the system.

This is very surprising. Are you sure this is fully reproducible?

How would you explain this?

Thank you,

Ludo’.

Taegil Bae wrote on 20 Nov 2018 02:33

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 30993@debbugs.gnu.org)

Message-ID:abf5965c-8cf9-fade-5539-30e054fc6c3d@gmail.com

Hello,

On 11/20/18 6:22 AM, Ludovic Courtès wrote:

Toggle quote (9 lines)

> Taegil Bae <esrevinu@gmail.com> skribis:

>> I have experienced this issue on a slow machine (Thinkpad T60). By

>> placing avahi-daemon after ssh-daemon, I fixed this issue. I added

>> ssh-daemon into the requirement of avahi-shepherd-service, and

>> reconfigured the system.

> This is very surprising. Are you sure this is fully reproducible?

> How would you explain this?

At least in my machine it seems reproducible. I just reproduced that: 
reconfigured the system without my modification of avahi-daemon, checked 
ssh-daemon not started, reconfigured the system again with the 
modification, and then checked ssh-daemon started.

I am not a professional. But I guess that avahi-daemon manipulates 
network things such as the host name, and ssh-daemon waits for that to 
be completed. Look at this failing case:

Nov 20 09:37:57 localhost avahi-daemon[344]: Found user 'avahi' (UID 
985) and group 'avahi' (GID 973).
Nov 20 09:37:59 localhost avahi-daemon[344]: Successfully dropped root 
privileges.
Nov 20 09:38:00 localhost avahi-daemon[344]: avahi-daemon 0.7 starting up.
Nov 20 09:38:18 localhost shepherd[1]: Service avahi-daemon has been 
started.
Nov 20 09:38:01 localhost avahi-daemon[344]: WARNING: No NSS support for 
mDNS detected, consider installing nss-mdns!
Nov 20 09:38:05 localhost avahi-daemon[344]: Successfully called chroot().
Nov 20 09:38:12 localhost avahi-daemon[344]: Successfully dropped 
remaining capabilities.
Nov 20 09:38:32 localhost shepherd[1]: Service ssh-daemon could not be 
started.
Nov 20 09:38:15 localhost avahi-daemon[344]: Loading service file 
/services/sftp-ssh.service.
Nov 20 09:38:17 localhost avahi-daemon[344]: Loading service file 
/services/ssh.service.
Nov 20 09:38:19 localhost avahi-daemon[344]: Network interface 
enumeration completed.
Nov 20 09:38:22 localhost avahi-daemon[344]: Server startup complete. 
Host name is gravity.local. Local service cookie is 4157419020.
Nov 20 09:38:29 localhost avahi-daemon[344]: Service "gravity" 
(/services/ssh.service) successfully established.
Nov 20 09:38:32 localhost avahi-daemon[344]: Service "gravity" 
(/services/sftp-ssh.service) successfully established.
Nov 20 09:38:36 localhost avahi-daemon[344]: write() failed while 
writing return value to pipe: Broken pipe
Nov 20 09:39:12 localhost avahi-daemon[344]: Joining mDNS multicast 
group on interface wls3.IPv6 with address fe80::4c7d:9233:7845:eb88.
Nov 20 09:39:12 localhost avahi-daemon[344]: New relevant interface 
wls3.IPv6 for mDNS.
Nov 20 09:39:12 localhost avahi-daemon[344]: Registering new address 
record for fe80::4c7d:9233:7845:eb88 on wls3.*.
Nov 20 09:39:12 localhost avahi-daemon[344]: Joining mDNS multicast 
group on interface wls3.IPv4 with address 192.168.42.242.
Nov 20 09:39:12 localhost avahi-daemon[344]: New relevant interface 
wls3.IPv4 for mDNS.
Nov 20 09:39:12 localhost avahi-daemon[344]: Registering new address 
record for 192.168.42.242 on wls3.IPv4.

Regards,

Taegil

Ludovic Courtès wrote on 9 Mar 2019 19:35

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87tvgb520i.fsf@gnu.org

merge 30993 34580

Ludovic Courtès wrote on 14 May 2019 15:33

Re: bug#30993: OpenSSH sshd killed by Shepherd 0.4.0

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 30993@debbugs.gnu.org)

Message-ID:878sv9yxbs.fsf@gnu.org

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (6 lines)

> One interesting tidbit is that the PID file '/var/run/sshd.pid' is not

> created anymore. And if I create an empty PID file by hand, it is

> removed after trying to start the ssh-daemon service. Also, the sshd

> user's home '/var/run/sshd' does not exist, and is similarly removed if

> it does exist.

There are reasons to believe that this issue is fixed by the Shepherd 0.6.1:

https://issues.guix.info/issue/35550

Could you check somehow if the bug shows up again?

Thanks,

Ludo’.

Leo Famulari wrote on 14 May 2019 20:21

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 30993-done@debbugs.gnu.org)

Message-ID:20190514182106.GA1446@jasmine.lan

On Tue, May 14, 2019 at 03:33:59PM +0200, Ludovic Courtès wrote:

Toggle quote (6 lines)

> There are reasons to believe that this issue is fixed by the Shepherd 0.6.1:

> https://issues.guix.info/issue/35550

> Could you check somehow if the bug shows up again?

The bug disappeared for me a couple of reboots after reinstalling the

Guix System on my affected machine. That reinstallation provided

Shepherd 0.5, although 0.5 was also tested unsuccessfully before

reinstalling.

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

So... I think the bug was probably some kind of race condition or TOCTOU

problem that went away with a less fragmented or full filesystem (I was

really pushing the limits in that regard).

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

that was the culprit.

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

Closed

Brant Gardner wrote on 20 Sep 2019 18:19

Archived problem report bug#34580 (Service ssh-daemon could no t be started)

Recipients:(address . control@debbugs.gnu.org)

Message-ID:1ee347ea-f340-4d61-8bfb-53a58139aa2d@www.fastmail.com

unarchive 34580

Brant Gardner

Attachment: file

Ludovic Courtès wrote on 26 Sep 2019 22:28

control message for bug #30993

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87r242ls3n.fsf@gnu.org

merge 30993 37309

quit

Ludovic Courtès wrote on 26 Sep 2019 22:29

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87pnjmls36.fsf@gnu.org

retitle 30993 'ssh-daemon' fails to start

quit

maxim.cournoyer wrote on 18 Aug 2020 06:08

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87wo1wppdk.fsf@hurd.i-did-not-set--mail-host-address--so-tickle-me

tags 30993 fixed
close 30993 
quit

Christopher Lemmer Webber wrote on 27 Nov 2020 23:57

unarchive 37309

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87y2imjtm0.fsf@dustycloud.org

unarchive 37309

Your comment

This issue is archived.

To comment on this conversation send an email to 30993@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it

mumi current 30993

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

is:open	open issues
is:done	closed issues
submitter:<who>	search issue submitter
author:<who>	search by message author
date:yesterday..now	search by issue date
mdate:3m..2d	search by message date