search

mysteriumnetwork / node

Mysterium Network Node - official implementation of distributed VPN network (dVPN) protocol
https://mysterium.network
GNU General Public License v3.0
1.11k stars 313 forks source link

Openvpn connectivity fails on 0.31.1 #2157

Closed rymir closed 3 years ago

rymir commented 4 years ago

Describe the bug Node server version 0.31.1 and desktop client app 0.31.1. Wireguard connectivity works, while Openvpn connectivity fails to engage (shows ~300B uploaded on desktop client and nothing downloaded) then drops after ~1 minute session time.

NOTE: Works as expected on node server version 0.22.5 (both openvpn and wireguard services can correctly establish node connectivity)

To Reproduce Steps to reproduce the behavior:

  1. Use node server version 0.31.1 and desktop client app 0.31.1
  2. Connect to node openvpn service from desktop client app
  3. Shows ~300B uploaded on desktop client and nothing downloaded, then drops after ~1 minute

Expected behavior Should connect and start uploading and downloading data as on node server version 0.22.5.

Screenshots If applicable, add screenshots to help explain your problem.

Environment (please complete the following information):

Additional context Session logs following (public ips masked):

May 02 22:23:21 raspberrypi myst[444]: 2020-05-02T22:23:21.552 DBG source/p2p/listener.go:209               > Received consumer public key 1748dce47dde5b892f581025a9219eca2625b50c71a1b335f668408d8af0573c
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.230 DBG source/core/ip/resolver.go:103           > IP detected: xxxxxxxx
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.242 INF source/core/port/pool.go:68              > Supplying port 40420
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.256 INF source/core/port/pool.go:68              > Supplying port 43123
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.286 DBG source/nat/mapping/port_mapping.go:119   > Detected router public IP address: xxxxxxxx
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.335 INF source/nat/mapping/port_mapping.go:149   > Mapped network port: 40420
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.345 DBG source/eventbus/event_bus.go:81          > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
May 02 22:23:22 raspberrypi myst[444]: 2020-05-02T22:23:22.355 INF source/nat/event/tracker.go:53           > Got NAT event event={"stage":"port_mapping","successful":true}
May 02 22:23:23 raspberrypi myst[444]: 2020-05-02T22:23:23.320 DBG source/core/ip/resolver.go:103           > IP detected: xxxxxxxx
May 02 22:23:23 raspberrypi myst[444]: 2020-05-02T22:23:23.358 DBG source/nat/mapping/port_mapping.go:119   > Detected router public IP address: xxxxxxxx
May 02 22:23:23 raspberrypi myst[444]: 2020-05-02T22:23:23.407 INF source/nat/mapping/port_mapping.go:149   > Mapped network port: 43123
May 02 22:23:23 raspberrypi myst[444]: 2020-05-02T22:23:23.419 DBG source/eventbus/event_bus.go:81          > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
May 02 22:23:23 raspberrypi myst[444]: 2020-05-02T22:23:23.431 INF source/nat/event/tracker.go:53           > Got NAT event event={"stage":"port_mapping","successful":true}
May 02 22:23:24 raspberrypi myst[444]: 2020-05-02T22:23:24.400 DBG source/core/ip/resolver.go:103           > IP detected: xxxxxxxx
May 02 22:23:24 raspberrypi myst[444]: 2020-05-02T22:23:24.438 DBG source/p2p/listener.go:244               > Sending reply with public key dee677bed9b58e095bcbf25b35b40154f1d64087539a96b36914292ac340ff57 and encrypted config to consumer
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.583 DBG source/p2p/listener.go:328               > Decrypted consumer config: publicIP:"xxxxxxxx"  ports:42610  ports:48272
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.596 DBG source/p2p/listener.go:147               > Skipping consumer ping
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.612 DBG source/p2p/listener.go:137               > Delaying pings from consumer for 100 ms
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.634 DBG source/p2p/channel.go:192                > Creating p2p channel with local addr: 192.168.1.184:40420, UDP session addr: 127.0.0.1:55756, proxy addr: 127.0.0.1:44658, remote peer addr: x.x.x.x:42610
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.640 DBG source/p2p/channel.go:503                > Will use service conn with local port: 43123, remote port: 48272
May 02 22:23:26 raspberrypi myst[444]: 2020-05-02T22:23:26.646 DBG source/p2p/listener.go:349               > Sending handlers ready message
May 02 22:23:28 raspberrypi myst[444]: 2020-05-02T22:23:28.385 DBG source/p2p/channel.go:251                > Peer port changed from 42610 to 27154
May 02 22:23:28 raspberrypi myst[444]: 2020-05-02T22:23:28.404 DBG source/core/service/subscription.go:39   > Received P2P message for "p2p-session-create": consumer:{id:"0xaa6350280c1abbaac58a01beba5cd3cf6065eaa1"  accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"  paymentVersion:"v3"}  proposalID:1  config:"{\"Ip\":\"37.159.107.110\",\"Ports\":[49885,49080,40300,41818,47138,42317,46301,40811,42507,46484]}"
May 02 22:23:29 raspberrypi myst[444]: 2020-05-02T22:23:29.065 DBG source/core/ip/resolver.go:103           > IP detected: xxxxxxxx
May 02 22:23:29 raspberrypi myst[444]: 2020-05-02T22:23:29.077 WRN source/services/openvpn/service/factory.go:107 > WARNING: It seems that publicly visible ip: [xxxxxxxx] does not match your local machines ip: [192.168.1.184].
May 02 22:23:29 raspberrypi myst[444]: You should probably need to do port forwarding on your router: xxxxxxxx:0 -> 192.168.1.184:0.
May 02 22:23:29 raspberrypi myst[444]: 2020-05-02T22:23:29.089 INF source/session/manager.go:177            > Using new payments
May 02 22:23:29 raspberrypi myst[444]: 2020-05-02T22:23:29.124 DBG source/session/pingpong/invoice_tracker.go:389 > Starting...
May 02 22:23:30 raspberrypi myst[444]: 2020-05-02T22:23:30.799 DBG source/session/pingpong/price_calculator.go:67 > Calculated price 2781. Time component: 2781, data component: 0
May 02 22:23:30 raspberrypi myst[444]: 2020-05-02T22:23:30.813 DBG source/session/pingpong/invoice_tracker.go:512 > Being lenient for the first payment, asking for 2224
May 02 22:23:30 raspberrypi myst[444]: 2020-05-02T22:23:30.824 DBG source/session/pingpong/invoice_messaging.go:66 > Sending P2P message to "p2p-payment-invoice": AgreementID:12738300842455260200  AgreementTotal:2224  Hashlock:"6051d1ec51163bc13dc160d5f24502db0fc373d6b91333c618e819d6eb6995da"  Provider:"0xcc075d98753c240105f3fdb7e6ae5db000be3129"
May 02 22:23:31 raspberrypi myst[444]: [785B blob data]
May 02 22:23:31 raspberrypi myst[444]: 2020-05-02T22:23:31.787 DBG source/eventbus/event_bus.go:81          > Published topic="SessionTokensEarned" event={ProviderID:{Address:0xcc075d98753c240105f3fdb7e6ae5db000be3129} SessionID:52890f47-2b85-4a61-bd65-9caecd69f29b Total:2224}
May 02 22:23:31 raspberrypi myst[444]: 2020-05-02T22:23:31.795 INF source/session/pingpong/accountant_promise_settler.go:247 > Received accountant promise for {"0xcc075d98753c240105f3fdb7e6ae5db000be3129"}
May 02 22:23:31 raspberrypi myst[444]: 2020-05-02T22:23:31.815 INF source/session/pingpong/accountant_promise_settler.go:264 > Accountant promise state updated for provider {"0xcc075d98753c240105f3fdb7e6ae5db000be3129"}
May 02 22:23:31 raspberrypi myst[444]: 2020-05-02T22:23:31.822 DBG source/eventbus/event_bus.go:81          > Published topic="earnings_change" event={Identity:{Address:0xcc075d98753c240105f3fdb7e6ae5db000be3129} Previous:{LifetimeBalance:725918826 UnsettledBalance:725918826} Current:{LifetimeBalance:725921050 UnsettledBalance:725921050}}
May 02 22:24:31 raspberrypi myst[444]: 2020-05-02T22:24:31.276 DBG source/session/pingpong/price_calculator.go:67 > Calculated price 103576. Time component: 103576, data component: 0
May 02 22:24:31 raspberrypi myst[444]: 2020-05-02T22:24:31.292 DBG source/session/pingpong/invoice_messaging.go:66 > Sending P2P message to "p2p-payment-invoice": AgreementID:12738300842455260200  AgreementTotal:103576  Hashlock:"4146551d5bcbe62478422a63e7ada844376d334e929fab2279aa687929a5c74a"  Provider:"0xcc075d98753c240105f3fdb7e6ae5db000be3129"
May 02 22:24:32 raspberrypi myst[444]: 2020-05-02T22:24:32.310 DBG source/p2p/channel.go:251                > Peer port changed from 27154 to 27147
May 02 22:24:32 raspberrypi myst[444]: 2020-05-02T22:24:32.319 DBG source/core/service/subscription.go:93   > Received P2P session status message for "p2p-session-connectivity-status": ConsumerID:"0xaa6350280c1abbaac58a01beba5cd3cf6065eaa1"  SessionID:"52890f47-2b85-4a61-bd65-9caecd69f29b"  Code:2003  Message:"connection has failed"
May 02 22:24:32 raspberrypi myst[444]: 2020-05-02T22:24:32.333 DBG source/core/service/subscription.go:114  > Received P2P message for "p2p-session-destroy": consumerID:"0xaa6350280c1abbaac58a01beba5cd3cf6065eaa1"  sessionID:"52890f47-2b85-4a61-bd65-9caecd69f29b"
May 02 22:24:32 raspberrypi myst[444]: 2020-05-02T22:24:32.347 DBG source/session/pingpong/invoice_tracker.go:714 > Stopping...
May 02 22:24:41 raspberrypi myst[444]: 2020-05-02T22:24:41.306 WRN source/session/pingpong/invoice_tracker.go:521 > Marking invoice as not sent error="timeout waiting for reply to \"p2p-payment-invoice\": p2p send timeout"
May 02 22:24:42 raspberrypi myst[444]: 2020-05-02T22:24:42.350 DBG source/nat/mapping/port_mapping.go:154   > Deleting port mapping for port: 40420
May 02 22:24:42 raspberrypi myst[444]: 2020-05-02T22:24:42.389 DBG source/nat/mapping/port_mapping.go:154   > Deleting port mapping for port: 43123
anjmao commented 4 years ago

Hi @rymir

I tried connecting from 0.31 app to 0.31 server and it seems to work. Could you also provide consumer logs for your connecrion? I tried to connect to your provider 0xcc075d98753c240105f3fdb7e6ae5db000be3129 but it looks that you are running older 0.22.5 again. Thank you.

rymir commented 4 years ago

@anjmao thanks for the response. Where can I find consumer logs? I'm running OSX mysterium-vpn-desktop https://github.com/mysteriumnetwork/mysterium-vpn-desktop/releases/download/2.0.0-beta1/MysteriumVPN-2.0.0-beta1.dmg

I tried to connect to your provider 0xcc075d98753c240105f3fdb7e6ae5db000be3129 but it looks that you are running older 0.22.5 again. Thank you.

Right, I keep downgrading my node cause version 0.22.5 is the only one which I can verify working in terms of both openvpn and wireguard connectivity.

Attempted again using server node verision 0.31.3, but p2p-payment "handshake" fails with:

May 08 13:54:24 raspberrypi myst[19841]: 2020-05-08T13:54:24.440 DBG source/session/pingpong/price_calculator.go:67 > Calculated price 102841. Time component: 102841, data component: 0
May 08 13:54:24 raspberrypi myst[19841]: 2020-05-08T13:54:24.457 DBG source/session/pingpong/invoice_messaging.go:66 > Sending P2P message to "p2p-payment-invoice": AgreementID:9315018199832517915  AgreementTotal:102841  Hashlock:"ec1ce365d0bce329deec0b1bae3b1003fc771701f7c98741cfafb12caf2865e2"  Provider:"0xcc075d98753c240105f3fdb7e6ae5db000be3129"
May 08 13:54:25 raspberrypi myst[19841]: 2020-05-08T13:54:25.676 DBG source/p2p/channel.go:251                > Peer port changed from 63146 to 63171
May 08 13:54:25 raspberrypi myst[19841]: 2020-05-08T13:54:25.692 DBG source/core/service/subscription.go:93   > Received P2P session status message for "p2p-session-connectivity-status": ConsumerID:"0xaa6350280c1abbaac58a01beba5cd3cf6065eaa1"  SessionID:"fb680e42-5bde-4c92-ae14-ae79a6c4ddc4"  Code:2003  Message:"connection has failed"
stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 3 years ago

This issue has been automatically closed because it has not had activity for a long time. If this issue is still valid, please ping a maintainer and ask them to label it as "pinned". Thank you for your contributions.