celzero
Wireguard failing if phone is locked.
If phone is locked for sometime wireguard fails. Have to stop-start rethinkdns or toggle off-on the wireguard config to establish connection. This is occuring frequently but not always.
Notes:
- DNS works fine. Issue only with wireguard.
- Tried with always on vpn toggles on and off.
Rethink does attempt a reconnection to ALL active peers on network changes.
toggle off-on the wireguard config to establish connection.
Can you check if tapping on the "refresh" icon (in the top-right corner of the "Setup WireGuard" UI) works too?
If phone is locked for sometime wireguard fails.
Is there a pattern you spot? For example, if the phone is locked for more than a few hours, or when the phone is low on battery, etc?
This is occuring frequently but not always.
Can you share some logs (adb logcat), if you know how from exactly from the time when WireGuard starts failing? Make sure to turn on "Verbose" logging from Configure -> Settings -> Log Level (and dial it back to "Info" once done).
Also, does it happen with ALL wireguard profiles or just select ones?
I saw this happen to me today. Not sure what caused it, but the first signs are the Proton servers refuse to respond. "Refresh" did not fix the issue.
Kotlin isn't "Refreshing" WireGuard as it should on network changes:
Logs from UPDATE:
10-09 05:33:43.610 28339 29917 D VpnLifecycle: refresh wg config
10-09 05:33:43.610 28339 29917 D VpnLifecycle: selected proxy type: WIREGUARD, with provider as WIREGUARD
# update triggers removing ALL peers and adding NEW or EXISTING ones
10-09 06:18:08.582 28339 32338 I GoLog : I proxy: updating wg wg8/10.2.0.2/32
10-09 06:18:08.583 28339 32338 I GoLog : V wgwg8 UAPI: Updating private key
10-09 06:18:08.583 28339 32338 I GoLog : V wgwg8 UAPI: Removing all peers
10-09 06:18:08.583 28339 32338 I GoLog : V wgwg8 peer(8xx8…fZw8) - Stopping
10-09 06:18:08.584 28339 28881 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential receiver - stopped
10-09 06:18:08.585 28339 8034 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential sender - stopped
10-09 06:18:08.588 28339 32338 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Created
10-09 06:18:08.588 28339 32338 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Adding allowedip
10-09 06:18:08.588 28339 32338 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Updating endpoint
10-09 06:18:08.588 28339 32338 I GoLog : V wgwg8 peer(8xx8…fZw8) - Starting
10-09 06:18:08.588 28339 28881 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential sender - started
10-09 06:18:08.589 28339 28881 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential receiver - started
# this should be followed by a REFRESH, which triggers binding UDP to upstream.
Logs from when REFRESH is triggered as expected (during ADD):
10-09 06:19:20.422 28339 32329 D VpnLifecycle: handle proxy change, proxy: WIREGUARD
10-09 06:19:20.441 28339 32329 I GoLog : D proxy: wg: added addr(10.2.0.2) / v4(true)/v6(false)
10-09 06:19:20.442 28339 32329 I GoLog : V wgwg8 UAPI: Updating private key
...
10-09 06:19:20.443 28339 6562 I GoLog : V wgwg8 Routine: decryption worker 4 - started
10-09 06:19:20.443 28339 6573 I GoLog : V wgwg8 Routine: handshake worker 6 - started
10-09 06:19:20.443 28339 6573 I GoLog : V wgwg8 Routine: handshake worker 4 - started
10-09 06:19:20.444 28339 6573 I GoLog : V wgwg8 Routine: encryption worker 5 - started
...
10-09 06:19:20.444 28339 6562 I GoLog : V wgwg8 Routine: decryption worker 1 - started
10-09 06:19:20.444 28339 6562 I GoLog : V wgwg8 Routine: handshake worker 1 - started
...
10-09 06:19:20.446 28339 6562 I GoLog : V wgwg8 Routine: TUN reader - started
10-09 06:19:20.447 28339 6572 I GoLog : V wgwg8 Routine: event worker - started
...
10-09 06:19:20.447 28339 32329 I GoLog : V wgwg8 UAPI: Removing all peers
...
10-09 06:19:20.448 28339 6572 I GoLog : V wgwg8 Interface up requested
10-09 06:19:20.448 28339 6572 I GoLog : I wg: bind: close; err4? <nil> err6? <nil>
10-09 06:19:20.450 28339 6572 I GoLog : D wg: bind: listen4(34899); no4? false err? <nil>
10-09 06:19:20.451 28339 6572 I GoLog : D wg: bind: listen6(34899); busy? false no6? false err? <nil>
10-09 06:19:20.451 28339 6572 I GoLog : I wg: bind: opened port(34899) for v4? true v6? true
10-09 06:19:20.451 28339 6572 I GoLog : V wgwg8 UDP bind has been updated
10-09 06:19:20.452 28339 32329 I GoLog : D wg: bind: peek4: fd(139)
10-09 06:19:20.456 28339 32329 I GoLog : D wg: bind: peek6: fd(2146)
10-09 06:19:20.453 28339 6572 I GoLog : V wgwg8 Routine: receive incoming makeReceiveFn - started
10-09 06:19:20.453 28339 6562 I GoLog : V wgwg8 Routine: receive incoming makeReceiveFn - started
10-09 06:19:20.460 28339 32329 I GoLog : D proxy: wg: new wg8 / bound? true; addrs([10.2.0.2/32]) mtu(1280) / v4(true) v6(false)
...
10-09 06:19:20.449 28339 32329 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Created
10-09 06:19:20.449 28339 32329 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Adding allowedip
10-09 06:19:20.449 28339 32329 I GoLog : V wgwg8 peer(8xx8…fZw8) - UAPI: Updating endpoint
10-09 06:19:20.449 28339 32329 I GoLog : V wgwg8 peer(8xx8…fZw8) - Starting
10-09 06:19:20.450 28339 6573 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential sender - started
10-09 06:19:20.450 28339 6562 I GoLog : V wgwg8 peer(8xx8…fZw8) - Routine: sequential receiver - started
...
10-09 06:19:20.451 28339 6572 I GoLog : V wgwg8 Interface state was Down, requested Up, now Up
...
10-09 06:19:20.460 28339 32329 I GoLog : I proxy: added wg8/wg/10.2.0.2/32
Sorry, not familiar with logcat. I couldn't sense any specific pattern. Not battery specific. It is happening in random. Refresh did work rarely, but mostly have to stop and start wireguard or rethinkdns.
mostly have to stop and start wireguard or rethinkdns
Thanks. I believe I saw the same bug (in fact, I see it happen fairly regularly) and merged in one part of the fix, already. Which should improve things in v055b, the next release due in a week or so.
@ignoramous When will the next release happen. This bug is making me anxious. 🥲
We can release it tomorrow but you'll not like the new bugs ;) Give us time as we work through stablizing v055b. I predict a week or so, but I've been shown to be pretty bad at predictions...
This has been fixed in v055b released on github (and website): https://github.com/celzero/rethink-app/releases/tag/v0.5.5b
Please feel free to re-open if that's not the case. For F-Droid and Play Store you'd have to wait a few more days as the app is under review.