search

celzero / rethink-app

DNS over HTTPS / DNS over Tor / DNSCrypt client, WireGuard proxifier, firewall, and connection tracker for Android.
https://rethinkfirewall.com/
Apache License 2.0
2.87k stars 146 forks source link

v055n: Crash when stopping WireGuard in Simple mode #1632

Closed soshial closed 1 month ago

soshial commented 1 month ago

Steps to reproduce:

The app crashes while the VPN is still activated and it doesn't work.

ignoramous commented 1 month ago

Can you share the crash logs, please?

Instructions: https://github.com/celzero/rethink-app/issues/1533#issuecomment-2161596524

ignoramous commented 1 month ago

Thanks.

Apart from a string of ARM Memory Tagging related crashes (#962), the crash you're seeing when stopping WireGuard specifically is due to an issue fixed in v55o (due release in a week or so): https://github.com/celzero/firestack/issues/67

...
08-02 19:31:14.119  9581  7856 I GoLog   : wgproxy.go:653: D proxy: wg: wg28 tun: closing...
08-02 19:31:14.119  9581  7856 I GoLog   : base.go:110: I proxy: base: stopped  
08-02 19:31:14.119  9581  7856 I GoLog   : tunnel.go:168: I tun: <<< disconnect >>>; err0(<nil>); err1(<nil>); svc(0)
08-02 19:31:14.119  9581  7856 D VpnLifecycle: onProxiesStopped; clear the handshake times
08-02 19:31:14.120  9581  7856 I GoLog   : fdbased.go:443: VV ns: tun(6): WritePackets (to tun): written(1)/total(1)
...
08-02 19:31:14.121  9581  7834 E GoLog   : wgproxy.go:577: W wg: wg28 tun: read closed
08-02 19:31:14.122  9581  9656 I GoLog   : wgnet.go:159: I wg: dial: tcp: #0 [2001:bc8:710:750::]:443
...
08-02 19:31:14.125  9581     0 E Go      : panic: send on closed channel        
08-02 19:31:14.125  9581     0 E Go      :      
08-02 19:31:14.125  9581     0 E Go      : goroutine 1489 [running, locked to thread]:
08-02 19:31:14.126  9581     0 E Go      : github.com/celzero/firestack/intra/ipn.(*wgtun).WriteNotify(0x400694a870)
08-02 19:31:14.126  9581     0 E Go      : >/home/jitpack/build/intra/ipn/wgproxy.go:634 +0xe8
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/link/channel.(*queue).Write(0x4006b474c0, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/link/channel/channel.go:100 +0x164
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/link/channel.(*Endpoint).WritePackets(0x40002a01e0, {{0x40001224f0, 0x1, 0x1}})
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/link/channel/channel.go:260 +0x6c
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/stack.(*delegatingQueueingDiscipline).WritePacket(0x40069d5a30, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/stack/nic.go:156 +0xa4
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).writeRawPacket(0x4000ce8008, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/stack/nic.go:411 +0x5c
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).writePacket(0x4000ce8008, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/stack/nic.go:393 +0x40
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/stack.(*nic).WritePacket(0x4000ce8008, 0x4000484d80, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/stack/nic.go:354 +0x124
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/network/ipv4.(*endpoint).writePacketPostRouting(0x4006ad4908, 0x4000484d80, 0x40069ac280, 0x0?)
...
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/network/ipv4/ipv4.go:605 +0x418
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/network/ipv4.(*endpoint).writePacket(0x4006ad4908, 0x4000484d80, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/network/ipv4/ipv4.go:555 +0x17c
08-02 19:31:14.126  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/network/ipv4.(*endpoint).WritePacket(0x4006ad4908, 0x4000484d80, {0x800?, 0x0?, 0x0?, 0x0?}, 0x40069ac280)
08-02 19:31:14.126  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/network/ipv4/ipv4.go:523 +0x9c
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/stack.(*Route).WritePacket(0x4000484d80, {0x3c21000a?, 0x0?, 0x0?, 0x0?}, 0x40069ac280)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/stack/route.go:500 +0x80
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.sendTCP(0x4000484d80, {{0xf675, {{0xa, 0x0, 0x21, 0x3c, 0x0, 0x0, 0x0, 0x0, ...}, ...}, ...}, ...}, ...)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/connect.go:917 +0x1c0
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).sendTCP(0x40006f4e08, 0x75e2c004c4?, {{0xf675, {{0xa, 0x0, 0x21, 0x3c, 0x0, 0x0, 0x0, ...}, ...}, ...}, ...}, ...)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/connect.go:815 +0x90
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).sendRaw(0x40006f4e08, 0x40069ac280, 0x11, 0x2cd7ed4e, 0xe54079ef, 0x1000)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/connect.go:990 +0x258
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendSegmentFromPacketBuffer(0x4000b0fc08, 0x40068dc3c0, 0x11, 0x2cd7ed4e)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/snd.go:1752 +0xdc
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendSegment(0x4000b0fc08, 0x40067d6300)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/snd.go:1713 +0x1a0
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).maybeSendSegment(0x4000b0fc08, 0x40067d6300, 0x40006175e8?, 0xe2ec62b4?)
08-02 19:31:14.127  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/snd.go:920 +0x1f4
08-02 19:31:14.127  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*sender).sendData(0x4000b0fc08)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/snd.go:1037 +0x1d0
08-02 19:31:14.128  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).sendData(0x40006f4e08?, 0x3c21000a?)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/connect.go:1015 +0x40
08-02 19:31:14.128  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).shutdownLocked(0x40006f4e08, 0x400012e000?)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/endpoint.go:2580 +0x490
08-02 19:31:14.128  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).closeLocked(0x40006f4e08)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/endpoint.go:1100 +0xa0
08-02 19:31:14.128  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/transport/tcp.(*Endpoint).Close(0x40006f4e08)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/transport/tcp/endpoint.go:1070 +0x30
08-02 19:31:14.128  9581     0 E Go      : gvisor.dev/gvisor/pkg/tcpip/adapters/gonet.(*TCPConn).Close(...)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/pkg/mod/gvisor.dev/gvisor@v0.0.0-20240524213522-f2b01a6e47ff/pkg/tcpip/adapters/gonet/gonet.go:418
...
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra/core.CloseConn({0x4000617840?, 0x400669b020?, 0x4000891850?})
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/core/closer.go:102 +0xe0
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra/core.(*cm).Clear(0x400669b080)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/core/connmap.go:226 +0x2b0
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra.closeconns({0x75e323c018?, 0x400669b080?}, {0x0?, 0x0, 0x0?})
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/common.go:215 +0x3c
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra.(*tcpHandler).CloseConns(0x0?, {0x0?, 0x4000132080?, 0x4000812000?})
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/tcp.go:145 +0x3c
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra/netstack.(*gconnhandler).CloseConns(0x400669b1a0, {0x0?, 0x4000122020?})
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/netstack/hdl.go:69 +0xa8
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra/netstack.(*gconnhandler).Close(0x400669b1a0)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/netstack/hdl.go:86 +0x30
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/tunnel.(*gtunnel).Disconnect.func1()
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/tunnel/tunnel.go:214 +0x48
08-02 19:31:14.128  9581     0 E Go      : sync.(*Once).doSlow(0x4000817740?, 0x2?)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/golang/go/src/sync/once.go:74 +0x100
08-02 19:31:14.128  9581     0 E Go      : sync.(*Once).Do(...)                 
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/golang/go/src/sync/once.go:65
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/tunnel.(*gtunnel).Disconnect(0x40001680e0?)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/tunnel/tunnel.go:209 +0x44
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra.(*rtunnel).Disconnect.func1()
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/tunnel.go:170 +0x200
08-02 19:31:14.128  9581     0 E Go      : sync.(*Once).doSlow(0x75fffffcf3?, 0x4000124a50?)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/golang/go/src/sync/once.go:74 +0x100
08-02 19:31:14.128  9581     0 E Go      : sync.(*Once).Do(...)                 
08-02 19:31:14.128 12880  5604 V NativeCrypto: SSL shutdown failed: ssl=0xb40000778fcb06d8: I/O error during system call, Broken pipe
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/golang/go/src/sync/once.go:65
08-02 19:31:14.128  9581     0 E Go      : github.com/celzero/firestack/intra.(*rtunnel).Disconnect(0x75e365ca70?)
08-02 19:31:14.128  9581     0 E Go      : >/home/jitpack/build/intra/tunnel.go:160 +0xd4
08-02 19:31:14.128  9581     0 E Go      : main.proxyintra_Tunnel_Disconnect(0xfffffc01?)
08-02 19:31:14.128  9581     0 E Go      : >/tmp/gomobile-work-574208690/src/gobind/go_intramain.go:946 +0x84
soshial commented 1 month ago

