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.

Sign up for GitHub

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

Jump to bottom

Wireguard session not killed on payment engine error #2393

Closed
vkuznecovas opened this issue Jun 18, 2020 · 3 comments
Closed

Wireguard session not killed on payment engine error #2393

vkuznecovas opened this issue Jun 18, 2020 · 3 comments
Assignees
@soffokl
Labels
bug

Comments

@vkuznecovas
Copy link
Contributor

vkuznecovas commented Jun 18, 2020 •
edited 

2020-06-18T13:52:20.929 DBG session/pingpong/factory.go:155          > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"\x19\xdf\x1f\xfa9\xa5\x18\xc3h,b)\xf3Bʸ\xa7\x1c\xb2/" Amount:282234948 Hashlock:"\xfe\x0c\xd1H\xe4\xd4*\xb3\xd8y\x03\xc7\xe7\xc0\x83\x02?\x04=\x01\xbc\xf6\xfd\xd8\r\xaf\xb4Õ\x12:\x87" Signature:"\x12\xb6\x12#\xcb<#\xf5g)y\xa2\x08揱xf\x16}\xa5-}\xf7\xa5\x94\\<44\xaa\x9e\x1c\xf8\xf7\xd7\xc8;\xc4B\xb9q$\xe0!\xb7\x93\xef\x19s7\xf4\xd7\x0b\xb7\xb8\xf0w^\xf8\x85Q\x98X\x1c"} AgreementID:13972232513873681633 AgreementTotal:1 Provider:"0x59a12402649d63b3a0ad61d30b2f38b57cfe7faa" Signature:"a5b8193320a8680c0c65cbe36194fedead1db86dfe19098b698da7cae1e589c8609069c657b0abc1e1cdc6c55f5828956e0a04a4b6d35cfa8a38e7e80f1ecd471c" 6:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"
2020-06-18T13:52:20.940 ERR session/manager.go:186                   > Payment engine error error="failed to get exchange message: exchange validation failed"
2020-06-18T13:52:20.941 ERR session/manager.go:189                   > Session cleanup failed error="failed to get exchange message: exchange validation failed"
2020-06-18T13:52:22.775 INF services/wireguard/service/service_unix.go:113 > Accepting new WireGuard connection
2020-06-18T13:52:22.945 DBG session/pingpong/price_calculator.go:67  > Calculated price 528. Time component: 528, data component: 0
2020-06-18T13:52:23.067 DBG core/ip/resolver.go:103                  > IP detected: 78.63.76.227
2020-06-18T13:52:23.067 DBG config/config.go:186                     > Returning default value usermode:false
2020-06-18T13:52:23.067 INF services/wireguard/endpoint/wg_client.go:48 > Wireguard kernel space is not supported. Switching to user space implementation.
2020-06-18T13:52:23.112 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun0 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address

2020-06-18T13:52:23.113 WRN services/wireguard/endpoint/endpoint.go:165 > Failed to destroy abandoned interface: utun0 error="\"ifconfig utun0 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-06-18T13:52:23.113
 INF services/wireguard/endpoint/endpoint.go:167 > Abandoned interface destroyed: utun0

EDIT: this is macos
@vkuznecovas
Copy link
Contributor Author

Related to #2388

@vkuznecovas vkuznecovas mentioned this issue Jun 18, 2020
Closed
@zolia
Copy link
Contributor

zolia commented Jun 18, 2020 

