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

Provider attempts to settle new initial promise #2149

Closed zolia closed 4 years ago

zolia commented 4 years ago

imho there should be no such attempt at this phase. Also getting: "promise signed with wrong operator".

This happened for brand new provider, right after it registers its identity. 

2020-04-29T14:54:03.145 INF logconfig/openvpnlog.go:54               > Client with ID: 0 connection established successfully
2020-04-29T14:54:03.375 DBG core/service/subscription.go:138         > Received P2P message for "p2p-session-acknowledge": consumerID:"0x8ea78b28f155e417cf904b6325df1fdd891bd058"  sessionID:"4b54fed2-b2ec-4405-b8a2-ebf4f62b0d65"
2020-04-29T14:54:03.856 DBG session/pingpong/price_calculator.go:67  > Calculated price 1050. Time component: 1050, data component: 0
2020-04-29T14:54:03.856 DBG session/pingpong/invoice_tracker.go:375  > Being lenient for the first payment, asking for 840
2020-04-29T14:54:03.857 DBG session/pingpong/invoice_messaging.go:66 > Sending P2P message to "p2p-payment-invoice": AgreementID:17176730741991300435  AgreementTotal:840  Hashlock:"5c9fc34cdf46178cba0ffc0dc05183f3f639e8ca778022de9c358ac734e47186"  Provider:"0x816c8cf15593824a772159541a9d67bd41a4ecc8"
2020-04-29T14:54:03.884 DBG session/pingpong/factory.go:166          > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"˯\xfa\x80?\x88#\xa2\xd6\x0b\\\xa5\xc8i:/ 9H\xc4"  Amount:5207517433  Hashlock:"\\\x9f\xc3L\xdfF\x17\x8c\xba\x0f\xfc\r\xc0Q\x83\xf3\xf69\xe8\xcaw\x80\"ޜ5\x8a\xc74\xe4q\x86"  Signature:"\xe2\xb6R.\x93-\xaa\xb6\xc2h\xb0\x87\xe8\x94\xe0ta\xbb\xa7k\x17\xa6<\x8c2\xd1T\xec9;\x12\x9eusy$Q\xfb\xa3e'\xf2+\xf8\xfd\x05\x91\x89\xebs\xac\x0c\xd1\xd3\xe5e\xde@\xa3\xde\x14>N\x1c"}  AgreementID:17176730741991300435  AgreementTotal:840  Provider:"0x816c8cf15593824a772159541a9d67bd41a4ecc8"  Signature:"d6b67e4293b401bf32c1319edc81a2be47ac1762c8c179ddfe2015387f3409fd0ab23223b60abfc7b3de4f88e9527c0bd174fb801d3ea0d4b1538978f95d3f421c"
2020-04-29T14:54:04.001 DBG eventbus/event_bus.go:81                 > Published topic="SessionTokensEarned" event={ProviderID:{Address:0x816c8cf15593824a772159541a9d67bd41a4ecc8} SessionID:44c60898-c6c2-45aa-9819-927f2510981a Total:840}
2020-04-29T14:54:04.001 INF session/pingpong/accountant_promise_settler.go:247 > Received accountant promise for {"0x816c8cf15593824a772159541a9d67bd41a4ecc8"}
2020-04-29T14:54:04.001 INF session/pingpong/accountant_promise_settler.go:264 > Accountant promise state updated for provider {"0x816c8cf15593824a772159541a9d67bd41a4ecc8"}
2020-04-29T14:54:04.001 INF session/pingpong/accountant_promise_settler.go:332 > Marked provider {0x816c8cf15593824a772159541a9d67bd41a4ecc8} as requesting setlement
2020-04-29T14:54:04.002 DBG eventbus/event_bus.go:81                 > Published topic="earnings_change" event={Identity:{Address:0x816c8cf15593824a772159541a9d67bd41a4ecc8} Previous:{LifetimeBalance:0 UnsettledBalance:0} Current:{LifetimeBalance:840 UnsettledBalance:840}}
2020-04-29T14:54:04.073 ERR session/pingpong/accountant_promise_settler.go:376 > Could not settle promise for 0x816c8cf15593824a772159541a9d67bd41a4ecc8 error="server response invalid: 400 Bad Request (https://testnet-transactor.mysterium.network/api/v1/identity/settle_and_rebalance){\"error\":\"promise signed with wrong operator\"}"
2020-04-29T14:54:04.158 DBG session/pingpong/price_calculator.go:67  > Calculated price 1230. Time component: 1052, data component: 178
2020-04-29T14:54:04.158 DBG session/pingpong/invoice_tracker.go:375  > Being lenient for the first payment, asking for 984
2020-04-29T14:54:04.158 DBG session/pingpong/invoice_messaging.go:66 > Sending P2P message to "p2p-payment-invoice": AgreementID:13696161106387307318  AgreementTotal:984  Hashlock:"e60500b332abba52befb345807c2855e594ee5be0b136396af850b984b936eec"  Provider:"0x816c8cf15593824a772159541a9d67bd41a4ecc8"

consumer log: 

2020-04-29T15:47:30.752 INF core/connection/manager.go:624           > Connection state: Disconnecting -> NotConnected
2020-04-29T15:47:30.752 DBG core/connection/manager.go:487           > Sending P2P message to "p2p-session-destroy": consumerID:"0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a"  sessionID:"ec7daae4-998f-4798-a8de-fa9d0778ae71"
2020-04-29T15:47:30.752 DBG eventbus/event_bus.go:81                 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2020-04-29 15:47:10.608053 +0300 EEST m=+33.541105822 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:NotConnected SessionID:ec7daae4-998f-4798-a8de-fa9d0778ae71 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:30.752 INF cmd/di.go:860                            > Reconnecting HTTP clients due to VPN connection state change
2020-04-29T15:47:30.752 DBG core/location/oracle_resolver.go:41      > Detecting with oracle resolver
2020-04-29T15:47:30.752 INF core/state/state.go:359                  > Session ID ec7daae4-998f-4798-a8de-fa9d0778ae71 NotConnected duration: 20.144742625s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-04-29T15:47:30.755 INF communication/nats/connector.go:85       > Attempting to reconnect to broker (1 connections)
2020-04-29T15:47:30.755 INF communication/nats/connector.go:91       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03
2020-04-29T15:47:30.761 INF communication/nats/connector.go:95       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03 DONE
2020-04-29T15:47:30.761 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-04-29T15:47:30.761 INF communication/nats/connector.go:100      > All broker connections re-established
2020-04-29T15:47:30.875 WRN communication/nats/connection_wrap.go:87 > NATS: reconnected
2020-04-29T15:47:30.896 INF market/mysterium/mysterium_api.go:309    > Session stats sent: ec7daae4-998f-4798-a8de-fa9d0778ae71
2020-04-29T15:47:30.896 DBG consumer/statistics/reporter.go:109      > Final stats sent
2020-04-29T15:47:31.030 DBG core/location/cache.go:95                > Location update succeeded: {78.157.70.161 21211 Penki EU LT Vilnius business}
2020-04-29T15:47:32.447 INF tequilapi/endpoints/connection.go:160    > identity "0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a" is registered, continuing...
2020-04-29T15:47:32.558 INF core/connection/manager.go:624           > Connection state: NotConnected -> Connecting
2020-04-29T15:47:32.558 DBG communication/nats/connector.go:45       > Connecting to NATS servers: nats://testnet-broker.mysterium.network:4222
2020-04-29T15:47:32.558 DBG eventbus/event_bus.go:81                 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:32.558 INF firewall/outgoing_firewall_noop.go:57    > Allow URL nats://testnet-broker.mysterium.network:4222 access
2020-04-29T15:47:32.559 INF core/state/state.go:359                  > Session ID  Connecting duration: 927.633µs data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-04-29T15:47:32.660 DBG p2p/dialer.go:144                        > Consumer 0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a sending public key 29871971627786fb96b3539830b4f623c65a2f7c2212e2dea012f574e56de203 to provider 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b
2020-04-29T15:47:33.944 DBG p2p/dialer.go:171                        > Consumer 0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a received provider 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b with config: publicIP:"88.119.191.24"  ports:46706  ports:49306  ports:40205  ports:46356  ports:47804  ports:49937  ports:43916  ports:40031  ports:48234  ports:46765  ports:47719  ports:48958  ports:46417  ports:43133  ports:44644  ports:49353  ports:45668  ports:41748  ports:47344  ports:43257
2020-04-29T15:47:34.226 DBG core/ip/resolver.go:103                  > IP detected: 78.157.70.161
2020-04-29T15:47:34.226 INF core/port/pool.go:68                     > Supplying port 48794
2020-04-29T15:47:34.226 INF core/port/pool.go:68                     > Supplying port 44776
2020-04-29T15:47:34.227 INF core/port/pool.go:68                     > Supplying port 46868
2020-04-29T15:47:34.227 INF core/port/pool.go:68                     > Supplying port 44719
2020-04-29T15:47:34.227 INF core/port/pool.go:68                     > Supplying port 41795
2020-04-29T15:47:34.227 INF core/port/pool.go:68                     > Supplying port 44262
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 45342
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 40323
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 49155
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 45170
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 40093
2020-04-29T15:47:34.228 INF core/port/pool.go:68                     > Supplying port 48433
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 41203
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 48700
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 41382
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 41280
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 42032
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 45814
2020-04-29T15:47:34.229 INF core/port/pool.go:68                     > Supplying port 46681
2020-04-29T15:47:34.230 INF core/port/pool.go:68                     > Supplying port 40740
2020-04-29T15:47:34.230 DBG p2p/dialer.go:194                        > Consumer 0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a sending ack with encrypted config to provider 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b
2020-04-29T15:47:34.408 INF firewall/outgoing_firewall_noop.go:48    > Allow IP 88.119.191.24 access
2020-04-29T15:47:34.408 DBG p2p/dialer.go:109                        > Pinging provider 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b with IP 88.119.191.24 using ports [48794 44776 46868 44719 41795 44262 45342 40323 49155 45170 40093 48433 41203 48700 41382 41280 42032 45814 46681 40740]:[46706 49306 40205 46356 47804 49937 43916 40031 48234 46765 47719 48958 46417 43133 44644 49353 45668 41748 47344 43257]
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:273              > NAT pinging to remote peer
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:41795
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:41203
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:40093
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:46868
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:45170
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:44719
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:44776
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:48433
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:48700
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:45814
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:45342
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:44262
2020-04-29T15:47:34.412 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:41280
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:48794
2020-04-29T15:47:34.408 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:49155
2020-04-29T15:47:34.413 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:41382
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:46681
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:40323
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:42032
2020-04-29T15:47:34.409 INF nat/traversal/pinger.go:521              > Local socket: 0.0.0.0:40740
2020-04-29T15:47:34.470 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:48958
2020-04-29T15:47:34.672 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:49353
2020-04-29T15:47:34.875 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:43133
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:44644
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:49937
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:46417
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:46356
2020-04-29T15:47:40.476 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:47804
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:40205
2020-04-29T15:47:40.475 INF nat/traversal/pinger.go:435              > Remote peer data received: OK, len: 2, from: 88.119.191.24:49306
2020-04-29T15:47:40.512 DBG p2p/dialer.go:121                        > Received handlers ready message from provider
2020-04-29T15:47:40.513 DBG p2p/channel.go:192                       > Creating p2p channel with local addr: 192.168.88.176:48433, UDP session addr: 127.0.0.1:56184, proxy addr: 127.0.0.1:53850, remote peer addr: x.x.x.x:48958
2020-04-29T15:47:40.513 DBG p2p/channel.go:503                       > Will use service conn with local port: 41280, remote port: 49353
2020-04-29T15:47:40.513 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-04-29T15:47:40.513 INF communication/nats/connector.go:71       > Removing broker connection from the registry: dbb393b7-1b5e-424c-b324-f2fdca6f1faf
2020-04-29T15:47:40.513 WRN communication/nats/connection_wrap.go:85 > NATS: connection closed
2020-04-29T15:47:40.513 INF firewall/outgoing_firewall_noop.go:61    > Rule for URL: nats://testnet-broker.mysterium.network:4222 removed
2020-04-29T15:47:40.808 DBG core/ip/resolver.go:103                  > IP detected: 78.157.70.161
2020-04-29T15:47:40.809 DBG config/config.go:181                     > Returning default value natpunching.max-ttl:10
2020-04-29T15:47:40.809 INF core/port/pool.go:68                     > Supplying port 40516
2020-04-29T15:47:40.809 INF core/port/pool.go:68                     > Supplying port 44612
2020-04-29T15:47:40.809 INF core/port/pool.go:68                     > Supplying port 47835
2020-04-29T15:47:40.809 INF core/port/pool.go:68                     > Supplying port 47890
2020-04-29T15:47:40.809 INF core/port/pool.go:68                     > Supplying port 44145
2020-04-29T15:47:40.810 INF core/port/pool.go:68                     > Supplying port 44136
2020-04-29T15:47:40.810 INF core/port/pool.go:68                     > Supplying port 41523
2020-04-29T15:47:40.810 INF core/port/pool.go:68                     > Supplying port 47734
2020-04-29T15:47:40.810 INF core/port/pool.go:68                     > Supplying port 41448
2020-04-29T15:47:40.810 INF core/port/pool.go:68                     > Supplying port 49400
2020-04-29T15:47:40.810 DBG core/connection/manager.go:451           > Sending P2P message to "p2p-session-create": consumer:{id:"0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a"  accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"  paymentVersion:"v3"}  proposalID:1  config:"{\"Ip\":\"78.157.70.161\",\"Ports\":[40516,44612,47835,47890,44145,44136,41523,47734,41448,49400]}"
2020-04-29T15:47:41.383 DBG eventbus/event_bus.go:81                 > Published topic="Session" event={Status:Created SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Connecting SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:41.425 DBG consumer/session/session_storage.go:178  > Session 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 saved
2020-04-29T15:47:41.430 DBG consumer/statistics/reporter.go:123      > Session statistics reporter started
2020-04-29T15:47:41.430 INF session/pingpong/factory.go:209          > Using new payments
2020-04-29T15:47:41.430 DBG session/pingpong/invoice_payer.go:120    > Starting...
2020-04-29T15:47:41.710 DBG core/ip/resolver.go:103                  > IP detected: 78.157.70.161
2020-04-29T15:47:41.711 INF services/openvpn/client.go:124           > Starting connection
2020-04-29T15:47:41.711 INF firewall/outgoing_firewall_noop.go:48    > Allow IP 88.119.191.24 access
2020-04-29T15:47:41.712 DBG core/connection/dns_option.go:86         > Selecting DNS servers using strategy: auto
2020-04-29T15:47:41.712 DBG core/connection/dns_option.go:96         > Attempting to use provider DNS
2020-04-29T15:47:41.712 INF services/openvpn/client.go:156           > Openvpn client configuration data={"VpnConfig":{"CACertificate":"-----BEGIN CERTIFICATE-----\nMIIBxjCCAWygAwIBAgICBFcwCgYIKoZIzj0EAwIwQjELMAkGA1UEBhMCTFQxGjAY\nBgNVBAoTEU15c3Rlcml1bSBOZXR3b3JrMRcwFQYDVQQLEw5NeXN0ZXJpdW0gVGVh\nbTAeFw0yMDA0MjkxMjQ1NDdaFw0zMDA0MjkxMjQ1NDdaMEIxCzAJBgNVBAYTAkxU\nMRowGAYDVQQKExFNeXN0ZXJpdW0gTmV0d29yazEXMBUGA1UECxMOTXlzdGVyaXVt\nIFRlYW0wWTATBgcqhkjOPQIBBggqhkjOPQMBBwNCAATa9PdAjGkmuJN/O2NrKlr3\nZVTsIgDVdR6ExPxZB9VrtBnaaIDyBm6b3IAxQ0jL3b+zRN202GotbMEER/WRckFz\no1IwUDAOBgNVHQ8BAf8EBAMCAoQwHQYDVR0lBBYwFAYIKwYBBQUHAwIGCCsGAQUF\nBwMBMA8GA1UdEwEB/wQFMAMBAf8wDgYDVR0OBAcEBQECAwQFMAoGCCqGSM49BAMC\nA0gAMEUCIQCBKWq3SlTGX3H1n1ckwWTBOikhAdD9JEc+M0HeMWgHbgIgEcFr1hoP\nBIw5LoAXxy54aujITp8G03jdcB2i19CC/Uc=\n-----END CERTIFICATE-----\n","TLSPresharedKey":"-----BEGIN OpenVPN Static key V1-----\n1921ae4413a648ab9aa43b1e80921cb673c55ec1929201814e6c88a982c87015\n997897ff707691a391ac1b7528078ce86d9a83cbb610b887bf693a4ad78cbc47\n391ef667703d150b57b4fbdbbc8523e495aad44c522782812b4faf53a216b3bb\n699ddd86d8a52f6f1e1aba0d2a3448597539f1910370e744329f661ddc7c0a71\n9d82eb1a475297b08cea85a6c89d87ec79538c226ac94586cf0c2663cc18b9b3\n7a4b16c83dbaaffc6cf4efd0cf684ec0d82f86f8a206ad40a7608fc452fee2bf\n88350d6f64d0745e9e62849d1459840dea4d56c44d98ce9dca4a015e2f4f55db\nba1c0447a2bd59b5fc1c4932f62d0ccf7afacc6ef55e8703b1788d71de19cd5c\n-----END OpenVPN Static key V1-----\n","dns_ips":"10.8.0.1","lport":0,"port":41288,"ports":null,"protocol":"udp","remote":"88.119.191.24"}}
2020-04-29T15:47:41.713 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Binding to socket: 127.0.0.1:0
2020-04-29T15:47:41.713 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Waiting for incoming connection on:  127.0.0.1:50692
2020-04-29T15:47:41.714 INF logconfig/openvpnlog.go:54               > [openvpn-proc] Starting cmd: openvpn with arguments: [--dev tun --cipher AES-256-GCM --verb 3 --tls-cipher TLS-ECDHE-ECDSA-WITH-AES-256-GCM-SHA384 --keepalive 10 60 --ping-timer-rem --persist-key --auth none --reneg-sec 0 --resolv-retry infinite --redirect-gateway def1 bypass-dhcp --up "/Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/config/update-resolv-conf" --down "/Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/config/update-resolv-conf" --dhcp-option DNS 10.8.0.1 --single-session --tls-exit --connect-retry-max 2 --remap-usr1 SIGTERM --client --script-security 2 --auth-nocache --remote 88.119.191.24 --port 49353 --lport 41280 --float --remote-cert-ku 84 --auth-user-pass --management-query-passwords --explicit-exit-notify --ca /Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/ca.crt --tls-crypt /Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/ta.key --dev tun --management 127.0.0.1 50692 --management-client]
2020-04-29T15:47:41.723 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:41 2020 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2020-04-29T15:47:41.724 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:41 2020 OpenVPN 2.4.8 x86_64-apple-darwin18.7.0 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Nov  1 2019
2020-04-29T15:47:41.724 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:41 2020 library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10
2020-04-29T15:47:41.724 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] New connection started
2020-04-29T15:47:41.725 INF firewall/outgoing_firewall_noop.go:40    > Outgoing traffic block requested
2020-04-29T15:47:41.725 DBG core/connection/manager.go:724           > waiting for connected state
2020-04-29T15:47:42.537 DBG session/pingpong/factory.go:250          > Received P2P message for "p2p-payment-invoice": AgreementID:717042320254531983  AgreementTotal:854  Hashlock:"7bb664aa4457c2cef63856d72ea6e53799bddb1814e794a5b151921c5ec7e3c0"  Provider:"0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b"
2020-04-29T15:47:42.537 DBG session/pingpong/invoice_payer.go:139    > Invoice received: {717042320254531983 854 0 7bb664aa4457c2cef63856d72ea6e53799bddb1814e794a5b151921c5ec7e3c0 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b}
2020-04-29T15:47:42.537 DBG session/pingpong/price_calculator.go:67  > Calculated price 137641. Time component: 922, data component: 136719
2020-04-29T15:47:42.538 DBG session/pingpong/invoice_payer.go:180    > Estimated tolerance 1.734, upper bound 238627
2020-04-29T15:47:42.538 DBG session/pingpong/invoice_payer.go:229    > Loaded previous state: already promised: 61008732
2020-04-29T15:47:42.538 DBG session/pingpong/invoice_payer.go:230    > Incrementing promised amount by 854
2020-04-29T15:47:42.539 DBG session/pingpong/exchange_messaging.go:72 > Sending P2P message to "p2p-payment-message": Promise:{ChannelID:"\xaf`\xa7\x85\x1db\xf0\xb1&3\x9c\x08\xbd\x98|\xb0nC\"\x0c"  Amount:61009586  Hashlock:"{\xb6d\xaaDW\xc2\xce\xf68V\xd7.\xa6\xe57\x99\xbd\xdb\x18\x14甥\xb1Q\x92\x1c^\xc7\xe3\xc0"  Signature:"V\xa2\xcc\x1eg\x91\xe1\xc7\x1d\xe7]\xb3\x00\x0f,S[\xa1\x1b(\xf3h\x03\xf0<aЗ\x8ch\xb8\x01M\x1e\x93R\xce\xf3\xe1g\x03\xa9k\xf1J\x83=\xc4\x13\x11\x10A.Ө\x92\xaf\xa4\x14\xa3.\nH'\x1c"}  AgreementID:717042320254531983  AgreementTotal:854  Provider:"0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b"  Signature:"48ca3fe7c5fc0b34ff732e2b165cfd1b864f5fb66361c74decf08bc22e252a383271ee9043d97a6ec70bde304c324160a85fab954561d15e5c1fd99269003c7d1b"
2020-04-29T15:47:42.546 DBG eventbus/event_bus.go:81                 > Published topic="invoice_paid" event={ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Invoice:{AgreementID:717042320254531983 AgreementTotal:854 TransactorFee:0 Hashlock:7bb664aa4457c2cef63856d72ea6e53799bddb1814e794a5b151921c5ec7e3c0 Provider:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b}}
2020-04-29T15:47:42.578 DBG consumer/session/session_storage.go:132  > Session 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 updated
2020-04-29T15:47:42.614 DBG eventbus/event_bus.go:81                 > Published topic="consumer_grand_total_change" event={Current:61009586 AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a}}
2020-04-29T15:47:42.618 DBG eventbus/event_bus.go:81                 > Published topic="balance_change" event={Identity:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} Previous:12338991268 Current:12338990414}
2020-04-29T15:47:42.724 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: Connected to management server at [AF_INET]127.0.0.1:50692
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: CMD 'state on all'
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >PASSWORD:Need 'Auth' username/password
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: SUCCESS: real-time state notification set to ON
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: 1588164462,CONNECTING,,,,,,
2020-04-29T15:47:42.725 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: END
2020-04-29T15:47:42.726 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: CMD 'bytecount 1'
2020-04-29T15:47:42.726 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: SUCCESS: bytecount interval changed
2020-04-29T15:47:42.726 INF logconfig/openvpnlog.go:54               > Starting client user-pass provider middleware
2020-04-29T15:47:42.726 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info
2020-04-29T15:47:42.727 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line not delivered: >INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info
2020-04-29T15:47:42.728 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >PASSWORD:Need 'Auth' username/password
2020-04-29T15:47:42.728 INF logconfig/openvpnlog.go:54               > Authenticating user 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7
2020-04-29T15:47:42.728 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: CMD 'password [...]'
2020-04-29T15:47:42.728 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: SUCCESS: 'Auth' password entered, but not yet verified
2020-04-29T15:47:42.728 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: SUCCESS: 'Auth' username entered, but not yet verified
2020-04-29T15:47:42.729 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: CMD 'username 'Auth' 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7'
2020-04-29T15:47:42.729 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2020-04-29T15:47:42.729 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2020-04-29T15:47:42.731 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2020-04-29T15:47:42.732 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2020-04-29T15:47:42.732 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
2020-04-29T15:47:42.732 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
2020-04-29T15:47:42.732 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]88.119.191.24:49353
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Socket Buffers: R=[786896->786896] S=[9216->9216]
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 UDP link local (bound): [AF_INET][undef]:41280
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 UDP link remote: [AF_INET]88.119.191.24:49353
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: >STATE:1588164462,WAIT,,,,,,
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164462,WAIT,,,,,,
2020-04-29T15:47:42.733 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164462,WAIT,,,,,,
2020-04-29T15:47:42.737 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 MANAGEMENT: >STATE:1588164462,AUTH,,,,,,
2020-04-29T15:47:42.737 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 TLS: Initial packet from [AF_INET]88.119.191.24:49353, sid=85fd16ba d7a05d60
2020-04-29T15:47:42.738 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164462,AUTH,,,,,,
2020-04-29T15:47:42.738 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164462,AUTH,,,,,,
2020-04-29T15:47:42.753 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 VERIFY OK: depth=1, C=LT, O=Mysterium Network, OU=Mysterium Team
2020-04-29T15:47:42.753 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Validating certificate key usage
2020-04-29T15:47:42.753 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 VERIFY KU OK
2020-04-29T15:47:42.753 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 VERIFY OK: depth=0, C=LT, O=Mysterium node operator company, OU=Node operator team, CN=0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b
2020-04-29T15:47:42.768 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 256 bit EC, curve: prime256v1
2020-04-29T15:47:42.768 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:42 2020 [0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b] Peer Connection Initiated with [AF_INET]88.119.191.24:49353
2020-04-29T15:47:42.785 INF core/state/state.go:402                  > Session ID  Connecting duration: 10.2275166s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000009MYST
2020-04-29T15:47:43.794 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:43 2020 MANAGEMENT: >STATE:1588164463,GET_CONFIG,,,,,,
2020-04-29T15:47:43.794 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:43 2020 SENT CONTROL [0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b]: 'PUSH_REQUEST' (status=1)
2020-04-29T15:47:43.795 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164463,GET_CONFIG,,,,,,
2020-04-29T15:47:43.795 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164463,GET_CONFIG,,,,,,
2020-04-29T15:47:44.414 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:45814: i/o timeout"
2020-04-29T15:47:44.414 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:40093: i/o timeout"
2020-04-29T15:47:44.415 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.415 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.418 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:42032: i/o timeout"
2020-04-29T15:47:44.418 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:46681: i/o timeout"
2020-04-29T15:47:44.418 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:45170: i/o timeout"
2020-04-29T15:47:44.418 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.418 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.419 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.421 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:45342: i/o timeout"
2020-04-29T15:47:44.421 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:49155: i/o timeout"
2020-04-29T15:47:44.421 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:40323: i/o timeout"
2020-04-29T15:47:44.421 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:48794: i/o timeout"
2020-04-29T15:47:44.421 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.421 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.422 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.422 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:44.422 DBG nat/traversal/pinger.go:431              > Failed to read remote peer: <nil> - attempting to continue error="read udp4 0.0.0.0:40740: i/o timeout"
2020-04-29T15:47:44.423 WRN nat/traversal/pinger.go:285              > One of the pings has error error="ping receiver error: NAT punch attempt stopped"
2020-04-29T15:47:48.823 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 SENT CONTROL [0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b]: 'PUSH_REQUEST' (status=1)
2020-04-29T15:47:48.834 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 PUSH: Received control message: 'PUSH_REPLY,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.8.0.4 255.255.255.0,peer-id 0,cipher AES-256-GCM'
2020-04-29T15:47:48.834 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: timers and/or timeouts modified
2020-04-29T15:47:48.834 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: --ifconfig/up options modified
2020-04-29T15:47:48.834 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: route-related options modified
2020-04-29T15:47:48.834 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: peer-id set
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: adjusting link_mtu to 1624
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 OPTIONS IMPORT: data channel crypto options modified
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 Opening utun (connect(AF_SYS_CONTROL)): Resource busy (errno=16)
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 Opened utun device utun1
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 MANAGEMENT: >STATE:1588164468,ASSIGN_IP,,10.8.0.4,,,,
2020-04-29T15:47:48.835 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 /sbin/ifconfig utun1 delete
2020-04-29T15:47:48.837 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stderr: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-04-29T15:47:48.837 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
2020-04-29T15:47:48.838 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 /sbin/ifconfig utun1 10.8.0.4 10.8.0.4 netmask 255.255.255.0 mtu 1500 up
2020-04-29T15:47:48.840 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 /sbin/route add -net 10.8.0.0 10.8.0.4 255.255.255.0
2020-04-29T15:47:48.843 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: add net 10.8.0.0: gateway 10.8.0.4
2020-04-29T15:47:48.844 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:48 2020 /Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/config/update-resolv-conf utun1 1500 1552 10.8.0.4 255.255.255.0 init
2020-04-29T15:47:48.880 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: dhcp-option DNS 10.8.0.1
2020-04-29T15:47:48.880 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for LPSS Serial Adapter (1)
2020-04-29T15:47:48.914 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for LPSS Serial Adapter (2)
2020-04-29T15:47:49.014 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for EDIMAX AX88179 USB 3.0 to Gigabit Ethernet
2020-04-29T15:47:49.162 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for USB 10/100/1000 LAN
2020-04-29T15:47:49.265 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for iPad USB
2020-04-29T15:47:49.359 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for iPhone USB
2020-04-29T15:47:49.455 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Wi-Fi
2020-04-29T15:47:49.553 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Bluetooth PAN
2020-04-29T15:47:49.631 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Thunderbolt Bridge
2020-04-29T15:47:49.689 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for zolia-fai-wg-tunnel
2020-04-29T15:47:49.791 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:49 2020 /sbin/route add -net 88.119.191.24 192.168.88.1 255.255.255.255
2020-04-29T15:47:49.804 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164468,ASSIGN_IP,,10.8.0.4,,,,
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164469,CONNECTED,SUCCESS,10.8.0.4,88.119.191.24,49353,,
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: add net 88.119.191.24: gateway 192.168.88.1
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164468,ASSIGN_IP,,10.8.0.4,,,,
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164469,CONNECTED,SUCCESS,10.8.0.4,88.119.191.24,49353,,
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:49 2020 /sbin/route add -net 0.0.0.0 10.8.0.1 128.0.0.0
2020-04-29T15:47:49.815 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: add net 0.0.0.0: gateway 10.8.0.1
2020-04-29T15:47:49.815 DBG core/connection/manager.go:734           > Connected started event received
2020-04-29T15:47:49.816 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:49 2020 /sbin/route add -net 128.0.0.0 10.8.0.1 128.0.0.0
2020-04-29T15:47:49.816 DBG core/connection/manager.go:759           > Connection state received: Connected
2020-04-29T15:47:49.816 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: add net 128.0.0.0: gateway 10.8.0.1
2020-04-29T15:47:49.816 DBG core/connection/manager.go:470           > Sending P2P message to "p2p-session-acknowledge": consumerID:"0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a"  sessionID:"7d8f3bac-30a1-49e8-a147-862fd8e5ccb7"
2020-04-29T15:47:49.816 INF core/connection/manager.go:624           > Connection state: Connecting -> Connected
2020-04-29T15:47:49.816 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:49 2020 Initialization Sequence Completed
2020-04-29T15:47:49.816 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:49 2020 MANAGEMENT: >STATE:1588164469,CONNECTED,SUCCESS,10.8.0.4,88.119.191.24,49353,,
2020-04-29T15:47:49.816 DBG eventbus/event_bus.go:81                 > Published topic="State" event={State:Connected SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Connected SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:49.816 DBG core/location/oracle_resolver.go:41      > Detecting with oracle resolver
2020-04-29T15:47:49.816 INF core/state/state.go:359                  > Session ID 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Connected duration: 17.258449102s data: 2.0KiB/1.3KiB, throughput: 1.9KiBs/1.2KiBs, spent: 0.000009MYST
2020-04-29T15:47:49.816 INF cmd/di.go:860                            > Reconnecting HTTP clients due to VPN connection state change
2020-04-29T15:47:49.816 INF communication/nats/connector.go:85       > Attempting to reconnect to broker (1 connections)
2020-04-29T15:47:49.817 INF communication/nats/connector.go:91       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03
2020-04-29T15:47:49.821 INF communication/nats/connector.go:95       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03 DONE
2020-04-29T15:47:49.822 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-04-29T15:47:49.822 INF communication/nats/connector.go:100      > All broker connections re-established
2020-04-29T15:47:49.978 WRN communication/nats/connection_wrap.go:87 > NATS: reconnected
2020-04-29T15:47:50.169 DBG core/ip/resolver.go:103                  > IP detected: 88.119.191.24
2020-04-29T15:47:50.169 DBG core/connection/manager.go:326           > Sending session status P2P message to "p2p-session-connectivity-status": ConsumerID:"0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a"  SessionID:"7d8f3bac-30a1-49e8-a147-862fd8e5ccb7"  Code:1000
2020-04-29T15:47:50.178 DBG core/location/cache.go:95                > Location update succeeded: {88.119.191.24 8764 Telia Lietuva EU LT Vilnius residential}
2020-04-29T15:47:51.338 DBG core/ip/resolver.go:103                  > IP detected: 88.119.191.24
2020-04-29T15:47:51.339 DBG core/location/oracle_resolver.go:41      > Detecting with oracle resolver
2020-04-29T15:47:53.329 INF core/connection/manager.go:624           > Connection state: Connected -> Disconnecting
2020-04-29T15:47:53.329 INF firewall/outgoing_firewall_noop.go:42    > Outgoing traffic block removed
2020-04-29T15:47:53.329 DBG core/connection/manager.go:822           > Stopping p2p keepalive: context canceled
2020-04-29T15:47:53.329 DBG eventbus/event_bus.go:81                 > Published topic="State" event={State:Disconnecting SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Disconnecting SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:53.329 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Shutdown
2020-04-29T15:47:53.329 INF core/connection/stats_publisher.go:62    > Stopped publishing connection statistics
2020-04-29T15:47:53.329 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:53 2020 event_wait : Interrupted system call (code=4)
2020-04-29T15:47:53.329 INF core/state/state.go:359                  > Session ID 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Disconnecting duration: 20.7716561s data: 107.2KiB/50.2KiB, throughput: 26.6KiBs/8.5KiBs, spent: 0.000009MYST
2020-04-29T15:47:53.329 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Shutdown finished
2020-04-29T15:47:53.329 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:53 2020 SIGTERM received, sending exit notification to peer
2020-04-29T15:47:54.000 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:54 2020 /sbin/route delete -net 88.119.191.24 192.168.88.1 255.255.255.255
2020-04-29T15:47:54.003 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: delete net 88.119.191.24: gateway 192.168.88.1
2020-04-29T15:47:54.003 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:54 2020 /sbin/route delete -net 0.0.0.0 10.8.0.1 128.0.0.0
2020-04-29T15:47:54.005 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: delete net 0.0.0.0: gateway 10.8.0.1
2020-04-29T15:47:54.006 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:54 2020 /sbin/route delete -net 128.0.0.0 10.8.0.1 128.0.0.0
2020-04-29T15:47:54.008 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: delete net 128.0.0.0: gateway 10.8.0.1
2020-04-29T15:47:54.008 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:54 2020 Closing TUN/TAP interface
2020-04-29T15:47:54.009 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:54 2020 /Users/zolia/golang/src/github.com/mysteriumnetwork/node/build/myst/config/update-resolv-conf utun1 1500 1552 10.8.0.4 255.255.255.0 init
2020-04-29T15:47:54.061 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for LPSS Serial Adapter (1)
2020-04-29T15:47:54.196 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for LPSS Serial Adapter (2)
2020-04-29T15:47:54.327 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for EDIMAX AX88179 USB 3.0 to Gigabit Ethernet
2020-04-29T15:47:54.487 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for USB 10/100/1000 LAN
2020-04-29T15:47:54.647 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for iPad USB
2020-04-29T15:47:54.808 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for iPhone USB
2020-04-29T15:47:54.924 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Wi-Fi
2020-04-29T15:47:55.058 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Bluetooth PAN
2020-04-29T15:47:55.178 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for Thunderbolt Bridge
2020-04-29T15:47:55.266 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: updating dns for zolia-fai-wg-tunnel
2020-04-29T15:47:55.402 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:55 2020 SIGTERM[soft,exit-with-notification] received, process exiting
2020-04-29T15:47:55.402 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Wed Apr 29 15:47:55 2020 MANAGEMENT: >STATE:1588164475,EXITING,exit-with-notification,,,,,
2020-04-29T15:47:55.402 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1588164475,EXITING,exit-with-notification,,,,,
2020-04-29T15:47:55.402 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Connection failed to read: EOF
2020-04-29T15:47:55.402 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1588164475,EXITING,exit-with-notification,,,,,
2020-04-29T15:47:55.403 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Event consumer is done
2020-04-29T15:47:55.403 DBG core/connection/manager.go:759           > Connection state received: Disconnecting
2020-04-29T15:47:55.403 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Middleware stop error: connection is gone
2020-04-29T15:47:55.403 DBG core/connection/manager.go:754           > State updater stopCalled
2020-04-29T15:47:55.403 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Middleware stop error: write tcp 127.0.0.1:50692->127.0.0.1:50693: write: broken pipe
2020-04-29T15:47:55.403 INF logconfig/openvpnlog.go:54               > [openvpn-proc] Stderr: stream ended
2020-04-29T15:47:55.403 INF firewall/outgoing_firewall_noop.go:50    > Rule for IP: 88.119.191.24 removed
2020-04-29T15:47:55.403 INF logconfig/openvpnlog.go:54               > [openvpn-proc] Stdout: stream ended
2020-04-29T15:47:55.403 INF core/connection/manager.go:717           > Connection exited
2020-04-29T15:47:55.404 DBG session/pingpong/invoice_payer.go:265    > Stopping...
2020-04-29T15:47:55.404 DBG eventbus/event_bus.go:81                 > Published topic="Session" event={Status:Ended SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Disconnecting SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:55.434 DBG consumer/session/session_storage.go:154  > Session 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 updated with final data
2020-04-29T15:47:55.438 DBG consumer/statistics/reporter.go:137      > Session statistics reporter stopping
2020-04-29T15:47:55.438 INF core/connection/manager.go:624           > Connection state: Disconnecting -> NotConnected
2020-04-29T15:47:55.439 DBG core/connection/manager.go:487           > Sending P2P message to "p2p-session-destroy": consumerID:"0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a"  sessionID:"7d8f3bac-30a1-49e8-a147-862fd8e5ccb7"
2020-04-29T15:47:55.439 DBG eventbus/event_bus.go:81                 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2020-04-29 15:47:32.558113 +0300 EEST m=+55.491064056 ConsumerID:{Address:0x0fc008021a33ee21a6d2c9dbb2a547fd8fc0b84a} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:NotConnected SessionID:7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:openvpn ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:8764 ISP:Telia Lietuva NodeType:residential} SessionBandwidth:8.388608e+07 Protocol:udp} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:1m0s Bytes:7669584 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b ProviderContacts:[{Type:nats/v1 Definition:{Topic:0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b.openvpn BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-04-29T15:47:55.439 INF cmd/di.go:860                            > Reconnecting HTTP clients due to VPN connection state change
2020-04-29T15:47:55.439 INF core/state/state.go:359                  > Session ID 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7 NotConnected duration: 22.881415331s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-04-29T15:47:55.439 DBG core/location/oracle_resolver.go:41      > Detecting with oracle resolver
2020-04-29T15:47:55.440 INF communication/nats/connector.go:85       > Attempting to reconnect to broker (1 connections)
2020-04-29T15:47:55.440 INF communication/nats/connector.go:91       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03
2020-04-29T15:47:55.445 INF communication/nats/connector.go:95       > Re-establishing broker connection d16de09f-bed0-4300-b99f-860df7acfa03 DONE
2020-04-29T15:47:55.445 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-04-29T15:47:55.445 INF communication/nats/connector.go:100      > All broker connections re-established
2020-04-29T15:47:55.550 WRN communication/nats/connection_wrap.go:87 > NATS: reconnected
2020-04-29T15:47:55.721 DBG core/location/cache.go:95                > Location update succeeded: {78.157.70.161 21211 Penki EU LT Vilnius business}
2020-04-29T15:47:56.030 INF market/mysterium/mysterium_api.go:309    > Session stats sent: 7d8f3bac-30a1-49e8-a147-862fd8e5ccb7
2020-04-29T15:47:56.030 DBG consumer/statistics/reporter.go:109      > Final stats sent
2020-04-29T15:50:23.406 DBG communication/nats/receiver.go:54        > Message "*.proposal-unregister" received: {"proposal":{"id":1,"format":"service-proposal/v1","service_type":"openvpn","service_definition":{"location":{"continent":"NA","country":"US","city":"New Jersey","asn":701,"isp":"Verizon Fios","node_type":"residential"},"location_originate":{"continent":"NA","country":"US","city":"New Jersey","asn":701,"isp":"Verizon Fios","node_type":"residential"},"session_bandwidth":83886080,"protocol":"udp"},"payment_method_type":"BYTES_TRANSFERRED_WITH_TIME","payment_method":{"price":{"amount":50000,"currency":"MYST"},"duration":60000000000,"bytes":7669584,"type":"BYTES_TRANSFERRED_WITH_TIME"},"provider_id":"0x7d8c5548147d9314a792c3c307235550aaefc53e","provider_contacts":[{"type":"nats/v1","definition":{"topic":"0x7d8c5548147d9314a792c3c307235550aaefc53e.openvpn","broker_addresses":["nats://testnet-broker.mysterium.network:4222"]}}]}}
^C2020-04-29T16:03:46.483 INF cmd/commands/daemon/command.go:65        > Stopping application
2020-04-29T16:03:46.496 INF nat/service_ipforward.go:68              > IP forwarding disabled
2020-04-29T16:03:46.514 DBG nat/service_pfctl.go:188                 > "/sbin/pfctl -F nat" output:
No ALTQ support in kernel
ALTQ related functions disabled
nat cleared

2020-04-29T16:03:46.515 INF nat/service_pfctl.go:192                 > NAT rules cleared
2020-04-29T16:03:46.524 INF communication/nats/receiver.go:99        > Unsubscribed from *.proposal-ping
2020-04-29T16:03:46.524 INF communication/nats/receiver.go:99        > Unsubscribed from *.proposal-unregister
2020-04-29T16:03:46.524 INF communication/nats/receiver.go:99        > Unsubscribed from *.proposal-register
2020-04-29T16:03:46.524 INF communication/nats/connector.go:71       > Removing broker connection from the registry: d16de09f-bed0-4300-b99f-860df7acfa03
2020-04-29T16:03:46.524 INF firewall/outgoing_firewall_noop.go:61    > Rule for URL: nats://testnet-broker.mysterium.network:4222 removed
2020-04-29T16:03:46.525 INF firewall/incoming_firewall_noop.go:38    > Rules reset was requested
2020-04-29T16:03:46.524 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-04-29T16:03:46.525 INF firewall/outgoing_firewall_noop.go:35    > Rules reset was requested
2020-04-29T16:03:46.525 WRN communication/nats/connection_wrap.go:85 > NATS: connection closed
2020-04-29T16:03:46.525 INF core/node/node.go:97                     > No active connection - proceeding
2020-04-29T16:03:46.525 INF core/node/node.go:106                    > API stopped
2020-04-29T16:03:46.525 DBG eventbus/event_bus.go:81                 > Published topic="Node" event={Status:Stopped}
2020-04-29T16:03:46.525 INF identity/registry/provider_registrar.go:209 > Stopping provider registrar
2020-04-29T16:03:46.525 INF ui/server.go:123                         > Server stopped
2020-04-29T16:03:46.525 DBG identity/registry/registry_contract.go:132 > event received {Stopped}
2020-04-29T16:03:46.525 INF session/pingpong/accountant_promise_settler.go:277 > Stopped listening for settlement events
2020-04-29T16:03:46.525 INF identity/registry/registry_contract.go:272 > Stopping registry...
2020-04-29T16:03:46.525 INF core/node/node.go:109                    > Web UI server stopped
2020-04-29T16:03:46.526 INF core/node/node.go:112                    > NAT pinger stopped

full log:

settle.log

vkuznecovas commented 4 years ago

2020-04-29T14:54:00.305 INF session/pingpong/accountant_promise_settler.go:159 > Loaded state for provider {“0x816c8cf15593824a772159541a9d67bd41a4ecc8”}: balance 0, available balance 0, unsettled balance 0

is the culprit. This should load proper info, like this: 2020-04-29T16:07:15.357 INF session/pingpong/accountant_promise_settler.go:159 > Loaded state for provider {“0xb8bbafc992fa207ac2877633a23dbb278b813a76”}: balance 6200000000, available balance 6200000000, unsettled balance 0

vkuznecovas commented 4 years ago

So this might happen after a fresh registration for provider. If the state fails to load from blockchain, the balance is assumed 0. This means that upon getting a payment from accountant, the provider will have a tiny bit of myst and detect that. However, the settler will also try to settle the promise, as he really needs the balance to be able to provide service.

There's 3 relevant todos in the node/session/pingpong/accountant_promise_settler.go.

Search for:TODO: should we retry?. Decide what to do with the initial state if we can't perform those actions. Do we quit? Do we stop service? Do we wait and retry fetching?

vkuznecovas commented 4 years ago

Dup #1422