Awesome thank you! I will delete my logs if you don't mind

ignoramous commented 1 month ago

Awesome thank you! I will delete my logs if you don't mind

Sure. Hopefully, with improvements (and UI changes) we've made to our crash & logs collector (#1455) in v055o, sharing all logs from adb logcat won't be required.

ignoramous commented 1 month ago

Btw, I also saw a couple "connection was refused" TCP errors[^0] (which is an unrecoverable error, and one we have been unable to root-cause). Are you running Rethink in Block connections without VPN mode? And if so, do you notice that Rethink completely fails connecting over TCP after a point (ie, when you hit these "connection was refused" errors) and that you've to STOP / START the app to recover from it?

[^0]: timestamp: 08-02 17:28:39

soshial commented 1 month ago

Is this a timestamp from today, 2nd of August, right? This mode was not turned on for at least a week or so. But I had problems last several days that some apps couldn't connect to internet, while others could. How can I help you more with catching this? I'd love to help as much as possible.

ignoramous commented 1 month ago

But I had problems last several days that some apps couldn't connect to internet, while others could.

The next time you see this happen, take a note of what the final status of the connection from those apps ends up being (the final status may only be visible in the footer of the bottomsheet that comes up when you tap on the entries in the Network Log UI after the connection has timed-out or ended, which is usually anywhere between 15seconds to 2mins, and varies from app to app).

If the final status shows "connection was refused" (this happens only for TCP connections), the network engine has entered this unrecoverable scenario and we don't know why it happens. Except the fact that it has happens fairly consistently once every few days when Block connections without VPN is turned ON (and the only way to recover was to either pause then unpause the app OR stop then start the app).

This happens regardless of WireGuard or any other proxy is in use or not.

soshial commented 1 month ago

AFAIU, nothing here shows the final status of the connection:

ignoramous commented 1 month ago

AFAIU, nothing here shows the final status of the connection:

Not all connections will have final status (but most should). This is due to edge cases where the network engine shuts down without sending one, like on crash or when abruptly stopped or where the database drops writes/updates due to backpressure / load etc.