2020-06-18T13:19:47.777 INF services/openvpn/service/manager.go:163  > OpenVPN server waiting
2020-06-18T13:19:47.893 INF core/discovery/discovery.go:98           > Starting discovery...
2020-06-18T13:19:47.893 DBG eventbus/event_bus.go:81                 > Published topic="Service status" event={ID:af3b4e87-dbbb-4c82-8c96-5f53f2b996f2 ProviderID:0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 Type:wireguard Status:Running}
2020-06-18T13:19:47.894 INF services/wireguard/service/service_unix.go:248 > Wireguard: starting
2020-06-18T13:19:47.894 INF dns/proxy.go:51                          > Starting DNS proxy on: :11253
2020-06-18T13:19:47.894 INF services/wireguard/service/service_unix.go:279 > Wireguard: started
2020-06-18T13:19:47.894 INF session/pingpong/accountant_promise_settler.go:138 > State for {0xadba6ef0c68746b9ec8e02d053cc39fd92e03541} already loaded, skipping
2020-06-18T13:19:47.894 INF identity/registry/provider_registrar.go:117 > Provider "0xadba6ef0c68746b9ec8e02d053cc39fd92e03541" already marked as registered, skipping
2020-06-18T13:19:48.018 INF market/mysterium/mysterium_api.go:166    > Proposal registered for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: wireguard
2020-06-18T13:19:49.200 INF nat/upnp/discover.go:58                  > UPnP gateways detected: 0
2020-06-18T13:22:47.868 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: openvpn
2020-06-18T13:22:48.138 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: wireguard
2020-06-18T13:25:47.984 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: openvpn
2020-06-18T13:25:48.268 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: wireguard
2020-06-18T13:28:31.428 DBG p2p/listener.go:209                      > Received consumer public key 69436d6ac077bace7ee63daed4e86ce5965b2a841796e69b4dcfa27990174f79
2020-06-18T13:28:31.697 DBG core/ip/resolver.go:103                  > IP detected: 95.217.221.75
2020-06-18T13:28:31.698 INF core/port/pool.go:68                     > Supplying port 46559
2020-06-18T13:28:31.698 INF core/port/pool.go:68                     > Supplying port 49246
2020-06-18T13:28:31.698 DBG p2p/listener.go:244                      > Sending reply with public key 8e69730340a4221a13af5de16f6bbcd92a10a694c463746e6542d229909e694b and encrypted config to consumer
2020-06-18T13:28:32.087 DBG p2p/listener.go:328                      > Decrypted consumer config: publicIP:"78.61.246.140"  ports:41539  ports:41396
2020-06-18T13:28:32.087 DBG p2p/listener.go:147                      > Skipping consumer ping
2020-06-18T13:28:32.088 DBG p2p/channel.go:200                       > Creating p2p channel with local addr: 95.217.221.75:46559, UDP session addr: 127.0.0.1:50273, proxy addr: 127.0.0.1:58279, remote peer addr: x.x.x.x:41539
2020-06-18T13:28:32.088 DBG p2p/listener.go:137                      > Delaying pings from consumer for 100 ms
2020-06-18T13:28:32.088 DBG p2p/channel.go:519                       > Will use service conn with local port: 49246, remote port: 41396
2020-06-18T13:28:32.089 DBG p2p/listener.go:349                      > Sending handlers ready message
2020-06-18T13:28:32.259 DBG core/service/subscription.go:39          > Received P2P message for "p2p-session-create": consumer:{id:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5"  accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"  paymentVersion:"v3"}  proposalID:1  config:"{\"PublicKey\":\"+BDBQfZqR4lg9k77tZqpExHRWLKbIQoJwe37Ux+3IBI=\",\"Ports\":null}"
2020-06-18T13:28:32.260 INF session/manager.go:171                   > Using new payments
2020-06-18T13:28:32.260 INF session/manager.go:194                   > Waiting for a first invoice to be paid
2020-06-18T13:28:32.260 DBG session/pingpong/invoice_tracker.go:268  > Starting...
2020-06-18T13:28:33.392 DBG session/pingpong/price_calculator.go:67  > Calculated price 189. Time component: 189, data component: 0
2020-06-18T13:28:33.394 DBG session/pingpong/invoice_tracker.go:446  > Being lenient for the first payment, asking for 1
2020-06-18T13:28:33.394 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:2317221582273057069  AgreementTotal:1  Hashlock:"ca6e6e93c57aabe0cfcf4569cc896533f520c052cca4e687ad591c993b5072fd"  Provider:"0xadba6ef0c68746b9ec8e02d053cc39fd92e03541"
2020-06-18T13:28:33.449 DBG session/pingpong/factory.go:155          > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"\x19\xdf\x1f\xfa9\xa5\x18\xc3h,b)\xf3B<CA><B8>\xa7\x1c\xb2/"  Amount:282234949  Hashlock:"\xcann\x93\xc5z\xab\xe0\xcf\xcfEi<CC><89>e3\xf5 \xc0R<CC><A4><E6><87><AD>Y\x1c\x99;Pr\xfd"  Signature:"w\x01\x01\xea\x9e\"kM\x18<D6><BD>\t\xab\xa1\xee.\x1f\x9a\x89\xd2Z\xa4j\xdb\nl\xafe\xf5\xf3:\xc7\x0c\xf6\xb7+\xb4\x04\x8dQD\xda<CA><B3>B\xf5Ta\xa0p\x0b\xc6/\xd5\x06R\xa3_\x88\x83<C6><96>\xd6\xdc\x1c"}  AgreementID:2317221582273057069  AgreementTotal:1  Provider:"0xadba6ef0c68746b9ec8e02d053cc39fd92e03541"  Signature:"bf38db6b7d2bebed8a437a4f7c55d772af9213c822e6be3112ce8c9cd626d1686a7e11f752522323ab05ba4594682fb58bb15b84e5335992eedc4b94767ab3361b"  6:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"
2020-06-18T13:28:33.450 ERR session/manager.go:186                   > Payment engine error error="failed to get exchange message: exchange validation failed"
2020-06-18T13:28:33.450 ERR session/manager.go:189                   > Session cleanup failed error="failed to get exchange message: exchange validation failed"
2020-06-18T13:28:35.260 INF services/wireguard/service/service_unix.go:113 > Accepting new WireGuard connection
2020-06-18T13:28:35.449 DBG session/pingpong/price_calculator.go:67  > Calculated price 531. Time component: 531, data component: 0
2020-06-18T13:28:35.504 DBG core/ip/resolver.go:103                  > IP detected: 95.217.221.75
2020-06-18T13:28:35.504 DBG config/config.go:186                     > Returning default value usermode:false
2020-06-18T13:28:35.515 DBG services/wireguard/endpoint/wg_client.go:57 > "ip link add iswgsupported type wireguard" output:

