Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Panic on stopping vpn client #885

Closed
ersonp opened this issue Sep 15, 2021 · 1 comment
Closed

Panic on stopping vpn client #885

ersonp opened this issue Sep 15, 2021 · 1 comment
Labels
bug Something isn't working

Comments

@ersonp
Copy link
Contributor

ersonp commented Sep 15, 2021

Describe the bug
The visor panics when VPN client is stopped via UI.

Environment information:

  • OS: Linux
  • Platform: Linux 5.11.0-34-generic x86_64

Steps to Reproduce
Steps to reproduce the behavior:

  1. Start visor A on with a vpn-server
  2. Start visor B and connect to visor A via vpn-client
  3. Stop vpn-client on visor B
  4. See error

Note: This does not happen often. So might have to try multiple times.

Actual behavior
Deployment: myownsky (env removed), varuns deployment (more info in the PR)
Branch: 1faca3
Transport used : dmsg

[2021-09-15T15:38:27+05:30] ERROR [RouteGroup rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44]: Error during close route group: close route group timed out: context deadline exceeded
[2021-09-15T15:38:27+05:30] INFO [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Request processed. _elapsed="2.000828229s" _method="CloseConn" _received="3:38PM" input=0xc000125be8
[2021-09-15T15:38:27+05:30] INFO [RouteGroup rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44]: Remote got closed, stopping network probe loop
[2021-09-15T15:38:27+05:30] INFO [RouteGroup rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44]: Remote got closed, stopping keep-alive loop
[2021-09-15T15:38:27+05:30] WARN [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Received unexpected error when reading from server. error="io: read/write on closed pipe"
[2021-09-15T15:38:27+05:30] INFO [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Request processed. _elapsed="51.979µs" _method="SetDetailedStatus" _received="3:38PM" input=0xc0017af620
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Error resending traffic from TUN tun0 to VPN server: io: read/write on closed pipe
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Error resending traffic from VPN server to TUN tun0: read tun: file already closed
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Closed TUN
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Removing direct route to 104.21.72.123
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Removing direct route to 172.67.184.157
[2021-09-15T15:38:27+05:30] INFO (STDOUT) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: Removing direct route to 165.232.178.201
[2021-09-15T15:38:27+05:30] INFO (STDERR) [proc:vpn-client:97fb6652b50143b49de8096c9d7ecfc7]: 2021/09/15 15:38:27 rpc.Serve: accept:accept tcp 127.0.0.1:34099: use of closed network connection
2021/09/15 15:38:27 [erson-69/q8yuFPHfxL-000013] "PUT http://localhost:8000/api/visors/03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66/apps/vpn-client HTTP/1.1" from [::1]:49458 - 200 175B in 2.128615344s
[2021-09-15T15:38:28+05:30] DEBUG [transport_manager]: Locked in cleanup
[2021-09-15T15:38:28+05:30] DEBUG [transport_manager]: Unlocked in cleanup
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet header. header_len=7 header_raw=[4 0 0 0 2 0 16]
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet payload. payload_len=16
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Received packet. rt_id=2 size=16 type="NetworkProbe"
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Awaiting packet...
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet of type NetworkProbe with route ID 2
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet with descriptor rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44
[2021-09-15T15:38:28+05:30] DEBUG [router]: Got new remote packet with size 16 and route ID 2. Using rule: REV(keyRtID:2, rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44)
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet header. header_len=7 header_raw=[0 0 0 0 2 5 246]
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet payload. payload_len=1526
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Received packet. rt_id=2 size=1526 type="DataPacket"
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Awaiting packet...
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet of type DataPacket with route ID 2
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet with descriptor rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44
[2021-09-15T15:38:28+05:30] DEBUG [router]: Got new remote packet with size 1526 and route ID 2. Using rule: REV(keyRtID:2, rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44)
[2021-09-15T15:38:28+05:30] WARN [router]: Failed to handle transport frame: io: read/write on closed pipe
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet header. header_len=7 header_raw=[0 0 0 0 2 5 246]
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet payload. payload_len=1526
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Received packet. rt_id=2 size=1526 type="DataPacket"
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Awaiting packet...
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet of type DataPacket with route ID 2
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet with descriptor rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44
[2021-09-15T15:38:28+05:30] DEBUG [router]: Got new remote packet with size 1526 and route ID 2. Using rule: REV(keyRtID:2, rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44)
[2021-09-15T15:38:28+05:30] WARN [router]: Failed to handle transport frame: io: read/write on closed pipe
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet header. header_len=7 header_raw=[0 0 0 0 2 5 246]
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Read packet payload. payload_len=1526
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Received packet. rt_id=2 size=1526 type="DataPacket"
[2021-09-15T15:38:28+05:30] DEBUG readPacket [tp:03f228]: Awaiting packet...
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet of type DataPacket with route ID 2
[2021-09-15T15:38:28+05:30] DEBUG [router]: Handling packet with descriptor rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44
[2021-09-15T15:38:28+05:30] DEBUG [router]: Got new remote packet with size 1526 and route ID 2. Using rule: REV(keyRtID:2, rAddr:03c1d911914f4306bf88f3345edc856c29f9b674fba2e6009a2fe4e4a2ce22fb66:49153, lAddr:03f228c861436cb8e108739df3b74c9e444de4433b2732892d472a000aa2ac6256:44)
panic: send on closed channel

goroutine 115 [running]:
github.com/skycoin/skywire/pkg/router.(*RouteGroup).handleDataPacket(0xc0002001c0, 0xc0017e8000, 0x5fd, 0x600, 0xec, 0xc0019ddc00)
        /home/erson/Workspace/Go/skywire/pkg/router/route_group.go:624 +0x2e5
github.com/skycoin/skywire/pkg/router.(*RouteGroup).handlePacket(0xc0002001c0, 0xc0017e8000, 0x5fd, 0x600, 0x0, 0x0)
        /home/erson/Workspace/Go/skywire/pkg/router/route_group.go:588 +0x23f
github.com/skycoin/skywire/pkg/router.(*NoiseRouteGroup).handlePacket(...)
        /home/erson/Workspace/Go/skywire/pkg/router/noise_route_group.go:62
github.com/skycoin/skywire/pkg/router.(*router).handleDataHandshakePacket(0xc000396f80, 0x17aee58, 0xc00007a4c0, 0xc0017e8000, 0x5fd, 0x600, 0x43948b, 0xc00028fb00)
        /home/erson/Workspace/Go/skywire/pkg/router/router.go:524 +0xda7
github.com/skycoin/skywire/pkg/router.(*router).handleTransportPacket(0xc000396f80, 0x17aee58, 0xc00007a4c0, 0xc0017e8000, 0x5fd, 0x600, 0x179d9c0, 0xc00011a090)
        /home/erson/Workspace/Go/skywire/pkg/router/router.go:484 +0xb3
github.com/skycoin/skywire/pkg/router.(*router).serveTransportManager(0xc000396f80, 0x17aee58, 0xc00007a4c0)
        /home/erson/Workspace/Go/skywire/pkg/router/router.go:336 +0x125
created by github.com/skycoin/skywire/pkg/router.(*router).Serve
        /home/erson/Workspace/Go/skywire/pkg/router/router.go:316 +0x10e

Expected behavior
Stop app without panic.

@ersonp ersonp added the bug Something isn't working label Sep 15, 2021
@ersonp
Copy link
Contributor Author

ersonp commented Sep 17, 2021

One thing that I have noticed is that vpn on stcpr runs smoothly but it runs in some (presumably) bandwidth issues on dmsg which causes the panic on app close.

@ersonp ersonp mentioned this issue Sep 17, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants