No VPN connectivity after domain/api restart

[sdaberdaku]

Describe the bug

I am self-hosting Firezone (latest version) on Kubernetes using the community Helm Chart, and I noticed that, if the domain/api Pods are restarted, VPN connectivity is lost. The DNS names are correctly resolved (I checked with nslookup from terminal) but then the actual requests to the resources time out. Connectivity is restored once I manually restart the gateway Pods.

To Reproduce

In Kubernetes, try killing the domain and api Pods and the connections to the resources under VPN will time out.

Expected behavior

The gateway pod should have a healthcheck that detects that the domain/api resources have restarted and force the gateway Pod to restart. Or the gateway pod should have a more resilient re-connection mechanism.

Screenshots / Logs

I did not see any error logs in the gateway pod.

Platform (please complete the following information)

• _Component (i.e. macOS client / Linux client / Gateway / Admin portal): Gateway
• _Firezone Version (e.g. 1.0.0 or N/A): Gateway 1.3.1; Firezone API: ghcr.io/firezone/api:235c2f3b161348c0bbf6fa21747e11c17f5ca7f5; Firezone Domain: ghcr.io/firezone/domain:235c2f3b161348c0bbf6fa21747e11c17f5ca7f5
• _OS and version: (e.g. Ubuntu 22.04 or N/A): Tested with latest gui-client 1.3.2 on Linux Mint 21.2 and Windows 11
• _Deployment method: (e.g. Docker / Systemd / App Store or N/A): Helm Chart on Kubernetes (AWS EKS)

[sdaberdaku]

If anyone else is facing a similar issue, for the moment I kind of mitigated it by increasing the number of replicas of the API and Domain components and applied podAntiAffinities so that the replicas are guaranteed to run in different nodes and availability zones. This way it is more unlikely that the Gateway Pods loose the connectivity completely.

[thomaseizinger]

The gateway pod should have a healthcheck that detects that the domain/api resources have restarted and force the gateway Pod to restart. Or the gateway pod should have a more resilient re-connection mechanism.

The connection to the portal is designed to not affect the data plane and we have integration tests to check that.

Can you post some logs of client and gateways? Ideally with RUST_LOG=debug,wire::api=trace.

[sdaberdaku]

It took me some time to sanitize the logs from personal information (IPs, passwords, etc.) but I finally made it.

Here are the gateway logs:
firezone-gateway-nocolor.log
And here are the client logs:
connlib.2024-09-10-17-24-36.log
connlib.2024-09-10-17-22-15.log

Hope this helps!

[thomaseizinger]

And here are the client logs:
connlib.2024-09-10-17-24-36.log
connlib.2024-09-10-17-22-15.log

Unfortunately, those seem to be the logs of the GUI, not the IPC service.

[thomaseizinger]

Here are the gateway logs:
firezone-gateway-nocolor.log

2024-09-10T17:38:10.826909Z DEBUG handle_input{from=x.x.x.x:3478 tid=DCFF5F89AD85162E7F186707 method=channel bind class=error response rtt=2.259626ms}: snownet::allocation: Request failed, re-authenticating error="Stale Nonce"
2024-09-10T17:38:10.827071Z DEBUG handle_input{from=x.x.x.x:3478 tid=739F3E67ABF2CF509264DACE method=channel bind class=error response rtt=2.293111ms}: snownet::allocation: Request failed, re-authenticating error="Stale Nonce"
2024-09-10T17:38:10.828714Z WARN handle_input{from=x.x.x.x:3478 tid=806AF275D85FEEB25DDA353C method=channel bind class=error response rtt=1.822374ms}: snownet::allocation: Invalid credentials, refusing to re-authenticate channel bind
2024-09-10T17:38:10.828818Z DEBUG snownet::node: Packet was a STUN message but not accepted
2024-09-10T17:38:10.911027Z INFO connection{cid=5dd08d79-37fb-4fce-84c6-9f3b4b1ab806}: str0m::ice_::agent: Local candidate to discard Candidate(relay=x.x.x.x:55035/udp prio=37748479)
2024-09-10T17:38:10.911135Z ERROR snownet::node: Disconnecting from relay; authentication error rid=14f57985-8321-43dd-a300-76d1fa4e04e9

This seems to be where the issue starts. For some reason, the relay credentials we have locally don't match anymore. Are you restart the relay too as part of restarting the API? They should be restarted in sequence, not in parallel, otherwise the API can't detect that the relay restarted and push new credentials to the clients.

[thomaseizinger]

2024-09-10T17:36:59.580053Z TRACE wire::api::recv: {"event":"init","ref":null,"topic":"gateway","payload":{"config":{"ipv4_masquerade_enabled":true,"ipv6_masquerade_enabled":true},"interface":{"ipv6":"fd00:2021:1111::17:68ef","ipv4":"100.81.88.43"},"relays":[{"id":"14f57985-8321-43dd-a300-76d1fa4e04e9","type":"turn","addr":"x.x.x.x:3478","username":"1727199419:tQvGIkcyomo9USZrs4cDLQ","password":"xxx","expires_at":1727199419}]}}
2024-09-10T17:36:59.580123Z INFO snownet::node: Skipping known TURN server rid=14f57985-8321-43dd-a300-76d1fa4e04e9 address=V4(x.x.x.x:3478)