2020-06-18T13:28:35.595 DBG services/wireguard/endpoint/wg_client.go:62 > "ip link del iswgsupported" output:

2020-06-18T13:28:35.608 DBG services/wireguard/endpoint/kernelspace/client.go:131 > "ip link add dev myst0 type wireguard" output:

2020-06-18T13:28:35.623 DBG services/wireguard/endpoint/kernelspace/client.go:136 > "ip address replace dev myst0 10.182.0.1/24" output:

2020-06-18T13:28:35.647 DBG services/wireguard/endpoint/kernelspace/client.go:140 > "ip link set dev myst0 up" output:

2020-06-18T13:28:35.658 INF nat/service_iptables.go:45               > Setting up NAT/Firewall rules
2020-06-18T13:28:35.658 DBG config/config.go:186                     > Returning default value firewall.protected.networks:10.0.0.0/8,172.16.0.0/12,192.168.0.0/16,127.0.0.0/8
2020-06-18T13:28:35.668 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol udp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:

2020-06-18T13:28:35.676 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol tcp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:

2020-06-18T13:28:35.685 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.0.2/24 --destination 10.0.0.0/8 --jump DROP" output:

2020-06-18T13:28:35.693 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.0.2/24 --destination 172.16.0.0/12 --jump DROP" output:

2020-06-18T13:28:35.701 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.0.2/24 --destination 192.168.0.0/16 --jump DROP" output:

2020-06-18T13:28:35.709 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.0.2/24 --destination 127.0.0.0/8 --jump DROP" output:

2020-06-18T13:28:35.717 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A POSTROUTING --source 10.182.0.2/24 ! --destination 10.182.0.2/24 --jump SNAT --to 95.217.221.75 --table nat" output:

