bug#30622: "Service ssh-daemon could not be started." in desktop VM image

bug#30622: "Service ssh-daemon could not be started." in desktop VM image

[George myglc2 Clemmer]

[-- Attachment #1: Type: text/plain, Size: 1794 bytes --]

sshd fails to start in a desktop config (destop03.scm, attached)

The shepherd.log contains (full log attached) ...

g1@g1 ~/bug/sshtoXFCE/log$ grep could shepherd.log
2018-02-26 18:07:47 Service user-homes could not be started.
2018-02-26 18:07:48 Service term-auto could not be started.
2018-02-26 18:07:58 Service ssh-daemon could not be started.

I attempted to start it manually ...

root@desktop03 /gnu/store# sshd -D -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
sshd re-exec requires execution with an absolute path

root@desktop03 /gnu/store# sshd -d -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
sshd re-exec requires execution with an absolute path

root@desktop03 /gnu/store# cat /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
# Generated by 'openssh-service'.
Port 22
PermitRootLogin yes
PermitEmptyPasswords no
PasswordAuthentication yes
PubkeyAuthentication yes
X11Forwarding yes
PidFile /var/run/sshd.pid
ChallengeResponseAuthentication no
UsePAM yes
PrintLastLog yes
AuthorizedKeysFile  .ssh/authorized_keys .ssh/authorized_keys2 /etc/ssh/authorized_keys.d/%u
Subsystem	sftp	internal-sftp
root@desktop03 /gnu/store# 

The vm was created by ...

guix system vm-image -M 4 -c 4 --image-size=5GB \
/home/g1/www/vm/vms/desktop03/desktop03.scm

... and run by ...

sudo qemu-system-x86_64 -name desktop03 -net \
tap,ifname=desktop03,script=/home/g1/www/vm/qemu-ifup,downscript=/home/g1/www/vm/qemu-ifdn \
-net nic,model=virtio,macaddr=DE:AD:BE:EF:3A:8E -enable-kvm -m 5120 -k \
en-us -vga qxl -spice addr=127.0.0.1,port=3001,disable-ticketing -device \
virtio-serial -chardev spicevmc,id=vdagent,debug=0,name=vdagent -device \
virtserialport,chardev=vdagent,name=com.redhat.spice.0 -daemonize \
/home/g1/www/vm/vms/desktop03/vm.img

TIA - George


[-- Attachment #2: desktop03.scm --]
[-- Type: application/octet-stream, Size: 1554 bytes --]

;;; desktop desktop03 config
(use-modules (gnu))
(use-modules (gnu system nss))
(use-service-modules ssh) ; openssh-service-type
(use-service-modules spice)
(use-service-modules desktop)
(use-service-modules networking) ; dhcp-client-service
(use-package-modules
 base                  ; glibc-utf8-locales
 certs                 ; nss-certs
 emacs
 gnome                 ; gvfs
 linux                 ; mdadm
 screen
 ssh                   ; openssh mosh
 xorg
 )
(operating-system
  (host-name "desktop03")
  (timezone "America/New_York")
  (locale "en_US.utf8")
  (bootloader (grub-configuration (target "/dev/sda")))
  (file-systems (cons (file-system
			(device "g1sd")
			(title 'label)
			(mount-point "/")
			(type "ext4"))
		      %base-file-systems))
  (users (cons*
	  (user-account
	   (name "g1")
	   (group "users")
	   (supplementary-groups '("wheel" "netdev"))
	   (home-directory "/home/g1"))
	  %base-user-accounts))
  (packages
   (cons*
    emacs-no-x-toolkit
    emacs-guix
    gvfs              ;for user mounts
    nss-certs         ;for HTTPS access
    openssh
    screen
    xauth
    %base-packages))
  (services (cons*
	     (service openssh-service-type
		      (openssh-configuration
		       (x11-forwarding? #t)
		       (permit-root-login #t)
		       (authorized-keys
			`(
			  ("g1" ,(local-file "glc.pub"))
			  ("al" ,(local-file "glc.pub"))
			  ("root" ,(local-file "glc.pub"))))))
	     (spice-vdagent-service)
	     (xfce-desktop-service)
	     %desktop-services))
  (name-service-switch %mdns-host-lookup-nss))

[-- Attachment #3: shepherd.log --]
[-- Type: application/octet-stream, Size: 3324 bytes --]

2018-02-26 18:07:46 Service root has been started.
2018-02-26 18:07:46 starting services...
2018-02-26 18:07:46 Service root-file-system has been started.
2018-02-26 18:07:46 Service user-file-systems has been started.
2018-02-26 18:07:46 Service file-system-/dev/pts has been started.
2018-02-26 18:07:46 Service file-system-/dev/shm has been started.
2018-02-26 18:07:46 Service file-system-/gnu/store has been started.
2018-02-26 18:07:46 Service file-system-/run/systemd has been started.
2018-02-26 18:07:46 Service file-system-/run/user has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/elogind has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/cpuset has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/cpu has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/cpuacct has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/memory has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/devices has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/freezer has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/blkio has been started.
2018-02-26 18:07:46 Service file-system-/sys/fs/cgroup/perf_event has been started.
2018-02-26 18:07:46 Service file-systems has been started.
2018-02-26 18:07:46 waiting for udevd...
2018-02-26 18:07:47 Service udev has been started.
2018-02-26 18:07:47 Service urandom-seed has been started.
2018-02-26 18:07:47 Service user-processes has been started.
2018-02-26 18:07:47 Service host-name has been started.
2018-02-26 18:07:47 Service user-homes could not be started.
2018-02-26 18:07:48 Service nscd has been started.
2018-02-26 18:07:48 Service guix-daemon has been started.
2018-02-26 18:07:48 Service syslogd has been started.
2018-02-26 18:07:48 Service loopback has been started.
2018-02-26 18:07:48 Service term-tty6 has been started.
2018-02-26 18:07:48 Service term-tty5 has been started.
2018-02-26 18:07:48 Service term-tty4 has been started.
2018-02-26 18:07:48 Service term-tty3 has been started.
2018-02-26 18:07:48 Service term-tty2 has been started.
2018-02-26 18:07:48 Service term-tty1 has been started.
2018-02-26 18:07:48 Service term-auto could not be started.
2018-02-26 18:07:48 Service console-font-tty1 has been started.
2018-02-26 18:07:48 Service console-font-tty2 has been started.
2018-02-26 18:07:48 Service console-font-tty3 has been started.
2018-02-26 18:07:48 Service console-font-tty4 has been started.
2018-02-26 18:07:48 Service console-font-tty5 has been started.
2018-02-26 18:07:48 Service console-font-tty6 has been started.
2018-02-26 18:07:50 Service dbus-system has been started.
2018-02-26 18:07:52 Service wpa-supplicant has been started.
2018-02-26 18:07:52 Service networking has been started.
2018-02-26 18:07:52 Service ntpd has been started.
2018-02-26 18:07:52 Service elogind has been started.
2018-02-26 18:07:52 Service upower-daemon has been started.
2018-02-26 18:07:53 Service avahi-daemon has been started.
2018-02-26 18:07:53 Service xorg-server has been started.
2018-02-26 18:07:53 Service spice-vdagentd has been started.
2018-02-26 18:07:58 Service ssh-daemon could not be started.

bug#30622: "Service ssh-daemon could not be started." in desktop VM image

[Danny Milosavljevic]

> root@desktop03 /gnu/store# sshd -d -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
> sshd re-exec requires execution with an absolute path

Try

$(which sshd) -d -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config

bug#30622: "Service ssh-daemon could not be started." in desktop VM image

[George myglc2 Clemmer]

On 02/26/2018 at 23:58 Danny Milosavljevic writes:

>> root@desktop03 /gnu/store# sshd -d -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
>> sshd re-exec requires execution with an absolute path
>
> Try
>
> $(which sshd) -d -f
> /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config

OOOOOH! DUH! Thanks ...

root@desktop03 /var/log# $(which sshd) -d -f /gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-sshd_config
debug1: sshd version OpenSSH_7.6, OpenSSL 1.0.2n  7 Dec 2017
debug1: private host key #0: ssh-rsa SHA256:4Y2/l5rho7puE5FUHwQ93/ky02ekOyb4aeelkBh6z3U
debug1: private host key #1: ssh-dss SHA256:y+dCJmm1qe8X8fFJ258dQfCH4QMsXGCek2YbKcvawB8
debug1: private host key #2: ecdsa-sha2-nistp256 SHA256:gp64wMW/h9GJpt8BvsxwuJWwBrI3DqO4JZUeknffgvU
debug1: private host key #3: ssh-ed25519 SHA256:ZJzqmZe0yLcK79Ob5Y3IZhggFHZ6npJ2JuuruqopXGM
debug1: rexec_argv[0]='/run/current-system/profile/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-f'
debug1: rexec_argv[3]='/gnu/store/ky9d1r3kj7yv6sbf8cjp23ym95lc5kss-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.
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from fe80::1ccf:c589:7e5f:a21f%eth0 port 52505 on fe80::3a50:30cc:3431:3d8d%eth0 port 22
debug1: Client protocol version 2.0; client software version OpenSSH_7.6
debug1: match: OpenSSH_7.6 pat OpenSSH* compat 0x04000000
debug1: Local version string SSH-2.0-OpenSSH_7.6
debug1: permanently_set_uid: 993/978 [preauth]
debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
debug1: kex: client->server cipher: aes128-ctr MAC: umac-64-etm@openssh.com compression: none [preauth]
debug1: kex: server->client cipher: aes128-ctr MAC: umac-64-etm@openssh.com compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug1: rekey after 4294967296 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: rekey after 4294967296 blocks [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user g1 service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug1: PAM: initializing for "g1"
debug1: PAM: setting PAM_RHOST to "fe80::1ccf:c589:7e5f:a21f%eth0"
debug1: PAM: setting PAM_TTY to "ssh"
debug1: userauth-request for user g1 service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: userauth_pubkey: test whether pkalg/pkblob are acceptable for RSA SHA256:RAXP4+5SU3UN09NL+QwkQmAsLIoDa8Wq6Bi61DzUScY [preauth]
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /home/g1/.ssh/authorized_keys
debug1: Could not open authorized keys '/home/g1/.ssh/authorized_keys': No such file or directory
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /home/g1/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/g1/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /etc/ssh/authorized_keys.d/g1
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /etc/ssh/authorized_keys.d/g1, line 1 RSA SHA256:RAXP4+5SU3UN09NL+QwkQmAsLIoDa8Wq6Bi61DzUScY
debug1: restore_uid: 0/0
Postponed publickey for g1 from fe80::1ccf:c589:7e5f:a21f%eth0 port 52505 ssh2 [preauth]
debug1: userauth-request for user g1 service ssh-connection method publickey [preauth]
debug1: attempt 2 failures 0 [preauth]
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /home/g1/.ssh/authorized_keys
debug1: Could not open authorized keys '/home/g1/.ssh/authorized_keys': No such file or directory
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /home/g1/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/g1/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/998 (e=0/0)
debug1: trying public key file /etc/ssh/authorized_keys.d/g1
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /etc/ssh/authorized_keys.d/g1, line 1 RSA SHA256:RAXP4+5SU3UN09NL+QwkQmAsLIoDa8Wq6Bi61DzUScY
debug1: restore_uid: 0/0
debug1: do_pam_account: called
Accepted publickey for g1 from fe80::1ccf:c589:7e5f:a21f%eth0 port 52505 ssh2: RSA SHA256:RAXP4+5SU3UN09NL+QwkQmAsLIoDa8Wq6Bi61DzUScY
debug1: monitor_child_preauth: g1 has been authenticated by privileged process
debug1: monitor_read_log: child log fd closed
debug1: PAM: establishing credentials
User child is on pid 576
debug1: PAM: establishing credentials
debug1: permanently_set_uid: 1000/998
debug1: rekey after 4294967296 blocks
debug1: rekey after 4294967296 blocks
debug1: ssh_packet_set_postauth: called
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch
debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
debug1: server_input_channel_req: channel 0 request x11-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req x11-req
debug1: channel 1: new [X11 inet listener]
debug1: channel 2: new [X11 inet listener]
debug1: server_input_channel_req: channel 0 request pty-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: Allocating pty.
debug1: session_new: session 0
debug1: session_pty_req: session 0 alloc /dev/pts/3
debug1: Ignoring unsupported tty mode opcode 11 (0xb)
debug1: Ignoring unsupported tty mode opcode 17 (0x11)
debug1: server_input_channel_req: channel 0 request env reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req env
debug1: server_input_channel_req: channel 0 request shell reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req shell
Starting session: shell on pts/3 for g1 from fe80::1ccf:c589:7e5f:a21f%eth0 port 52505 id 0
debug1: Setting controlling tty using TIOCSCTTY.

bug#30622: Status: "Service ssh-daemon could not be started." in desktop VM image

[myglc2]

As of guix (GNU Guix) 0.14.0.4032-cfb55 I can't reproduce this so I
suggest it be closed. TIA - George

bug#30622: Status: "Service ssh-daemon could not be started." in desktop VM image

[Ludovic Courtès]

myglc2@gmail.com skribis:

> As of guix (GNU Guix) 0.14.0.4032-cfb55 I can't reproduce this so I
> suggest it be closed. TIA - George

Closing.

(Note: Just email NNN-done@debbugs.gnu.org to close bug NNN.)

Thanks,
Ludo'.

bug#30622: Status: "Service ssh-daemon could not be started." in desktop VM image

[Chris Marusich]

[-- Attachment #1: Type: text/plain, Size: 450 bytes --]

myglc2@gmail.com writes:

> As of guix (GNU Guix) 0.14.0.4032-cfb55 I can't reproduce this so I
> suggest it be closed. TIA - George

Before we close it, could you try reproducing this with both "guix
system vm" and "guix system vm-image"?  I recall that when I tried to
reproduce this problem, I was able to do it with one invocation, but not
the other - I couldn't figure out why, though, so I didn't post here at
the time.

-- 
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#30622: Status: "Service ssh-daemon could not be started." in desktop VM image

[myglc2]

On 04/06/2018 at 02:06 Chris Marusich writes:

> myglc2@gmail.com writes:
>
>> As of guix (GNU Guix) 0.14.0.4032-cfb55 I can't reproduce this so I
>> suggest it be closed. TIA - George
>
> Before we close it, could you try reproducing this with both "guix
> system vm" and "guix system vm-image"?  

Hi Chris, yes it works here both ways. Thanks, George