Can't ssh from router to LInux server?

RouterOS General
1

I have an Ubuntu server on my LAN and if I issue the command

/system ssh 192.168.4.5

I just get a “Welcome back!” message without even a login prompt. I can ssh from the router to other devices. I can also ssh to 192.168.4.5 if I use Putty. On the Ubuntu server the ssh log just shows I connected and disconnected before authenticating.

I tried adding the “ssh” topic to the Logging configuration, but it either doesn’t show anything or shows a constant scroll of hex messages.

How do I diagnose this?

2

Hi there!

Can you try the following?

/system ssh user=<some non root user on the linux server> 192.168.4.5
3

Yes, same result. But my login is the same on the router and Ubuntu, and the Ubuntu logs show my username connecting and disconnecting before auth. So I don’t think it makes a difference.

4

Ok. That was worth a shot.

On the linux server - can you get the SSH entries?

sudo journalctl -xr -u ssh
5

Hmm, seems like it’s not telling us anything different than the router seems to be disconnecting:

david@zoidberg:~$ sudo journalctl -xr -u ssh
Jan 25 13:53:08 zoidberg sshd[274495]: Disconnected from authenticating user david 192.168.4.1 port 35024 [preau>
Jan 25 13:53:08 zoidberg sshd[274495]: Received disconnect from 192.168.4.1 port 35024:11:  [preauth]
6

Likely your ubuntu runs recent OpenSSH version, which deprecates use of ssh-rsa algorithm to exchange keys whike ROS doesn’t support newer ones.

So on the server, add PubkeyAcceptedAlgorithms +ssh-rsa to /etc/ssh/sshd_config …

7

OK, that’s the general “something went wrong somewhere” type of messages.

Could be a number of things:

  • If your server is a bit dated and the client a lot more recent, it may disconnect as it doesn’t find something in common (but usually it says so)
  • Are you trying key authentication? If so, is your private key set with permissions 0400? (it should also complain in the logs)
  • Your server refuses RSA key authentication
  • And more …

On the server, set in /etc/ssh/sshd_config[/]

# …
LogLevel DEBUG
#LogLevel DEBUG2
#LogLevel DEBUG3

And restart the daemon, you should have a lot more info on what goes wrong.

8

Ah, good idea…but doesn’t make a difference. Yes, I restarted sshd server. And I forced Putty to connect using rsa, and it worked. So the server does support rsa keys now.

9

Ah, thanks. Logs don’t seem to show much of interest. The server is Ubuntu 23.04, so pretty new. Log is;

Jan 25 14:19:05 zoidberg sshd[274825]: Connection from 192.168.4.1 port 35060 on 192.168.4.5 port 22 rdomain ""
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: Remote protocol version 2.0, remote software version ROSSSH
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: compat_banner: no match: ROSSSH
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: permanently_set_uid: 127/65534 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: kex: client->server cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: kex: server->client cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: rekey out after 4294967296 blocks [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: rekey in after 4294967296 blocks [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: KEX done [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: userauth-request for user david service ssh-connection method none [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: attempt 0 failures 0 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: PAM: initializing for "david"
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: PAM: setting PAM_RHOST to "192.168.4.1"
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: PAM: setting PAM_TTY to "ssh"
Jan 25 14:19:05 zoidberg sshd[274825]: Received disconnect from 192.168.4.1 port 35060:11:  [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: Disconnected from authenticating user david 192.168.4.1 port 35060 [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: do_cleanup [preauth]
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: monitor_read_log: child log fd closed
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: do_cleanup
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: PAM: cleanup
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: Killing privsep child 274826
Jan 25 14:19:05 zoidberg sshd[274825]: debug1: audit_event: unhandled event 12
10

ok … can you set the loglevel to DEBUG2, restart the daemon and try another connection?

Stupid question: clocks synchronized on both devices?

11

Yep, clocks are in sync. Both systems are set via ntp from us.pool.ntp.org I think.

Jan 25 15:28:49 zoidberg sshd[275510]: Connection from 192.168.4.1 port 35208 on 192.168.4.5 port 22 rdomain ""
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: Remote protocol version 2.0, remote software version ROSSSH
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: compat_banner: no match: ROSSSH
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: fd 4 setting O_NONBLOCK
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: Network child is on pid 275511
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: permanently_set_uid: 127/65534 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: local server KEXINIT proposal [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,kex-strict-s-v00@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: compression ctos: none,zlib@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: compression stoc: none,zlib@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: languages ctos:  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: languages stoc:  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: first_kex_follows 0  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: reserved 0  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: peer client KEXINIT proposal [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: KEX algorithms: curve25519-sha256,diffie-hellman-group-exchange-sha256,ext-info-c [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: host key algorithms: ssh-ed25519,rsa-sha2-256 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ciphers ctos: aes192-ctr,aes256-ctr,aes256-gcm@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ciphers stoc: aes192-ctr,aes256-ctr,aes256-gcm@openssh.com [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: compression ctos: none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: compression stoc: none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: languages ctos:  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: languages stoc:  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: first_kex_follows 0  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: reserved 0  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: kex: client->server cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: kex: server->client cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: monitor_read: 6 used once, disabling now
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ssh_set_newkeys: mode 1 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: rekey out after 4294967296 blocks [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: ssh_set_newkeys: mode 0 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: rekey in after 4294967296 blocks [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: KEX done [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: userauth-request for user david service ssh-connection method none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: attempt 0 failures 0 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: parse_server_config_depth: config reprocess config len 3323
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: parse_server_config_depth: config /etc/ssh/sshd_config.d/allow-rsa.conf len 29
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: monitor_read: 8 used once, disabling now
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: input_userauth_request: setting up authctxt for david [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: input_userauth_request: try method none [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: PAM: initializing for "david"
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: PAM: setting PAM_RHOST to "192.168.4.1"
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: PAM: setting PAM_TTY to "ssh"
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: monitor_read: 100 used once, disabling now
Jan 25 15:28:49 zoidberg sshd[275510]: debug2: monitor_read: 4 used once, disabling now
Jan 25 15:28:49 zoidberg sshd[275510]: Received disconnect from 192.168.4.1 port 35208:11:  [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: Disconnected from authenticating user david 192.168.4.1 port 35208 [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: do_cleanup [preauth]
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: monitor_read_log: child log fd closed
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: do_cleanup
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: PAM: cleanup
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: Killing privsep child 275511
Jan 25 15:28:49 zoidberg sshd[275510]: debug1: audit_event: unhandled event 12
12

Hmmm …

Jan 25 15:28:49 zoidberg sshd[275510]: debug2: input_userauth_request: try method none [preauth]

After this one it should try another method - do you have “PasswordAuthentication yes” in /etc/ssh/sshd_config ?

13

Yep, and I log in using passwords all the time on this Ubuntu box. It’s weird that I can’t ssh from the router to anything. I’ve tried other routers I have connected via vpn, even spun up a virtual server on DigitalOcean and always the same thing.

14

OK. Let’s try LogLevel at DEBUG3. I will have a look tomorrow morning.

That is weird.

15

Thanks! Now this is a crazy level of detail. It occurs to me that it might be better to find the router’s ssh log from its end, since the server log seems to indicate the router is just disconnecting of its own accord. I don’t think that’s accessible in ROS though.

There is a line in the below log just before the router disconnects that says “userauth_finish: failure partial=0 next methods=“publickey,password” [preauth]” and I guess that’s the issue? Perhaps ROS isn’t saying it supports one of those auth methods? Which seems very odd. This is ROS 7.13…I’ll try upgrading to 7.13.3 and see if it makes a difference.

Jan 25 16:04:53 zoidberg sshd[275927]: Connection from 192.168.4.1 port 35274 on 192.168.4.5 port 22 rdomain ""
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: Remote protocol version 2.0, remote software version ROSSSH
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: compat_banner: no match: ROSSSH
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: fd 4 setting O_NONBLOCK
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: Network child is on pid 275928
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: preauth child monitor started
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: privsep user:group 127:65534 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: permanently_set_uid: 127/65534 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 20 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 20 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: SSH2_MSG_KEXINIT received [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: local server KEXINIT proposal [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,kex-strict-s-v00@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: compression ctos: none,zlib@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: compression stoc: none,zlib@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: languages ctos:  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: languages stoc:  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: first_kex_follows 0  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: reserved 0  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: peer client KEXINIT proposal [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: KEX algorithms: curve25519-sha256,diffie-hellman-group-exchange-sha256,ext-info-c [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: host key algorithms: ssh-ed25519,rsa-sha2-256 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ciphers ctos: aes192-ctr,aes256-ctr,aes256-gcm@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ciphers stoc: aes192-ctr,aes256-ctr,aes256-gcm@openssh.com [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: compression ctos: none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: compression stoc: none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: languages ctos:  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: languages stoc:  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: first_kex_follows 0  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: reserved 0  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: kex: client->server cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: kex: server->client cipher: aes192-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 30 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_sshkey_sign: entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 6 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive_expect: entering, type 7 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: monitor_read: checking request 6
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_answer_sign: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_answer_sign: ssh-ed25519 KEX signature len=83
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 7
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: monitor_read: 6 used once, disabling now
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 31 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 21 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ssh_set_newkeys: mode 1 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: rekey out after 4294967296 blocks [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 7 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 21 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: ssh_set_newkeys: mode 0 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: rekey in after 4294967296 blocks [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: KEX done [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 5 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 6 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 50 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: userauth-request for user david service ssh-connection method none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: attempt 0 failures 0 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_getpwnamallow: entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 8 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive_expect: entering, type 9 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: monitor_read: checking request 8
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_answer_pwnamallow: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: parse_server_config_depth: config reprocess config len 3323
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: parse_server_config_depth: config /etc/ssh/sshd_config.d/allow-rsa.conf len 29
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 9
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: monitor_read: 8 used once, disabling now
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: input_userauth_request: setting up authctxt for david [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_start_pam entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 100 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_inform_authserv: entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_send: entering, type 4 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: input_userauth_request: try method none [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: ensure_minimum_time_since: elapsed 0.942ms, delaying 5.693ms (requested 6.635ms) [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: monitor_read: checking request 100
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: PAM: initializing for "david"
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: PAM: setting PAM_RHOST to "192.168.4.1"
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: PAM: setting PAM_TTY to "ssh"
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: monitor_read: 100 used once, disabling now
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: monitor_read: checking request 4
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_answer_authserv: service=ssh-connection, style=, role=
Jan 25 16:04:53 zoidberg sshd[275927]: debug2: monitor_read: 4 used once, disabling now
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: send packet: type 51 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: receive packet: type 1 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: Received disconnect from 192.168.4.1 port 35274:11:  [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: Disconnected from authenticating user david 192.168.4.1 port 35274 [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: do_cleanup [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: PAM: sshpam_thread_cleanup entering [preauth]
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: monitor_read_log: child log fd closed
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: mm_request_receive: entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: do_cleanup
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: PAM: cleanup
Jan 25 16:04:53 zoidberg sshd[275927]: debug3: PAM: sshpam_thread_cleanup entering
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: Killing privsep child 275928
Jan 25 16:04:53 zoidberg sshd[275927]: debug1: audit_event: unhandled event 12
16

Yes and we now know that the server is not sending the client packing but the client disconnects (type 1) after a message “USERAUTH FAILURE” (type 51) (https://www.ietf.org/rfc/rfc4250.txt)

The stanza to debug SSH is the following. Be warned: that’s verbose.

/system/logging/add topics=ssh,debug action=memory
17

Ahhh this is very interesting. If I am reading this log right, the router is only trying to do public key auth and then disconnects when it realizes it can’t (because it doesn’t have a key). It doesn’t try to fall back to password auth.

11:04:45 ssh,debug agreed on: curve25519-sha256,ssh-ed25519,aes192-ctr,aes192-ctr,hmac-sha2-256,hmac-sha2-256,none,none,
11:04:45 ssh,debug packet process: userauth failure
 11:04:45 ssh,debug available auth methods: publickey,password
 11:04:45 ssh,debug selected auth: publickey
 11:04:45 ssh,debug publickey authorization phase1, keys:1
 11:04:45 ssh,debug code 0x0300000b closing..
 11:04:45 ssh,debug,packet packet create: disconnect

I thought that this might be a bug due to /ip/ssh always-allow-password-login=no so I tried setting it to yes but it doesn’t make a difference.

It appears to be a bug that the Mikrotik ssh client doesn’t let you use password auth?

18

Seems so. I will try tomorrow.

BTW, what’s your version?

19

When I started the thread I was running 7.13. Now on 7.13.3, no change.

20

Here is my defaults for /ip/ssh (7.13.2):. always-allow-password-login is already “no”.

           forwarding-enabled: no
  always-allow-password-login: no
                strong-crypto: no
            allow-none-crypto: no
                host-key-size: 2048
                host-key-type: rsa

Changing “strong-crypto” doesn’t prevent me from ssh-ing out. Adding a public to my user on the MT doesn’t either. Adding a private and a public keys to the user neither. I am a bit miffed at the problem you are having.

I keep digging …