This has me puzzled to no end, hopefully someone can clarify.
I have a local server, LOCALSRV, and remote server (Ubuntu 20.04), REMOTESRV.
On the local server, I've established a reverse ssh tunnel, forwarding LOCALSRV port 5555 to REMOTESRV port 7777, by running autossh
at boot, using a passwordless key authentication:
/opt/sbin/autossh -M 51501 -f \
my_tnl_user@REMOTESRV \
-p 51500 -NT -i /path/to/mykey_id_rsa \
-o "ExitOnForwardFailure=yes" \
-o "ServerAliveInterval 60" -o "ServerAliveCountMax 3" \
-R 7777:127.0.0.1:5555
When I started this last night, everything worked fine; so sudo journalctl -t sshd
on REMOTESRV from that time (around 18 o'clock) reports:
Nov 18 18:09:51 REMOTESRV sshd[29058]: Disconnected from user my_tnl_user LOCALSRV_PUB_IP port 48109
Nov 18 18:09:51 REMOTESRV sshd[28990]: pam_unix(sshd:session): session closed for user my_tnl_user
Nov 18 18:17:49 REMOTESRV sshd[29127]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 50641 ssh2: R>
Nov 18 18:17:49 REMOTESRV sshd[29127]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
Good enough; so now I check everything this morning, and nothing works. The autossh
log on the LOCALSRV was not too informative (I had forgotten to use AUTOSSH_DEBUG=1
):
...
2021/11/18 18:17:49 autossh[13408]: starting ssh (count 1)
2021/11/18 18:17:49 autossh[13408]: ssh child pid is 13409
2021/11/18 22:58:06 autossh[13408]: timeout polling to accept read connection
2021/11/18 22:58:06 autossh[13408]: port down, restarting ssh
2021/11/18 22:58:06 autossh[13408]: starting ssh (count 2)
2021/11/18 22:58:06 autossh[13408]: ssh child pid is 17556
2021/11/18 22:58:07 autossh[13408]: ssh exited with error status 255; restarting ssh
2021/11/18 22:58:07 autossh[13408]: starting ssh (count 3)
2021/11/18 22:58:07 autossh[13408]: ssh child pid is 17557
2021/11/18 22:58:07 autossh[13408]: ssh exited with error status 255; restarting ssh
# this then repeats all the way to end, with differing PIDs:
2021/11/18 22:58:07 autossh[13408]: starting ssh (count 4)
2021/11/18 22:58:07 autossh[13408]: ssh child pid is 17559
2021/11/18 22:58:07 autossh[13408]: ssh exited with error status 255; restarting ssh
...
So, I cannot tell, what might have happened at 22:58 o'clock, to have caused "timeout polling to accept read connection" and "port down, restarting ssh" (which are the only occurences of those strings in that log).
Thus, I looked into sudo journalctl -t sshd
on REMOTESRV (linebreak added for legibility):
...
Nov 18 18:17:49 REMOTESRV sshd[29127]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 50641 ssh2: R>
Nov 18 18:17:49 REMOTESRV sshd[29127]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
Nov 18 22:58:06 REMOTESRV sshd[29920]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 57231 ssh2: R>
Nov 18 22:58:06 REMOTESRV sshd[29920]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
Nov 18 22:58:07 REMOTESRV sshd[30003]: error: bind [127.0.0.1]:51501: Address already in use
Nov 18 22:58:07 REMOTESRV sshd[30003]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 51501
Nov 18 22:58:07 REMOTESRV sshd[30003]: error: bind [127.0.0.1]:7777: Address already in use
Nov 18 22:58:07 REMOTESRV sshd[30003]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 7777
Nov 18 22:58:07 REMOTESRV sshd[29920]: pam_unix(sshd:session): session closed for user my_tnl_user
Nov 18 22:58:07 REMOTESRV sshd[30004]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 57232 ssh2: R>
Nov 18 22:58:07 REMOTESRV sshd[30004]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
...
Right, so here we can see "bind: Address already in use" and "error: channel_setup_fwd_listener_tcpip: cannot listen to port" - and I cannot tell why this happened; closest I found is this:
- https://askubuntu.com/questions/903866/multiple-port-forwarding-gives-bind-address-already-in-use
- https://serverfault.com/questions/1014401/ssh-reverse-port-forward-disconnects-each-10-minutes
In my case, this behavior was caused by simultaneous connections to the server of two computers with the same autossh monitoring port (-M).
If the client reconnect before the connection has terminated on the server, you can end up in a situation where the new ssh connection is live, but has no port forwardings. In order to avoid that, you need to use the
ExitOnForwardFailure
keyword on the client side.
Eh, but I already use that, don't I?
Now, here's the tricky part - right after the above log sudo journalctl -t sshd
snippet on REMOTESRV, this repeats for a while:
...
Nov 18 22:58:07 REMOTESRV sshd[30004]: pam_unix(sshd:session): session closed for user my_tnl_user
Nov 18 22:58:07 REMOTESRV sshd[30066]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 57233 ssh2: R>
Nov 18 22:58:07 REMOTESRV sshd[30066]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
Nov 18 22:58:08 REMOTESRV sshd[30127]: error: bind [127.0.0.1]:51501: Address already in use
Nov 18 22:58:08 REMOTESRV sshd[30127]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 51501
Nov 18 22:58:08 REMOTESRV sshd[30127]: error: bind [127.0.0.1]:7777: Address already in use
Nov 18 22:58:08 REMOTESRV sshd[30127]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 7777
...
... and then, it ends like this (spaces added for legibility):
...
Nov 18 22:59:11 REMOTESRV sshd[30500]: pam_unix(sshd:session): session closed for user my_tnl_user
Nov 18 23:00:01 REMOTESRV sshd[30562]: Accepted publickey for my_tnl_user from LOCALSRV_PUB_IP port 57263 ssh2: R>
Nov 18 23:00:01 REMOTESRV sshd[30562]: pam_unix(sshd:session): session opened for user my_tnl_user by (uid=0)
Nov 18 23:00:01 REMOTESRV sshd[30623]: error: bind [127.0.0.1]:51501: Address already in use
Nov 18 23:00:01 REMOTESRV sshd[30623]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 51501
Nov 18 23:00:01 REMOTESRV sshd[30623]: error: bind [127.0.0.1]:7777: Address already in use
Nov 18 23:00:01 REMOTESRV sshd[30623]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 7777
Nov 18 23:00:01 REMOTESRV sshd[30562]: pam_unix(sshd:session): session closed for user my_tnl_user
Nov 18 23:01:13 REMOTESRV sshd[30624]: Failed password for my_tnl_user from LOCALSRV_PUB_IP port 57286 ssh2
Nov 18 23:01:13 REMOTESRV sshd[30624]: Failed password for my_tnl_user from LOCALSRV_PUB_IP port 57286 ssh2
Nov 18 23:01:13 REMOTESRV sshd[30624]: Connection closed by authenticating user my_tnl_user LOCALSRV_PUB_IP port >
Nov 18 23:02:51 REMOTESRV sshd[30627]: Failed password for my_tnl_user from LOCALSRV_PUB_IP port 57294 ssh2
Nov 18 23:02:51 REMOTESRV sshd[30627]: Failed password for my_tnl_user from LOCALSRV_PUB_IP port 57294 ssh2
Nov 18 23:02:52 REMOTESRV sshd[30627]: Connection closed by authenticating user my_tnl_user LOCALSRV_PUB_IP port >
...
So, suddenly, REMOTESRV started asking for ssh password for the user my_tnl_user - even if originally it has been set up as passwordless key athentication login, which did work fine?!
What the hell is going on?
So here's the thing: I don't really have access to LOCALSRV, however autossh
still runs there, and attempts to connect to the server.
I did restart REMOTESRV this morning (Nov 19), and autossh
on LOCALSRV did attempt to connect to it multiple times already - but it fails everytime, because it tries to use the key authentication, and yet REMOTESRV keeps asking for a password, and failing the authentication.
Can someone explain what happened? And is there anything I can do, - and if so, what - on REMOTESRV, so as to have it accept the key authentication from LOCALSRV again, without asking for password - so that I have a working ssh reverse tunnel again?!