Race condition on opening a tunnel

[carlfriedrich]

I think I stumbled upon a race condition when trying to open a tunnel from a bad internet connection (Wi-Fi on german trains is really annoying 🙈). When the SSH connection drops immediatly after it is established, sish starts the forwarding anyway, blocking the alias name for further connections.

For a usual working tunnel I see the following in the sish log:

2025/04/04 - 16:00:34 | Accepted SSH connection for: 185.104.138.67:62632
2025/04/04 - 16:00:35 | Login attempt: 185.104.138.67:62632, user tim key: ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOX5V9bKQY0bn/BCusYQ4KuzIw8ZieKqYv7Uoc7S0iog
2025/04/04 - 16:00:35 | HTTP forwarding started: http://mytunnel.sish.myserver.de -> /tmp/185.104.138.67_62632_4431231408965 for client: 185.104.138.67:62632
2025/04/04 - 16:00:35 | HTTPS forwarding started: https://mytunnel.sish.myserver.de -> /tmp/185.104.138.67_62632_4431231408965 for client: 185.104.138.67:62632
2025/04/04 - 16:00:42 | Closed SSH connection for: 185.104.138.67:62632 user: tim

In the error case I see the following:

2025/04/04 - 16:01:02 | Accepted SSH connection for: 185.104.138.67:62686
2025/04/04 - 16:01:05 | Login attempt: 185.104.138.67:62686, user tim key: ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIOX5V9bKQY0bn/BCusYQ4KuzIw8ZieKqYv7Uoc7S0iog
2025/04/04 - 16:01:05 | Closed SSH connection for: 185.104.138.67:62686 user: tim
2025/04/04 - 16:01:06 | HTTP forwarding started: http://mytunnel.sish.myserver.de -> /tmp/185.104.138.67_62686_4431133630303 for client: 185.104.138.67:62686
2025/04/04 - 16:01:06 | HTTPS forwarding started: http://mytunnel.sish.myserver.de -> /tmp/185.104.138.67_62686_4431133630303 for client: 185.104.138.67:62686
2025/04/04 - 16:01:06 | Error replying to port forwarding request: EOF

I haven't looked into the code yet, but from what I see the connection is closed before the forwarding is started. Probably there is a check missing whether the connection is still active before actually starting the forwarding.

The tunnel does not work, of course, because the SSH connection is closed. The domain http://mytunnel.sish.myserver.de is blocked for subsequent requests, though.

I was able to reproduce this after seeing it for the first time on the same bad Wi-Fi connection. In both cases the sish docker container stopped a few minutes afterwards without any useful message in the log. I had to manually restart sish.

@antoniomika As I said, I haven't looked into the code, yet, but maybe you already have an idea why this is happening and how to prevent it?

And as a sidenote: I think it might be useful to have a message in the log as soon as a forwarding is stopped.

[carlfriedrich]

Maybe this is related to #328.

[carlfriedrich]

@antoniomika Did you notice this issue and can you say anything about it?

[antoniomika]

Sorry @carlfriedrich! Circling back here.

Do you have specific repro steps for this? I've attempted to look into it in the past and haven't been able to figure it out.

I do think it's possible for something like this to occur since SSH sends forward requests through a channel, so they aren't established right on connection. I do find it odd that they aren't removed right as the connection is closed given there's a log line for it. I would've thought the issue was sish didn't know the connection closed due to the network timeout not being met.

My guess is these are related to the issue you listed above.

[carlfriedrich]

@antoniomika Thanks for your reply! I haven't been able to reproduce this on a usual stable network.

In a first step could we add a debug message as soon as a forwarding is stopped?