[SOLVED] No SSH access before TTY login

blochl · 2018-10-20 18:20:28

Hi,

I run a basic Arch VM, nothing fancy, user network, single network interface. sshd and dhcpcd are enabled.
The problem: once I start the VM, there is no SSH access:

On the first attempt (even long time after VM startup) it says:

ssh_exchange_identification: read: Connection reset by peer

On all subsequent attempts:

ssh_exchange_identification: Connection closed by remote host

But once I log in via TTY on the VM GUI (spicy), even if I log out afterwards, SSH access works perfectly!

I saw some related posts, like this and this , but I don't have an encrypted home directory, and IP is not a problem, because I run only a single VM, with port forwarding. Moreover, this exact setup worked perfectly a year ago. This problem began just lately.

What do you think can cause it?

Last edited by blochl (2018-10-21 16:59:52)

x33a · 2018-10-21 08:06:19

Post the output of

systemctl status sshd.service

and

journalctl -u sshd

from the host. If that doesn't help, you might want to run sshd with the -d option.

blochl · 2018-10-21 09:39:51

Thanks for the reply.

The output of the first command is:

● sshd.service - OpenSSH Daemon
   Loaded: loaded (/usr/lib/systemd/system/sshd.service; disabled; vendor prese>
   Active: inactive (dead)

... Which makes sense, because the sshd is not enabled on the host (nor was it before, when this setup worked). Conseqently, the log has no entries.

But what do you think host sshd has to do with it? I tried starting it - same result.

seth · 2018-10-21 11:45:46

I assume x33a confused the location of the ssh server.

How do you authenticate to the server?
Did you try to create a new user and login as that?
Did you check the sshd log? (Possibly raising "LogLevel DEBUG")

blochl · 2018-10-21 13:20:42

seth wrote:

I assume x33a confused the location of the ssh server.

That makes sense, sorry.

The output of

systemctl status sshd.service

On the guest is:

● sshd.service - OpenSSH Daemon
   Loaded: loaded (/usr/lib/systemd/system/sshd.service; enabled; vendor preset: disabled)
   Active: active (running) since Sun 2018-10-21 14:12:52 CEST; 3min 0s ago
 Main PID: 310 (sshd)
    Tasks: 1 (limit: 4719)
   Memory: 7.9M
   CGroup: /system.slice/sshd.service
           └─310 /usr/bin/sshd -D

Oct 21 14:12:52 pvm systemd[1]: Started OpenSSH Daemon.
Oct 21 14:13:35 pvm sshd[310]: Server listening on 0.0.0.0 port 22.
Oct 21 14:13:35 pvm sshd[310]: Server listening on :: port 22.
Oct 21 14:13:51 pvm sshd[392]: Accepted password for pvm-user from 10.0.2.2 port 59684 ssh2
Oct 21 14:13:51 pvm sshd[392]: pam_unix(sshd:session): session opened for user pvm-user by (uid=0)

And of

journalctl -u sshd

is:

-- Reboot --
Oct 21 14:12:52 pvm systemd[1]: Started OpenSSH Daemon.
Oct 21 14:13:35 pvm sshd[310]: Server listening on 0.0.0.0 port 22.
Oct 21 14:13:35 pvm sshd[310]: Server listening on :: port 22.
Oct 21 14:13:51 pvm sshd[392]: Accepted password for pvm-user from 10.0.2.2 port 59684 ssh2
Oct 21 14:13:51 pvm sshd[392]: pam_unix(sshd:session): session opened for user pvm-user by (uid=0)

This is after several failed attempts to ssh before graphical login, and then one successful attempt after the graphical login.

seth wrote:

How do you authenticate to the server?

Regular password. The only change i made to the default /etc/ssh/sshd_config is:

s/#X11Forwarding no/X11Forwarding yes/

seth wrote:

Did you try to create a new user and login as that?

Just created a second user, in the exact same way as I created the first one:

useradd -m -G wheel -s /bin/bash user2
passwd user2

Exactly the same result. Moreover - logging in as one user on the graphical login enables both the users to ssh fine afterwards.

seth wrote:

Did you check the sshd log? (Possibly raising "LogLevel DEBUG")

I've upped the LogLevel (thanks for the advice!) and the output is the following. Looks like it only ever sees the successful attempt - after the graphical login, as before that there was an unsuccessful attempt. Moreover, judging by the timestamps, it only starts listening to port 22 after the graphical login, despite the OpenSSH Daemon was started on VM startup!! 0_0

-- Reboot --
Oct 21 15:01:26 pvm systemd[1]: Started OpenSSH Daemon.
Oct 21 15:03:24 pvm sshd[324]: debug1: Set /proc/self/oom_score_adj from 0 to -1000
Oct 21 15:03:24 pvm sshd[324]: debug1: Bind to port 22 on 0.0.0.0.
Oct 21 15:03:24 pvm sshd[324]: Server listening on 0.0.0.0 port 22.
Oct 21 15:03:24 pvm sshd[324]: debug1: Bind to port 22 on ::.
Oct 21 15:03:24 pvm sshd[324]: Server listening on :: port 22.
Oct 21 15:03:31 pvm sshd[324]: debug1: Forked child 400.
Oct 21 15:03:31 pvm sshd[400]: debug1: Set /proc/self/oom_score_adj to 0
Oct 21 15:03:31 pvm sshd[400]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
Oct 21 15:03:31 pvm sshd[400]: debug1: inetd sockets after dupping: 5, 5
Oct 21 15:03:31 pvm sshd[400]: Connection from 10.0.2.2 port 60106 on 10.0.2.15 port 22
Oct 21 15:03:31 pvm sshd[400]: debug1: Client protocol version 2.0; client software version OpenSSH_7.9
Oct 21 15:03:31 pvm sshd[400]: debug1: match: OpenSSH_7.9 pat OpenSSH* compat 0x04000000
Oct 21 15:03:31 pvm sshd[400]: debug1: Local version string SSH-2.0-OpenSSH_7.9
Oct 21 15:03:31 pvm sshd[400]: debug1: permanently_set_uid: 65534/65534 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: SSH2_MSG_KEXINIT received [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: rekey after 134217728 blocks [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: rekey after 134217728 blocks [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: KEX done [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: userauth-request for user pvm-user service ssh-connection method none [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: attempt 0 failures 0 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: PAM: initializing for "pvm-user"
Oct 21 15:03:31 pvm sshd[400]: debug1: PAM: setting PAM_RHOST to "10.0.2.2"
Oct 21 15:03:31 pvm sshd[400]: debug1: PAM: setting PAM_TTY to "ssh"
Oct 21 15:03:31 pvm sshd[400]: debug1: userauth-request for user pvm-user service ssh-connection method publickey [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: attempt 1 failures 0 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: userauth_pubkey: test pkalg ecdsa-sha2-nistp521 pkblob ECDSA SHA256:iLnS9qaMjd+0LnUEp0QjoVZT70SEPHr3clynpaj71rs [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Oct 21 15:03:31 pvm sshd[400]: debug1: trying public key file /home/pvm-user/.ssh/authorized_keys
Oct 21 15:03:31 pvm sshd[400]: debug1: Could not open authorized keys '/home/pvm-user/.ssh/authorized_keys': No such file or directory
Oct 21 15:03:31 pvm sshd[400]: debug1: restore_uid: 0/0
Oct 21 15:03:31 pvm sshd[400]: Failed publickey for pvm-user from 10.0.2.2 port 60106 ssh2: ECDSA SHA256:iLnS9qaMjd+0LnUEp0QjoVZT70SEPHr3clynpaj71rs
Oct 21 15:03:31 pvm sshd[400]: debug1: userauth-request for user pvm-user service ssh-connection method publickey [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: attempt 2 failures 1 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: userauth_pubkey: test pkalg ssh-ed25519 pkblob ED25519 SHA256:pp+c6M7Zx2XnAo6NHDoR2Bi/2HleKzoKiHu27NJ8FT4 [preauth]
Oct 21 15:03:31 pvm sshd[400]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Oct 21 15:03:31 pvm sshd[400]: debug1: trying public key file /home/pvm-user/.ssh/authorized_keys
Oct 21 15:03:31 pvm sshd[400]: debug1: Could not open authorized keys '/home/pvm-user/.ssh/authorized_keys': No such file or directory
Oct 21 15:03:31 pvm sshd[400]: debug1: restore_uid: 0/0
Oct 21 15:03:31 pvm sshd[400]: Failed publickey for pvm-user from 10.0.2.2 port 60106 ssh2: ED25519 SHA256:pp+c6M7Zx2XnAo6NHDoR2Bi/2HleKzoKiHu27NJ8FT4
Oct 21 15:03:34 pvm sshd[400]: debug1: userauth-request for user pvm-user service ssh-connection method password [preauth]
Oct 21 15:03:34 pvm sshd[400]: debug1: attempt 3 failures 2 [preauth]
Oct 21 15:03:34 pvm sshd[400]: debug1: PAM: password authentication accepted for pvm-user
Oct 21 15:03:34 pvm sshd[400]: debug1: do_pam_account: called
Oct 21 15:03:34 pvm sshd[400]: Accepted password for pvm-user from 10.0.2.2 port 60106 ssh2
Oct 21 15:03:34 pvm sshd[400]: debug1: monitor_child_preauth: pvm-user has been authenticated by privileged process
Oct 21 15:03:34 pvm sshd[400]: debug1: monitor_read_log: child log fd closed
Oct 21 15:03:34 pvm sshd[400]: debug1: PAM: establishing credentials
Oct 21 15:03:34 pvm sshd[400]: pam_unix(sshd:session): session opened for user pvm-user by (uid=0)
Oct 21 15:03:34 pvm sshd[400]: User child is on pid 409
Oct 21 15:03:34 pvm sshd[400]: debug1: session_new: session 0

seth · 2018-10-21 14:16:46

Wild guess: https://www.archlinux.org/packages/extr … 4/haveged/ ?

blochl · 2018-10-21 16:59:13

seth wrote:

Wild guess: https://www.archlinux.org/packages/extr … 4/haveged/ ?

Genius! Thank you so much, seth!!!
It did the trick!

The funny thing is that I was playing with haveged just a few days ago, in another context...

I wonder though: why sshd needs entropy on each startup? I was under the impression that it needs to generate the keys once - upon installation...

seth · 2018-10-21 19:22:01

I'd assume for session keys.

blochl · 2018-10-22 06:31:20

seth wrote:

I'd assume for session keys.

Yeah, that makes sense. Thanks again - your previous answer made my day.

mobiusloop · 2018-11-21 18:01:45

seth wrote:

Wild guess: https://www.archlinux.org/packages/extr … 4/haveged/ ?

Confirming that this solved it for me as well, thanks for the heads up.
For anyone else struggling, I also needed to install polkit for haveged to work

$ sudo pacman -S polkit

and then:

$ sudo systemctl enable haveged

Thanks for the tip!

Edits: too much fun with iOS autocorrect.

Last edited by mobiusloop (2018-11-21 18:07:04)

dslink · 2019-04-12 10:51:49

Thanks, I was having the same issue in more or less the same setup, a headless KVM. Totally forgot about the entropy issue

Arch Linux

#1 2018-10-20 18:20:28

[SOLVED] No SSH access before TTY login

#2 2018-10-21 08:06:19

Re: [SOLVED] No SSH access before TTY login

#3 2018-10-21 09:39:51

Re: [SOLVED] No SSH access before TTY login

#4 2018-10-21 11:45:46

Re: [SOLVED] No SSH access before TTY login

#5 2018-10-21 13:20:42

Re: [SOLVED] No SSH access before TTY login

#6 2018-10-21 14:16:46

Re: [SOLVED] No SSH access before TTY login

#7 2018-10-21 16:59:13

Re: [SOLVED] No SSH access before TTY login

#8 2018-10-21 19:22:01

Re: [SOLVED] No SSH access before TTY login

#9 2018-10-22 06:31:20

Re: [SOLVED] No SSH access before TTY login

#10 2018-11-21 18:01:45

Re: [SOLVED] No SSH access before TTY login

#11 2019-04-12 10:51:49

Re: [SOLVED] No SSH access before TTY login

Board footer