2020-06-18T13:28:35.717 INF nat/service_iptables.go:69               > Setting up NAT/Firewall rules... done
2020-06-18T13:28:35.725 ??? github.com/rs/zerolog@v1.17.2/log.go:403 > Error: Cannot delete qdisc with handle of zero.
2020-06-18T13:28:35.732 ??? github.com/rs/zerolog@v1.17.2/log.go:403 > Error: Cannot find specified qdisc on specified device.
2020-06-18T13:28:35.745 ??? github.com/rs/zerolog@v1.17.2/log.go:403 > Cannot find device "ifb0"
2020-06-18T13:28:35.757 ??? github.com/rs/zerolog@v1.17.2/log.go:403 > Cannot find device "ifb0"
2020-06-18T13:28:35.758 DBG config/config.go:186                     > Returning default value shaper.enabled:false
2020-06-18T13:28:36.160 DBG core/service/subscription.go:138         > Received P2P message for "p2p-session-acknowledge": consumerID:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5"  sessionID:"c297a625-21f8-4168-9ed6-c322d445fb08"
2020-06-18T13:28:36.823 DBG core/service/subscription.go:93          > Received P2P session status message for "p2p-session-connectivity-status": ConsumerID:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5"  SessionID:"c297a625-21f8-4168-9ed6-c322d445fb08"  Code:1000
2020-06-18T13:28:37.449 DBG session/pingpong/price_calculator.go:67  > Calculated price 1390. Time component: 865, data component: 525
2020-06-18T13:28:39.450 DBG session/pingpong/price_calculator.go:67  > Calculated price 1909. Time component: 1198, data component: 711
2020-06-18T13:28:41.450 DBG session/pingpong/price_calculator.go:67  > Calculated price 2726. Time component: 1532, data component: 1194
2020-06-18T13:28:43.451 DBG session/pingpong/price_calculator.go:67  > Calculated price 3434. Time component: 1865, data component: 1569
2020-06-18T13:28:45.451 DBG session/pingpong/price_calculator.go:67  > Calculated price 3802. Time component: 2198, data component: 1604
2020-06-18T13:28:47.451 DBG session/pingpong/price_calculator.go:67  > Calculated price 4363. Time component: 2532, data component: 1831
2020-06-18T13:28:48.103 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: openvpn
2020-06-18T13:28:48.393 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: wireguard
2020-06-18T13:28:49.452 DBG session/pingpong/price_calculator.go:67  > Calculated price 38917. Time component: 2865, data component: 36052
2020-06-18T13:28:51.452 DBG session/pingpong/price_calculator.go:67  > Calculated price 551715. Time component: 3199, data component: 548516
2020-06-18T13:28:53.453 DBG session/pingpong/price_calculator.go:67  > Calculated price 1377933. Time component: 3532, data component: 1374401
2020-06-18T13:28:55.454 DBG session/pingpong/price_calculator.go:67  > Calculated price 1976370. Time component: 3866, data component: 1972504
2020-06-18T13:28:56.165 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:28:57.454 DBG session/pingpong/price_calculator.go:67  > Calculated price 2234835. Time component: 4199, data component: 2230636
2020-06-18T13:28:59.455 DBG session/pingpong/price_calculator.go:67  > Calculated price 2238673. Time component: 4532, data component: 2234141
2020-06-18T13:29:01.455 DBG session/pingpong/price_calculator.go:67  > Calculated price 2239347. Time component: 4866, data component: 2234481
2020-06-18T13:29:03.455 DBG session/pingpong/price_calculator.go:67  > Calculated price 2239873. Time component: 5199, data component: 2234674
2020-06-18T13:29:05.456 DBG session/pingpong/price_calculator.go:67  > Calculated price 2240287. Time component: 5533, data component: 2234754
2020-06-18T13:29:07.456 DBG session/pingpong/price_calculator.go:67  > Calculated price 2240763. Time component: 5866, data component: 2234897
2020-06-18T13:29:09.457 DBG session/pingpong/price_calculator.go:67  > Calculated price 2242331. Time component: 6199, data component: 2236132
2020-06-18T13:29:11.457 DBG session/pingpong/price_calculator.go:67  > Calculated price 2243256. Time component: 6533, data component: 2236723
2020-06-18T13:29:13.458 DBG session/pingpong/price_calculator.go:67  > Calculated price 2243755. Time component: 6866, data component: 2236889
2020-06-18T13:29:15.458 DBG session/pingpong/price_calculator.go:67  > Calculated price 2244250. Time component: 7200, data component: 2237050
2020-06-18T13:29:16.219 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:29:17.458 DBG session/pingpong/price_calculator.go:67  > Calculated price 2244786. Time component: 7533, data component: 2237253
2020-06-18T13:29:19.459 DBG session/pingpong/price_calculator.go:67  > Calculated price 2245342. Time component: 7866, data component: 2237476
2020-06-18T13:29:21.459 DBG session/pingpong/price_calculator.go:67  > Calculated price 2245908. Time component: 8200, data component: 2237708
2020-06-18T13:29:23.447 INF session/pingpong/invoice_tracker.go:506  > did not get paid for invoice with hashlock ca6e6e93c57aabe0cfcf4569cc896533f520c052cca4e687ad591c993b5072fd, invoice is critical. Aborting.
2020-06-18T13:29:23.460 DBG session/pingpong/price_calculator.go:67  > Calculated price 2246411. Time component: 8533, data component: 2237878
2020-06-18T13:29:25.460 DBG session/pingpong/price_calculator.go:67  > Calculated price 2247077. Time component: 8867, data component: 2238210
2020-06-18T13:29:27.461 DBG session/pingpong/price_calculator.go:67  > Calculated price 2247604. Time component: 9200, data component: 2238404
2020-06-18T13:29:29.461 DBG session/pingpong/price_calculator.go:67  > Calculated price 2248068. Time component: 9533, data component: 2238535
2020-06-18T13:29:31.461 DBG session/pingpong/price_calculator.go:67  > Calculated price 2248862. Time component: 9867, data component: 2238995
2020-06-18T13:29:33.462 DBG session/pingpong/price_calculator.go:67  > Calculated price 2249331. Time component: 10200, data component: 2239131
2020-06-18T13:29:36.275 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:29:56.327 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:30:16.389 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:30:36.442 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:30:56.496 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:31:16.554 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:31:36.612 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:31:48.224 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: openvpn
2020-06-18T13:31:48.514 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0xadba6ef0c68746b9ec8e02d053cc39fd92e03541 service type: wireguard
2020-06-18T13:31:56.666 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08
2020-06-18T13:32:16.719 DBG session/manager.go:278                   > Received p2p keepalive ping with SessionID=c297a625-21f8-4168-9ed6-c322d445fb08

@soffokl
Copy link
Member

soffokl commented Jun 29, 2020

This is resolved by the #2396

@soffokl soffokl closed this as completed Jun 29, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@soffokl soffokl

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@soffokl @zolia @vkuznecovas