I think what might be happening here is that we skip TURN server because it is still the same ID but the credentials might have changed. We might need an additional check here.

I am surprised this doesn't come up in our production setup though.

The relevant code is here:

firezone/rust/connlib/snownet/src/node.rs

Lines 519 to 522 in b657c18

	if self.allocations.contains_key(rid) {
	tracing::info!(%rid, address = ?server, "Skipping known TURN server");
	continue;
	}

Instead of just checking for the ID being present, we should also check whether we have the same credentials. Shouldn't be too difficult! Are you willing to send a PR? :)

[sdaberdaku]

And here are the client logs:
connlib.2024-09-10-17-24-36.log
connlib.2024-09-10-17-22-15.log

Unfortunately, those seem to be the logs of the GUI, not the IPC service.

Hello @thomaseizinger, thanks for the quick response!

My bad, when you said client I thought you meant the gui client.

Regarding the relay, I did not restart it, I just restarted the api and domain Pods. But I think the relay restarted on its own. I see the Pod has 1 restart and the old logs show this (the time is consistent with when I did the experiment):
2024-09-10T19:36:36+02:00 at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:283:12 2024-09-10T19:36:36+02:00 17: std::thread::local::LocalKey<T>::with 2024-09-10T19:36:36+02:00 at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:260:9 2024-09-10T19:36:36+02:00 18: tokio::runtime::context::set_scheduler 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context.rs:180:17 2024-09-10T19:36:36+02:00 19: tokio::runtime::scheduler::current_thread::CoreGuard::enter 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:751:27 2024-09-10T19:36:36+02:00 20: tokio::runtime::scheduler::current_thread::CoreGuard::block_on 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:660:19 2024-09-10T19:36:36+02:00 21: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}} 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:180:28 2024-09-10T19:36:36+02:00 22: tokio::runtime::context::runtime::enter_runtime 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context/runtime.rs:65:16 2024-09-10T19:36:36+02:00 23: tokio::runtime::scheduler::current_thread::CurrentThread::block_on 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:168:9 2024-09-10T19:36:36+02:00 24: tokio::runtime::runtime::Runtime::block_on_inner 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/runtime.rs:361:47 2024-09-10T19:36:36+02:00 25: tokio::runtime::runtime::Runtime::block_on 2024-09-10T19:36:36+02:00 at /cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/runtime.rs:335:13 2024-09-10T19:36:36+02:00 26: firezone_relay::main 2024-09-10T19:36:36+02:00 at /project/relay/src/main.rs:170:5 2024-09-10T19:36:36+02:00 27: core::ops::function::FnOnce::call_once 2024-09-10T19:36:36+02:00 at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 2024-09-10T19:36:36+02:00 28: std::sys_common::backtrace::__rust_begin_short_backtrace 2024-09-10T19:36:36+02:00 at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:155:18 2024-09-10T19:36:36+02:00 29: main

Regarding the PR, sorry but I have zero experience with Rust.
If I can help in any other way please let me know. We could also set up a meeting if you want and I could demonstrate this live.

Best regards,

Sebastian

[thomaseizinger]

That looks like a stacktrace. Can you upload the entire relay log please?

[sdaberdaku]

Here is the whole log (which ends with the stack trace I showed earlier):
firezone-relay.log

[thomaseizinger]

Thanks for uploading that!

First, I would highly recommend to lower the log level. Running the relay with TRACE enabled will impact the performance. Second, the relay exited because the reconnect backoff expired which suggests that the portal was down for longer than 15 minutes. Due to the restart, the credentials changed but we didn't detect that on the client. That is the bug I mentioned above and needs to be fixed.

I'd recommend to check your setup though why the portal was unreachable for 15 minutes. We only tolerate a certain amount of network partitioning.

[sdaberdaku]

Thanks for the feedback!
I will set the log level to info.

I do not think the portal was unreachable for 15 minutes though, the Pods were up and running within a couple of minutes tops. I deleted them manually and was monitoring the EKS cluster the whole time. I have not configured the re-connection backoff, is there a way to increase it, maybe with some environment variable?

[thomaseizinger]

I do not think the portal was unreachable for 15 minutes though

The logs suggest otherwise although it is hard to say because they only cover about 3 minutes. If you can reproduce the problem with INFO log, we will have less spam and can look at what actually happened.

I have not configured the re-connection backoff, is there a way to increase it, maybe with some environment variable?

It is currently not configurable and I wouldn't recommend to set it to anything longer than 15 minutes. The portal is what authorizes connection flows and thus having too long of a network partition is a risk.