search

mysteriumnetwork / node

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

Connection from desktop fails while it works from android app #2402

Closed chompomonim closed 4 years ago

chompomonim commented 4 years ago

Describe the bug There are quite a few nodes (e.g. 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f) where I'm not getting traffic from desktop app. It connects to node, but I can't browse the Internet (pings to IP address also doesn't works.

When connecting to the same node from android app, everything works fine, connection if stable and bandwidth is good.

To Reproduce Steps to reproduce the behavior:

  1. Install latest desktop app for Windows or macOS. Version 2.2.0
  2. Connect to node 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f
  3. After you'll see "Your connection is secure" try browsing the Internet.
  4. Pings and browsing don't work.
  5. Lanch latest android app (0.34.1 beta).
  6. Connect to the same node.
  7. Try browsing and everything works fine.

Screenshots Screenshot 2020-06-23 at 23 58 10

Environment (please complete the following information):

Consumer app logs

2020-06-24T00:13:41.567 INF source/tequilapi/endpoints/connection.go:161 > identity "0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5" is registered, continuing...
2020-06-24T00:13:41.809 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2020-06-24T00:13:41.809 INF source/core/connection/manager.go:574    > Connection state: NotConnected -> Connecting
2020-06-24T00:13:41.809 DBG source/communication/nats/connector.go:39 > Connecting to NATS servers: nats://testnet-broker.mysterium.network:4222
2020-06-24T00:13:41.809 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet-broker.mysterium.network:4222 access
2020-06-24T00:13:41.809 DBG source/eventbus/event_bus.go:81          > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2020-06-24 00:13:41.809448 +0300 EEST m=+9434.873346582 ConsumerID:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5} 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:wireguard ServiceDefinition:{Location:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting} LocationOriginate:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:5m0s Bytes:5368709 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xca08774b25cf9497af7e4911fc3a538d5ac9b27f ProviderContacts:[{Type:nats/v1 Definition:{}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-06-24T00:13:41.810 INF source/core/state/state.go:359           > Session ID  Connecting duration: 645.322µs data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-06-24T00:13:42.095 DBG source/p2p/dialer.go:144                 > Consumer 0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5 sending public key b5db1f55d085fad647f0a5b72713a7b18110f6e3c0ef133c370c1829d169dc6e to provider 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f
2020-06-24T00:13:42.781 DBG source/p2p/dialer.go:171                 > Consumer 0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5 received provider 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f with config: publicIP:"94.237.15.67" ports:46296 ports:42907
2020-06-24T00:13:42.781 DBG source/core/ip/cached_resolver.go:79     > Public IP cache is empty, fetching IP
2020-06-24T00:13:43.456 DBG source/core/ip/resolver.go:101           > IP detected: 213.101.138.37
2020-06-24T00:13:43.457 INF source/core/port/pool.go:68              > Supplying port 45104
2020-06-24T00:13:43.457 INF source/core/port/pool.go:68              > Supplying port 40515
2020-06-24T00:13:43.457 DBG source/p2p/dialer.go:194                 > Consumer 0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5 sending ack with encrypted config to provider 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f
2020-06-24T00:13:43.688 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 94.237.15.67 access
2020-06-24T00:13:43.689 DBG source/p2p/dialer.go:99                  > Skipping provider ping
2020-06-24T00:13:43.689 DBG source/p2p/dialer.go:121                 > Received handlers ready message from provider
2020-06-24T00:13:43.690 DBG source/p2p/channel.go:200                > Creating p2p channel with local addr: 192.168.0.134:45104, UDP session addr: 127.0.0.1:56929, proxy addr: 127.0.0.1:52989, remote peer addr: x.x.x.x:46296
2020-06-24T00:13:43.690 DBG source/p2p/channel.go:519                > Will use service conn with local port: 40515, remote port: 42907
2020-06-24T00:13:43.690 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet-broker.mysterium.network:4222 removed
2020-06-24T00:13:43.690 WRN source/communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-06-24T00:13:43.690 WRN source/communication/nats/connection_wrap.go:85 > NATS: connection closed
2020-06-24T00:13:43.690 DBG source/session/pingpong/invoice_payer.go:120 > Starting...
2020-06-24T00:13:43.690 DBG source/core/connection/manager.go:441    > Sending P2P message to "p2p-session-create": consumer:{id:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5" accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318" paymentVersion:"v3"} proposalID:1 config:"{\"PublicKey\":\"JTu40dkNkgfODOPFqzrBrSSefxw5qPdc/WXRVJzJPkc=\",\"Ports\":null}"
2020-06-24T00:13:44.239 INF source/core/connection/manager.go:454    > Provider's session config: {"local_port":0,"remote_port":0,"ports":null,"provider":{"public_key":"iCT3YeeFPBP1dX0I4EM8iEm0TgotKYa98aU7MpaZ0Ck=","endpoint":"94.237.15.67:42907"},"consumer":{"ip_address":"10.182.1.2/24","dns_ips":"10.182.1.1","connect_delay":2000}}
2020-06-24T00:13:44.239 DBG source/eventbus/event_bus.go:81          > Published topic="Session" event={Status:Created SessionInfo:{StartedAt:2020-06-24 00:13:41.809448 +0300 EEST m=+9434.873346582 ConsumerID:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Connecting SessionID:96b4fb7e-c2de-48a4-870d-adf6837156d1 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting} LocationOriginate:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:5m0s Bytes:5368709 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xca08774b25cf9497af7e4911fc3a538d5ac9b27f ProviderContacts:[{Type:nats/v1 Definition:{}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-06-24T00:13:44.266 DBG source/consumer/session/session_storage.go:178 > Session 96b4fb7e-c2de-48a4-870d-adf6837156d1 saved
2020-06-24T00:13:44.266 DBG source/consumer/statistics/reporter.go:123 > Session statistics reporter started
2020-06-24T00:13:44.267 DBG source/core/ip/cached_resolver.go:75     > Found cached public IP
2020-06-24T00:13:44.267 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 94.237.15.67 access
2020-06-24T00:13:44.267 DBG source/core/connection/dns_option.go:85  > Selecting DNS servers using strategy: system
2020-06-24T00:13:44.267 INF source/services/wireguard/connection/connection.go:130 > Starting new connection
2020-06-24T00:13:44.267 DBG source/config/config.go:177              > Returning CLI value usermode:true
2020-06-24T00:13:44.267 DBG source/services/wireguard/endpoint/remoteclient/client.go:40 > Creating remote wg client
2020-06-24T00:13:44.267 INF source/services/wireguard/connection/connection.go:167 > Starting connection endpoint
2020-06-24T00:13:44.271 WRN source/services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun0 error="failed to destroy wg interface: failed to down wg interface utun0: interface utun0 not found"
2020-06-24T00:13:44.271 INF source/services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun0
2020-06-24T00:13:44.271 WRN source/services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun1 error="failed to destroy wg interface: failed to down wg interface utun1: interface utun1 not found"
2020-06-24T00:13:44.272 INF source/services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun1
2020-06-24T00:13:44.272 DBG source/services/wireguard/endpoint/endpoint.go:61 > Allocated interface: utun2
2020-06-24T00:13:44.422 DBG source/services/wireguard/endpoint/remoteclient/client.go:65 > Tunnel interface created: utun2
2020-06-24T00:13:44.422 INF source/services/wireguard/connection/connection.go:150 > Adding connection peer 94.237.15.67:42907
2020-06-24T00:13:44.422 INF source/services/wireguard/connection/connection.go:152 > Waiting for initial handshake
2020-06-24T00:13:44.603 DBG source/core/ip/cached_resolver.go:59     > Outbound IP cache is empty, fetching IP
2020-06-24T00:13:44.604 INF source/firewall/outgoing_firewall_noop.go:40 > Outgoing traffic block requested
2020-06-24T00:13:44.604 DBG source/core/connection/manager.go:674    > waiting for connected state
2020-06-24T00:13:44.604 DBG source/core/connection/manager.go:709    > Connection state received: Connecting
2020-06-24T00:13:44.604 DBG source/core/connection/manager.go:684    > Connected started event received
2020-06-24T00:13:44.604 DBG source/core/connection/manager.go:709    > Connection state received: Connected
2020-06-24T00:13:44.604 INF source/core/connection/manager.go:574    > Connection state: Connecting -> Connected
2020-06-24T00:13:44.604 DBG source/core/connection/manager.go:461    > Sending P2P message to "p2p-session-acknowledge": consumerID:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5" sessionID:"96b4fb7e-c2de-48a4-870d-adf6837156d1"
2020-06-24T00:13:44.605 DBG source/core/ip/cached_resolver.go:91     > Clearing ip resolver cache
2020-06-24T00:13:44.605 DBG source/eventbus/event_bus.go:81          > Published topic="State" event={State:Connected SessionInfo:{StartedAt:2020-06-24 00:13:41.809448 +0300 EEST m=+9434.873346582 ConsumerID:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State:Connected SessionID:96b4fb7e-c2de-48a4-870d-adf6837156d1 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting} LocationOriginate:{Continent:EU Country:RU City:Unknown ASN:202053 ISP:UpCloud Ltd NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:5m0s Bytes:5368709 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xca08774b25cf9497af7e4911fc3a538d5ac9b27f ProviderContacts:[{Type:nats/v1 Definition:{}} {Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
2020-06-24T00:13:44.605 DBG source/core/ip/cached_resolver.go:79     > Public IP cache is empty, fetching IP
2020-06-24T00:13:44.605 DBG source/core/connection/manager.go:177    > Consumer connection trace: "Whole Connect" took 2.795735476s, "P2P channel creation" took 1.880943597s, "Session creation" took 576.608044ms, "Start connection" took 337.800062ms
2020-06-24T00:13:44.605 INF source/cmd/di.go:826                     > Reconnecting HTTP clients due to VPN connection state change
2020-06-24T00:13:44.605 DBG source/core/location/oracle_resolver.go:41 > Detecting with oracle resolver
2020-06-24T00:13:44.605 INF source/core/state/state.go:359           > Session ID 96b4fb7e-c2de-48a4-870d-adf6837156d1 Connected duration: 2.796008384s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-06-24T00:13:45.271 DBG source/core/ip/resolver.go:101           > IP detected: 94.237.15.67
2020-06-24T00:13:45.272 DBG source/core/connection/manager.go:327    > Sending session status P2P message to "p2p-session-connectivity-status": ConsumerID:"0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5" SessionID:"96b4fb7e-c2de-48a4-870d-adf6837156d1" Code:1000
2020-06-24T00:13:45.274 DBG source/core/location/cache.go:95         > Location update succeeded: {94.237.15.67 202053 UpCloud Ltd EU RU Unknown hosting}
2020-06-24T00:13:45.274 DBG source/core/location/oracle_resolver.go:41 > Detecting with oracle resolver
2020-06-24T00:13:45.371 DBG source/session/pingpong/factory.go:188   > Received P2P message for "p2p-payment-invoice": AgreementID:179327695230493421 AgreementTotal:575 Hashlock:"7ac8ae95288705e4f3663f11a8762a33c36cc2db76f8cf5b1a37a9c847f8ee87" Provider:"0xca08774b25cf9497af7e4911fc3a538d5ac9b27f"
2020-06-24T00:13:45.371 DBG source/session/pingpong/invoice_payer.go:139 > Invoice received: {179327695230493421 575 0 7ac8ae95288705e4f3663f11a8762a33c36cc2db76f8cf5b1a37a9c847f8ee87 0xca08774b25cf9497af7e4911fc3a538d5ac9b27f}
2020-06-24T00:13:45.372 DBG source/session/pingpong/price_calculator.go:67 > Calculated price 195593. Time component: 280, data component: 195313
2020-06-24T00:13:45.372 DBG source/session/pingpong/invoice_payer.go:180 > Estimated tolerance 1.695, upper bound 331535
2020-06-24T00:13:45.372 DBG source/session/pingpong/invoice_payer.go:229 > Loaded previous state: already promised: 301182469
2020-06-24T00:13:45.372 DBG source/session/pingpong/invoice_payer.go:230 > Incrementing promised amount by 575
2020-06-24T00:13:45.373 DBG source/session/pingpong/exchange_messaging.go:65 > Sending P2P message to "p2p-payment-message": Promise:{ChannelID:"\x19\xdf\x1f\xfa9\xa5\x18\xc3h,b)\xf3Bʸ\xa7\x1c\xb2/" Amount:301183044 Hashlock:"zȮ\x95(\x87\x05\xe4\xf3f?\x11\xa8v*3\xc3l\xc2\xdbv\xf8\xcf[\x1a7\xa9\xc8G\xf8\xee\x87" Signature:"ќ\xa3e\xc3VZ\x87\xb0\x0e\xce\x16\xb5\xff\xacX{O\x96ǤS\x14\x11\x8c\xd7q\x0e\xf3;&ev3[\xc8\xdc3\x02\x8bW\xfc\xb1\xa3),Ǖ\xb8\x84\xffB\xfa)\xfag\x9c\x8d\xcc\x0c\xe2E\xb3\t\x1c"} AgreementID:179327695230493421 AgreementTotal:575 Provider:"0xca08774b25cf9497af7e4911fc3a538d5ac9b27f" Signature:"a68cd2249ef9469776bfa7ee7663377cfb64ac5006ce5020d69f6eed02173aae64fd989756e81aeff503709ce3aec4364289edc39f232f6bce4cebf8bf4cee9c1b" HermesID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"
2020-06-24T00:13:45.425 DBG source/eventbus/event_bus.go:81          > Published topic="invoice_paid" event={ConsumerID:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5} SessionID:96b4fb7e-c2de-48a4-870d-adf6837156d1 Invoice:{AgreementID:179327695230493421 AgreementTotal:575 TransactorFee:0 Hashlock:7ac8ae95288705e4f3663f11a8762a33c36cc2db76f8cf5b1a37a9c847f8ee87 Provider:0xca08774b25cf9497af7e4911fc3a538d5ac9b27f}}
2020-06-24T00:13:45.446 DBG source/consumer/session/session_storage.go:132 > Session 96b4fb7e-c2de-48a4-870d-adf6837156d1 updated
2020-06-24T00:13:45.466 DBG source/eventbus/event_bus.go:81          > Published topic="consumer_grand_total_change" event={Current:301183044 AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] ConsumerID:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5}}
2020-06-24T00:13:45.466 DBG source/eventbus/event_bus.go:81          > Published topic="balance_change" event={Identity:{Address:0x76db93bf29861aef7f9bdf3c7c3a290d1afde0e5} Previous:603679642 Current:552504454}
2020-06-24T00:13:45.647 INF source/core/state/state.go:402           > Session ID 96b4fb7e-c2de-48a4-870d-adf6837156d1 Connected duration: 3.83823385s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000006MYST
etherunit commented 4 years ago

Same to me with 0x64c54964dca1745b761d0c17a7299b87edde3d31 (0.35). Connected but internet is not working.

zolia commented 4 years ago

It looks like we are already using too new desktop app. This is what you can see from cli logs: 

2020-06-25T16:34:19.767 WRN core/connection/manager.go:467           > Acknowledge failed error="internal peer error"

meaning that provider does not understand our message.

Mobile still is on a bit older version. I think we are not compatible with 0.32 already.

chompomonim commented 4 years ago

@etherunit could you please get logs from such providers?

etherunit commented 4 years ago

0xca08774b25cf9497af7e4911fc3a538d5ac9b27f has upgraded to 0.35.3. Will check others.

connected 2.3.3 Mac app > 0.35.3 node (0x64c54964dca1745b761d0c17a7299b87edde3d31) got same results- still (Updating..)

Screenshot 2020-07-07 at 17 28 04

Node logs https://my.mysterium.network/admin/issues/download/768 mysteriumnetwork/node-user-reports#768

p.s. When connecting to the same node from Android app, everything works normally.

chompomonim commented 4 years ago

I found a interesting case. Here is node id: 0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0

I can connect to it using 0.36 android app while on WIFI. When switching to mobile traffic, connection failing.

Node logs while connecting via WIFI:

Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.978 DBG p2p/listener.go:209                      > Received consumer public key f2dd4cb6c339064184661b156d3f3c9b17cff2c16b257435f9cf1bf44b8f771c
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.978 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.978 INF core/port/pool.go:68                     > Supplying port 48907
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.978 INF core/port/pool.go:68                     > Supplying port 43568
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.979 DBG nat/mapping/port_mapping.go:119          > Detected router public IP address: 213.101.138.37
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.984 INF nat/mapping/port_mapping.go:149          > Mapped network port: 48907
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.984 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:42:44 grin-miner myst[1673]: 2020-07-11T11:42:44.984 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.284 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.285 DBG nat/mapping/port_mapping.go:119          > Detected router public IP address: 213.101.138.37
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.291 INF nat/mapping/port_mapping.go:149          > Mapped network port: 43568
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.291 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.291 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.591 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:42:45 grin-miner myst[1673]: 2020-07-11T11:42:45.592 DBG p2p/listener.go:244                      > Sending reply with public key f558acb5967493d69abe18571ba17641efd6c8120fe3adc9977c8f932dc95d09 and encrypted config to consumer
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.541 DBG session/pingpong/price_calculator.go:67  > Calculated price 10692. Time component: 5054, data component: 5638
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.662 DBG p2p/listener.go:328                      > Decrypted consumer config: publicIP:"78.61.246.140" ports:44312 ports:41752
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.662 DBG p2p/listener.go:147                      > Skipping consumer ping
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.662 DBG p2p/channel.go:200                       > Creating p2p channel with local addr: 192.168.0.186:48907, UDP session addr: 127.0.0.1:59899, proxy addr: 127.0.0.1:56176, remote peer addr: x.x.x.x:44312
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.662 DBG p2p/channel.go:519                       > Will use service conn with local port: 43568, remote port: 41752
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.662 DBG p2p/listener.go:349                      > Sending handlers ready message
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.663 DBG p2p/listener.go:137                      > Delaying pings from consumer for 100 ms
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.858 DBG core/service/subscription.go:64          > Received P2P message for "p2p-session-create": consumer:{id:"0x53a51a8bb055187a21ad5fcbdf2ea4e11ba3cd71" accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318" paymentVersion:"v3"} proposalID:1 config:"{\"PublicKey\":\"eT9csPJYYSvHhpDgAp6J/RlvEqwWvadBpUVxWrtDV3o=\",\"Ports\":null}"
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.858 INF session/manager.go:175                   > Using new payments
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.859 INF session/manager.go:195                   > Waiting for a first invoice to be paid
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.859 DBG session/pingpong/invoice_tracker.go:268  > Starting...
Jul 11 11:42:46 grin-miner myst[1673]: 2020-07-11T11:42:46.960 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.034 DBG session/pingpong/price_calculator.go:67  > Calculated price 137. Time component: 137, data component: 0
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.034 DBG session/pingpong/invoice_tracker.go:449  > Being lenient for the first payment, asking for 1
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.034 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:18385847886580395516 AgreementTotal:1 Hashlock:"2d39f1621b24d052db52ea8030af877a4b7daf71d5f33f123e335dde6e2a1ad9" Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"
Jul 11 11:42:48 grin-miner myst[1673]: [802B blob data]
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.322 DBG eventbus/event_bus.go:81                 > Published topic="Service session" event={Status:Created SessionInfo:{StartedAt:0001-01-01 00:00:00 +0000 UTC ConsumerID:{Address:0x53a51a8bb055187a21ad5fcbdf2ea4e11ba3cd71} AccountantID:[2 20 40 28 241 92 26 102 181 25 144 226 230 94 31 123 124 54 51 24] State: SessionID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:1257 ISP:Tele2 Lithuania NodeType:cellular} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:1257 ISP:Tele2 Lithuania NodeType:cellular}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:7m8.632661808s Bytes:53687091 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.323 DBG consumer/session/session_storage.go:257  > Session e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf saved
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.323 INF services/wireguard/service/service_unix.go:114 > Accepting new WireGuard connection
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.323 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.323 DBG config/config.go:186                     > Returning default value usermode:false
Jul 11 11:42:48 grin-miner sudo[12434]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip link add iswgsupported type wireguard
Jul 11 11:42:48 grin-miner sudo[12434]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12434]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.336 DBG services/wireguard/endpoint/wg_client.go:57 > "ip link add iswgsupported type wireguard" output:
Jul 11 11:42:48 grin-miner sudo[12441]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip link del iswgsupported
Jul 11 11:42:48 grin-miner sudo[12441]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12441]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.443 DBG services/wireguard/endpoint/wg_client.go:62 > "ip link del iswgsupported" output:
Jul 11 11:42:48 grin-miner sudo[12478]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip link add dev myst1 type wireguard
Jul 11 11:42:48 grin-miner sudo[12478]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12478]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.451 DBG services/wireguard/endpoint/kernelspace/client.go:148 > "ip link add dev myst1 type wireguard" output:
Jul 11 11:42:48 grin-miner sudo[12482]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip address replace dev myst1 10.182.1.1/24
Jul 11 11:42:48 grin-miner sudo[12482]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12482]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.475 DBG services/wireguard/endpoint/kernelspace/client.go:153 > "ip address replace dev myst1 10.182.1.1/24" output:
Jul 11 11:42:48 grin-miner sudo[12490]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip link set dev myst1 up
Jul 11 11:42:48 grin-miner sudo[12490]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12490]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.503 DBG services/wireguard/endpoint/kernelspace/client.go:157 > "ip link set dev myst1 up" output:
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.510 INF nat/service_iptables.go:45               > Setting up NAT/Firewall rules
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.510 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
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.542 DBG session/pingpong/price_calculator.go:67  > Calculated price 11339. Time component: 5287, data component: 6052
Jul 11 11:42:48 grin-miner sudo[12501]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A PREROUTING --source 10.182.1.2/24 --destination 10.182.1.1 --protocol udp --dport 53 --jump REDIRECT --to-ports 11253 --table nat
Jul 11 11:42:48 grin-miner sudo[12501]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12501]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.603 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A PREROUTING --source 10.182.1.2/24 --destination 10.182.1.1 --protocol udp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:
Jul 11 11:42:48 grin-miner sudo[12522]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A PREROUTING --source 10.182.1.2/24 --destination 10.182.1.1 --protocol tcp --dport 53 --jump REDIRECT --to-ports 11253 --table nat
Jul 11 11:42:48 grin-miner sudo[12522]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12522]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.609 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A PREROUTING --source 10.182.1.2/24 --destination 10.182.1.1 --protocol tcp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:
Jul 11 11:42:48 grin-miner sudo[12528]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 10.0.0.0/8 --jump DROP
Jul 11 11:42:48 grin-miner sudo[12528]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12528]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.618 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 10.0.0.0/8 --jump DROP" output:
Jul 11 11:42:48 grin-miner sudo[12535]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 172.16.0.0/12 --jump DROP
Jul 11 11:42:48 grin-miner sudo[12535]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12535]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.626 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 172.16.0.0/12 --jump DROP" output:
Jul 11 11:42:48 grin-miner sudo[12545]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 192.168.0.0/16 --jump DROP
Jul 11 11:42:48 grin-miner sudo[12545]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12545]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.637 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 192.168.0.0/16 --jump DROP" output:
Jul 11 11:42:48 grin-miner sudo[12553]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 127.0.0.0/8 --jump DROP
Jul 11 11:42:48 grin-miner sudo[12553]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12553]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.644 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A FORWARD --source 10.182.1.2/24 --destination 127.0.0.0/8 --jump DROP" output:
Jul 11 11:42:48 grin-miner sudo[12555]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -A POSTROUTING --source 10.182.1.2/24 ! --destination 10.182.1.2/24 --jump SNAT --to 192.168.0.186 --table nat
Jul 11 11:42:48 grin-miner sudo[12555]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner sudo[12555]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.650 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -A POSTROUTING --source 10.182.1.2/24 ! --destination 10.182.1.2/24 --jump SNAT --to 192.168.0.186 --table nat" output:
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.650 INF nat/service_iptables.go:69               > Setting up NAT/Firewall rules... done
Jul 11 11:42:48 grin-miner sudo[12557]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev myst1 root
Jul 11 11:42:48 grin-miner sudo[12557]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.656 ??? vendor/github.com/rs/zerolog/log.go:403  > Error: Cannot delete qdisc with handle of zero
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.656 ??? vendor/github.com/rs/zerolog/log.go:403  > .
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.656 ??? vendor/github.com/rs/zerolog/log.go:403  >
Jul 11 11:42:48 grin-miner sudo[12557]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner sudo[12559]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev myst1 ingress
Jul 11 11:42:48 grin-miner sudo[12559]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.663 ??? vendor/github.com/rs/zerolog/log.go:403  > Error: Cannot find specified qdisc on specified device
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.663 ??? vendor/github.com/rs/zerolog/log.go:403  > .
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.663 ??? vendor/github.com/rs/zerolog/log.go:403  >
Jul 11 11:42:48 grin-miner sudo[12559]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner sudo[12561]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev ifb0 root
Jul 11 11:42:48 grin-miner sudo[12561]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.675 ??? vendor/github.com/rs/zerolog/log.go:403  > Cannot find device "ifb0"
Jul 11 11:42:48 grin-miner sudo[12561]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner sudo[12566]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev ifb0 ingress
Jul 11 11:42:48 grin-miner sudo[12566]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.684 ??? vendor/github.com/rs/zerolog/log.go:403  > Cannot find device "ifb0"
Jul 11 11:42:48 grin-miner sudo[12566]: pam_unix(sudo:session): session closed for user root
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.684 DBG config/config.go:182                     > Returning user config value shaper.enabled:false
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.685 DBG core/service/subscription.go:48          > Provider connection trace: "Provider whole session create" took 1.82621399s, "Provider session start" took 1.46403486s, "Provider config" took 361.246145ms
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.685 DBG eventbus/event_bus.go:81                 > Published topic="Service session" event={Status:Ended SessionInfo:{StartedAt:0001-01-01 00:00:00 +0000 UTC ConsumerID:{Address:} AccountantID:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] State: SessionID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:LT City:Vilnius ASN:1257 ISP:Tele2 Lithuania NodeType:cellular} LocationOriginate:{Continent:EU Country:LT City:Vilnius ASN:1257 ISP:Tele2 Lithuania NodeType:cellular}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:7m8.632661808s Bytes:53687091 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet-broker.mysterium.network:4222]}}] AccessPolicies:<nil>}}}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.685 DBG eventbus/event_bus.go:81                 > Published topic="Trace" event={ID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Key:Provider whole session create Duration:1.82621399s}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.685 DBG eventbus/event_bus.go:81                 > Published topic="Trace" event={ID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Key:Provider session start Duration:1.46403486s}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.685 DBG eventbus/event_bus.go:81                 > Published topic="Trace" event={ID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Key:Provider config Duration:361.246145ms}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.711 DBG eventbus/event_bus.go:81                 > Published topic="SessionTokensEarned" event={ProviderID:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} SessionID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Total:1}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.711 INF session/pingpong/accountant_promise_settler.go:264 > Received accountant promise for {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.711 INF session/pingpong/accountant_promise_settler.go:281 > Accountant promise state updated for provider {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:42:48 grin-miner myst[1673]: 2020-07-11T11:42:48.712 DBG eventbus/event_bus.go:81                 > Published topic="earnings_change" event={Identity:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} Previous:{LifetimeBalance:417270860 UnsettledBalance:417270860} Current:{LifetimeBalance:417270861 UnsettledBalance:417270861}}
Jul 11 11:42:49 grin-miner myst[1673]: 2020-07-11T11:42:49.309 DBG core/service/subscription.go:164         > Received P2P message for "p2p-session-acknowledge": consumerID:"0x53a51a8bb055187a21ad5fcbdf2ea4e11ba3cd71" sessionID:"e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf"
Jul 11 11:42:50 grin-miner myst[1673]: 2020-07-11T11:42:50.307 DBG session/pingpong/price_calculator.go:67  > Calculated price 404. Time component: 402, data component: 2
Jul 11 11:42:50 grin-miner myst[1673]: 2020-07-11T11:42:50.542 DBG session/pingpong/price_calculator.go:67  > Calculated price 13560. Time component: 5521, data component: 8039
Jul 11 11:42:52 grin-miner myst[1673]: 2020-07-11T11:42:52.307 DBG session/pingpong/price_calculator.go:67  > Calculated price 647. Time component: 636, data component: 11
Jul 11 11:42:52 grin-miner myst[1673]: 2020-07-11T11:42:52.542 DBG session/pingpong/price_calculator.go:67  > Calculated price 15487. Time component: 5754, data component: 9733
Jul 11 11:42:54 grin-miner myst[1673]: 2020-07-11T11:42:54.307 DBG session/pingpong/price_calculator.go:67  > Calculated price 896. Time component: 869, data component: 27
Jul 11 11:42:54 grin-miner myst[1673]: 2020-07-11T11:42:54.542 DBG session/pingpong/price_calculator.go:67  > Calculated price 17450. Time component: 5987, data component: 11463
Jul 11 11:42:56 grin-miner myst[1673]: 2020-07-11T11:42:56.307 DBG session/pingpong/price_calculator.go:67  > Calculated price 1137. Time component: 1102, data component: 35
Jul 11 11:42:56 grin-miner myst[1673]: 2020-07-11T11:42:56.542 DBG session/pingpong/price_calculator.go:67  > Calculated price 19680. Time component: 6221, data component: 13459
Jul 11 11:42:58 grin-miner myst[1673]: 2020-07-11T11:42:58.308 DBG session/pingpong/price_calculator.go:67  > Calculated price 1374. Time component: 1336, data component: 38
Jul 11 11:42:58 grin-miner myst[1673]: 2020-07-11T11:42:58.543 DBG session/pingpong/price_calculator.go:67  > Calculated price 21000. Time component: 6454, data component: 14546
Jul 11 11:43:00 grin-miner myst[1673]: 2020-07-11T11:43:00.308 DBG session/pingpong/price_calculator.go:67  > Calculated price 1614. Time component: 1569, data component: 45
Jul 11 11:43:00 grin-miner myst[1673]: 2020-07-11T11:43:00.543 DBG session/pingpong/price_calculator.go:67  > Calculated price 22596. Time component: 6687, data component: 15909
Jul 11 11:43:02 grin-miner myst[1673]: 2020-07-11T11:43:02.308 DBG session/pingpong/price_calculator.go:67  > Calculated price 1849. Time component: 1802, data component: 47
Jul 11 11:43:02 grin-miner myst[1673]: 2020-07-11T11:43:02.543 DBG session/pingpong/price_calculator.go:67  > Calculated price 24861. Time component: 6920, data component: 17941
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.308 DBG session/pingpong/price_calculator.go:67  > Calculated price 2094. Time component: 2035, data component: 59
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.543 DBG session/pingpong/price_calculator.go:67  > Calculated price 25833. Time component: 7154, data component: 18679
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.543 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:16165837183781112862 AgreementTotal:25833 Hashlock:"b1760b1579fafeb602de3d2fc69c41e286e3bd0fa76c14a5bd11be9c20612180" Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.623 DBG session/pingpong/exchange_messaging.go:81 > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"\xcd\x10*\xb4\xb7\xeb\x84h\x81\xa8\xb53be\xbfDR\xfc\x04\xec" Amount:25833 Hashlock:"\xb1v\x0b\x15y\xfa\xfe\xb6\x02\xde=/ƜA\xe2\x86\xe3\xbd\x0f\xa7l\x14\xa5\xbd\x11\xbe\x9c a!\x80" Signature:"@`\x19<Д\xbaa\xab\xac\xf4\x15\x92Y.\xaa\xd3\xc5v\x12ȣ\x81Q\xc3E\xba\xe7\xb7P\x87\xd8X/\xb5գ\xe4%\xf9\x8eU\xb9$\x02\x83Q4\\W(uVc\x8b\xfb=>^҉Q\xb3e\x1b"} AgreementID:16165837183781112862 AgreementTotal:25833 Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0" Signature:"a5f59d14e3ea20588e5a711f9fb986e73dc08b1b1d543902ce6defae4adcbc69331075d8d19f550a5ec1bfee90f6b56cd4a3b215d7915b1a785a9657c938f2cc1b"
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.793 INF session/pingpong/accountant_promise_settler.go:264 > Received accountant promise for {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.793 INF session/pingpong/accountant_promise_settler.go:281 > Accountant promise state updated for provider {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.793 DBG eventbus/event_bus.go:81                 > Published topic="earnings_change" event={Identity:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} Previous:{LifetimeBalance:417270861 UnsettledBalance:417270861} Current:{LifetimeBalance:417296693 UnsettledBalance:417296693}}
Jul 11 11:43:04 grin-miner myst[1673]: 2020-07-11T11:43:04.793 DBG eventbus/event_bus.go:81                 > Published topic="SessionTokensEarned" event={ProviderID:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} SessionID:0a67f6ae-57aa-431f-bdb1-a7a37f650b5d Total:25833}
Jul 11 11:43:06 grin-miner myst[1673]: 2020-07-11T11:43:06.308 DBG session/pingpong/price_calculator.go:67  > Calculated price 2345. Time component: 2269, data component: 76
Jul 11 11:43:06 grin-miner myst[1673]: 2020-07-11T11:43:06.543 DBG session/pingpong/price_calculator.go:67  > Calculated price 26325. Time component: 7387, data component: 18938
Jul 11 11:43:07 grin-miner myst[1673]: 2020-07-11T11:43:07.005 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:43:08 grin-miner myst[1673]: 2020-07-11T11:43:08.309 DBG session/pingpong/price_calculator.go:67  > Calculated price 2595. Time component: 2502, data component: 93
Jul 11 11:43:08 grin-miner myst[1673]: 2020-07-11T11:43:08.544 DBG session/pingpong/price_calculator.go:67  > Calculated price 29049. Time component: 7620, data component: 21429
Jul 11 11:43:09 grin-miner myst[1673]: 2020-07-11T11:43:09.308 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf
Jul 11 11:43:09 grin-miner myst[1673]: 2020-07-11T11:43:09.319 DBG core/service/subscription.go:119         > Received P2P session status message for "p2p-session-connectivity-status": ConsumerID:"0x53a51a8bb055187a21ad5fcbdf2ea4e11ba3cd71" SessionID:"e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf" Code:1000
Jul 11 11:43:10 grin-miner myst[1673]: 2020-07-11T11:43:10.309 DBG session/pingpong/price_calculator.go:67  > Calculated price 2839. Time component: 2735, data component: 104
Jul 11 11:43:10 grin-miner myst[1673]: 2020-07-11T11:43:10.544 DBG session/pingpong/price_calculator.go:67  > Calculated price 30603. Time component: 7854, data component: 22749
Jul 11 11:43:12 grin-miner myst[1673]: 2020-07-11T11:43:12.309 DBG session/pingpong/price_calculator.go:67  > Calculated price 3082. Time component: 2969, data component: 113
Jul 11 11:43:12 grin-miner myst[1673]: 2020-07-11T11:43:12.544 DBG session/pingpong/price_calculator.go:67  > Calculated price 32468. Time component: 8087, data component: 24381
Jul 11 11:43:14 grin-miner myst[1673]: 2020-07-11T11:43:14.309 DBG session/pingpong/price_calculator.go:67  > Calculated price 3469. Time component: 3202, data component: 267
Jul 11 11:43:14 grin-miner myst[1673]: 2020-07-11T11:43:14.544 DBG session/pingpong/price_calculator.go:67  > Calculated price 34381. Time component: 8320, data component: 26061
Jul 11 11:43:16 grin-miner myst[1673]: 2020-07-11T11:43:16.309 DBG session/pingpong/price_calculator.go:67  > Calculated price 3723. Time component: 3435, data component: 288
Jul 11 11:43:16 grin-miner myst[1673]: 2020-07-11T11:43:16.544 DBG session/pingpong/price_calculator.go:67  > Calculated price 36576. Time component: 8554, data component: 28022
Jul 11 11:43:18 grin-miner myst[1673]: 2020-07-11T11:43:18.310 DBG session/pingpong/price_calculator.go:67  > Calculated price 3980. Time component: 3669, data component: 311
Jul 11 11:43:18 grin-miner myst[1673]: 2020-07-11T11:43:18.545 DBG session/pingpong/price_calculator.go:67  > Calculated price 38792. Time component: 8787, data component: 30005
Jul 11 11:43:20 grin-miner myst[1673]: 2020-07-11T11:43:20.310 DBG session/pingpong/price_calculator.go:67  > Calculated price 4221. Time component: 3902, data component: 319
Jul 11 11:43:20 grin-miner myst[1673]: 2020-07-11T11:43:20.545 DBG session/pingpong/price_calculator.go:67  > Calculated price 41120. Time component: 9020, data component: 32100
Jul 11 11:43:22 grin-miner myst[1673]: 2020-07-11T11:43:22.310 DBG session/pingpong/price_calculator.go:67  > Calculated price 4478. Time component: 4135, data component: 343
Jul 11 11:43:22 grin-miner myst[1673]: 2020-07-11T11:43:22.545 DBG session/pingpong/price_calculator.go:67  > Calculated price 43118. Time component: 9254, data component: 33864
Jul 11 11:43:24 grin-miner myst[1673]: 2020-07-11T11:43:24.310 DBG session/pingpong/price_calculator.go:67  > Calculated price 4793. Time component: 4369, data component: 424
Jul 11 11:43:24 grin-miner myst[1673]: 2020-07-11T11:43:24.545 DBG session/pingpong/price_calculator.go:67  > Calculated price 43776. Time component: 9487, data component: 34289
Jul 11 11:43:26 grin-miner myst[1673]: 2020-07-11T11:43:26.310 DBG session/pingpong/price_calculator.go:67  > Calculated price 6267. Time component: 4602, data component: 1665
Jul 11 11:43:26 grin-miner myst[1673]: 2020-07-11T11:43:26.545 DBG session/pingpong/price_calculator.go:67  > Calculated price 44075. Time component: 9720, data component: 34355
Jul 11 11:43:27 grin-miner myst[1673]: 2020-07-11T11:43:27.325 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:43:28 grin-miner myst[1673]: 2020-07-11T11:43:28.311 DBG session/pingpong/price_calculator.go:67  > Calculated price 8331. Time component: 4835, data component: 3496
Jul 11 11:43:28 grin-miner myst[1673]: 2020-07-11T11:43:28.546 DBG session/pingpong/price_calculator.go:67  > Calculated price 44439. Time component: 9954, data component: 34485
Jul 11 11:43:29 grin-miner myst[1673]: 2020-07-11T11:43:29.416 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf
Jul 11 11:43:30 grin-miner myst[1673]: 2020-07-11T11:43:30.311 DBG session/pingpong/price_calculator.go:67  > Calculated price 10311. Time component: 5069, data component: 5242
Jul 11 11:43:30 grin-miner myst[1673]: 2020-07-11T11:43:30.546 DBG session/pingpong/price_calculator.go:67  > Calculated price 44853. Time component: 10187, data component: 34666
Jul 11 11:43:32 grin-miner myst[1673]: 2020-07-11T11:43:32.311 DBG session/pingpong/price_calculator.go:67  > Calculated price 12636. Time component: 5302, data component: 7334
Jul 11 11:43:32 grin-miner myst[1673]: 2020-07-11T11:43:32.546 DBG session/pingpong/price_calculator.go:67  > Calculated price 45238. Time component: 10420, data component: 34818
Jul 11 11:43:34 grin-miner myst[1673]: 2020-07-11T11:43:34.311 DBG session/pingpong/price_calculator.go:67  > Calculated price 14545. Time component: 5535, data component: 9010
Jul 11 11:43:34 grin-miner myst[1673]: 2020-07-11T11:43:34.546 DBG session/pingpong/price_calculator.go:67  > Calculated price 45590. Time component: 10654, data component: 34936
Jul 11 11:43:36 grin-miner myst[1673]: 2020-07-11T11:43:36.311 DBG session/pingpong/price_calculator.go:67  > Calculated price 15140. Time component: 5769, data component: 9371
Jul 11 11:43:36 grin-miner myst[1673]: 2020-07-11T11:43:36.546 DBG session/pingpong/price_calculator.go:67  > Calculated price 46136. Time component: 10887, data component: 35249
Jul 11 11:43:38 grin-miner myst[1673]: 2020-07-11T11:43:38.312 DBG session/pingpong/price_calculator.go:67  > Calculated price 15433. Time component: 6002, data component: 9431
Jul 11 11:43:38 grin-miner myst[1673]: 2020-07-11T11:43:38.547 DBG session/pingpong/price_calculator.go:67  > Calculated price 46623. Time component: 11120, data component: 35503
Jul 11 11:43:40 grin-miner myst[1673]: 2020-07-11T11:43:40.312 DBG session/pingpong/price_calculator.go:67  > Calculated price 15884. Time component: 6235, data component: 9649
Jul 11 11:43:40 grin-miner myst[1673]: 2020-07-11T11:43:40.547 DBG session/pingpong/price_calculator.go:67  > Calculated price 46875. Time component: 11354, data component: 35521
Jul 11 11:43:42 grin-miner myst[1673]: 2020-07-11T11:43:42.312 DBG session/pingpong/price_calculator.go:67  > Calculated price 17641. Time component: 6469, data component: 11172
Jul 11 11:43:42 grin-miner myst[1673]: 2020-07-11T11:43:42.547 DBG session/pingpong/price_calculator.go:67  > Calculated price 47123. Time component: 11587, data component: 35536
Jul 11 11:43:44 grin-miner myst[1673]: 2020-07-11T11:43:44.312 DBG session/pingpong/price_calculator.go:67  > Calculated price 19734. Time component: 6702, data component: 13032
Jul 11 11:43:44 grin-miner myst[1673]: 2020-07-11T11:43:44.547 DBG session/pingpong/price_calculator.go:67  > Calculated price 47374. Time component: 11820, data component: 35554
Jul 11 11:43:44 grin-miner myst[1673]: 2020-07-11T11:43:44.983 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0 service type: openvpn
Jul 11 11:43:45 grin-miner myst[1673]: 2020-07-11T11:43:45.015 INF market/mysterium/mysterium_api.go:203    > Proposal pinged for node: 0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0 service type: wireguard
Jul 11 11:43:46 grin-miner myst[1673]: 2020-07-11T11:43:46.312 DBG session/pingpong/price_calculator.go:67  > Calculated price 21657. Time component: 6935, data component: 14722
Jul 11 11:43:46 grin-miner myst[1673]: 2020-07-11T11:43:46.547 DBG session/pingpong/price_calculator.go:67  > Calculated price 47622. Time component: 12054, data component: 35568
Jul 11 11:43:47 grin-miner myst[1673]: 2020-07-11T11:43:47.732 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.313 DBG session/pingpong/price_calculator.go:67  > Calculated price 22718. Time component: 7169, data component: 15549
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.313 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:18385847886580395516 AgreementTotal:22718 Hashlock:"c2cea09e96d74234bf1a4c6f898d0049e66e8f5677198f1ff1364a7197be99a0" Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.415 DBG session/pingpong/exchange_messaging.go:81 > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"\xae\x85\xb5\xd3\xef\x89\x1cE\xbb\x0b\x11\xbc6\rթ\xeb\xf8I;" Amount:1483887946 Hashlock:"\xc2Π\x9e\x96\xd7B4\xbf\x1aLo\x89\x8d\x00I\xe6n\x8fVw\x19\x8f\x1f\xf16Jq\x97\xbe\x99\xa0" Signature:"'>\xefu\xf5Ec+\xa7\xa5\xca\x0fm\x88\x96Xo\xfc#\xe1l\xa1s1\xf4\xb6\x04\x96\xfc\x95\x92|7\x9c-\xd9Ijlid#\xb4`\ng\xccLJh\xbf\xec\x0cÅN\xa1Z\xe2>\x06u'0\x1b"} AgreementID:18385847886580395516 AgreementTotal:22718 Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0" Signature:"ca16507c69027f6d52098e4d521463ea6516dcbe80a4a85e10d6990a8790072d0fe8ec620e24802c340a6a0597a70d69f977015bde05db1c38e591cb41171b991c" HermesID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318"
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.548 DBG session/pingpong/price_calculator.go:67  > Calculated price 47877. Time component: 12287, data component: 35590
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.622 DBG eventbus/event_bus.go:81                 > Published topic="SessionTokensEarned" event={ProviderID:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} SessionID:e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf Total:22718}
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.623 INF session/pingpong/accountant_promise_settler.go:264 > Received accountant promise for {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.623 INF session/pingpong/accountant_promise_settler.go:281 > Accountant promise state updated for provider {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:43:48 grin-miner myst[1673]: 2020-07-11T11:43:48.623 DBG eventbus/event_bus.go:81                 > Published topic="earnings_change" event={Identity:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} Previous:{LifetimeBalance:417296693 UnsettledBalance:417296693} Current:{LifetimeBalance:417319410 UnsettledBalance:417319410}}
Jul 11 11:43:49 grin-miner myst[1673]: 2020-07-11T11:43:49.742 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf
Jul 11 11:43:50 grin-miner myst[1673]: 2020-07-11T11:43:50.313 DBG session/pingpong/price_calculator.go:67  > Calculated price 22960. Time component: 7402, data component: 15558
Jul 11 11:43:50 grin-miner myst[1673]: 2020-07-11T11:43:50.548 DBG session/pingpong/price_calculator.go:67  > Calculated price 48130. Time component: 12520, data component: 35610
Jul 11 11:43:52 grin-miner myst[1673]: 2020-07-11T11:43:52.313 DBG session/pingpong/price_calculator.go:67  > Calculated price 23194. Time component: 7635, data component: 15559
Jul 11 11:43:52 grin-miner myst[1673]: 2020-07-11T11:43:52.548 DBG session/pingpong/price_calculator.go:67  > Calculated price 48382. Time component: 12754, data component: 35628
Jul 11 11:43:54 grin-miner myst[1673]: 2020-07-11T11:43:54.313 DBG session/pingpong/price_calculator.go:67  > Calculated price 23428. Time component: 7869, data component: 15559
Jul 11 11:43:54 grin-miner myst[1673]: 2020-07-11T11:43:54.548 DBG session/pingpong/price_calculator.go:67  > Calculated price 48630. Time component: 12987, data component: 35643
Jul 11 11:43:56 grin-miner myst[1673]: 2020-07-11T11:43:56.313 DBG session/pingpong/price_calculator.go:67  > Calculated price 23661. Time component: 8102, data component: 15559
Jul 11 11:43:56 grin-miner myst[1673]: 2020-07-11T11:43:56.548 DBG session/pingpong/price_calculator.go:67  > Calculated price 48878. Time component: 13220, data component: 35658
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.314 DBG session/pingpong/price_calculator.go:67  > Calculated price 23894. Time component: 8335, data component: 15559
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.549 DBG session/pingpong/price_calculator.go:67  > Calculated price 49137. Time component: 13454, data component: 35683
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.640 INF nat/mapping/port_mapping.go:149          > Mapped network port: 48262
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.640 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.640 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.940 INF nat/mapping/port_mapping.go:149          > Mapped network port: 49517
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.940 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.940 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:43:58 grin-miner myst[1673]: 2020-07-11T11:43:58.940 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:43:59 grin-miner myst[1673]: 2020-07-11T11:43:59.240 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:44:00 grin-miner myst[1673]: 2020-07-11T11:44:00.314 DBG session/pingpong/price_calculator.go:67  > Calculated price 24128. Time component: 8569, data component: 15559
Jul 11 11:44:00 grin-miner myst[1673]: 2020-07-11T11:44:00.549 DBG session/pingpong/price_calculator.go:67  > Calculated price 49393. Time component: 13687, data component: 35706
Jul 11 11:44:02 grin-miner myst[1673]: 2020-07-11T11:44:02.314 DBG session/pingpong/price_calculator.go:67  > Calculated price 24369. Time component: 8802, data component: 15567
Jul 11 11:44:02 grin-miner myst[1673]: 2020-07-11T11:44:02.549 DBG session/pingpong/price_calculator.go:67  > Calculated price 49648. Time component: 13920, data component: 35728
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.314 DBG session/pingpong/price_calculator.go:67  > Calculated price 24602. Time component: 9035, data component: 15567
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.549 DBG session/pingpong/price_calculator.go:67  > Calculated price 49896. Time component: 14154, data component: 35742
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.549 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:16165837183781112862 AgreementTotal:49896 Hashlock:"f908f18e96c1daea6f17e0a98f3f8c5f83955021648dff47c3b3340ae08c27c3" Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.683 DBG session/pingpong/exchange_messaging.go:81 > Received P2P message for "p2p-payment-message": Promise:{ChannelID:"\xcd\x10*\xb4\xb7\xeb\x84h\x81\xa8\xb53be\xbfDR\xfc\x04\xec" Amount:49896 Hashlock:"\xf9\x08\xf1\x8e\x96\xc1\xda\xeao\x17੏?\x8c_\x83\x95P!d\x8d\xffGó4\n\xe0\x8c'\xc3" Signature:"\x84\xd5\xed\x84@Y\xb4\xa3\xbeN\x17o\xd9\xfa\x1f\xfe\xaf\xe7k\xe3\xfbG\xda;P1#\r\xcd\xee\x11\x16l\xdd^\x0b\xfb\xd2I\xeamK\xe7\xea\xe5\x94\x11\xe9͞\x80\xf4跖\x98\x0f\x17\x01B\x18aN\xf8\x1c"} AgreementID:16165837183781112862 AgreementTotal:49896 Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0" Signature:"014fd57f7587aa787ceb0ce9369ae6c56fa72db7163fd718dbb997aed1f0110c474a40ff728f9a5f12cd2f241dbfe3cba628ca121aefbe4079734fd62f43c1061b"
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.851 DBG eventbus/event_bus.go:81                 > Published topic="SessionTokensEarned" event={ProviderID:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} SessionID:0a67f6ae-57aa-431f-bdb1-a7a37f650b5d Total:49896}
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.851 INF session/pingpong/accountant_promise_settler.go:264 > Received accountant promise for {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.851 INF session/pingpong/accountant_promise_settler.go:281 > Accountant promise state updated for provider {"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"}
Jul 11 11:44:04 grin-miner myst[1673]: 2020-07-11T11:44:04.851 DBG eventbus/event_bus.go:81                 > Published topic="earnings_change" event={Identity:{Address:0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0} Previous:{LifetimeBalance:417319410 UnsettledBalance:417319410} Current:{LifetimeBalance:417343473 UnsettledBalance:417343473}}
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.314 DBG session/pingpong/price_calculator.go:67  > Calculated price 24835. Time component: 9268, data component: 15567
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.523 DBG core/service/subscription.go:140         > Received P2P message for "p2p-session-destroy": consumerID:"0x4aed3fda3c112ffc4bcaea5afd4bc412ff5a6311" sessionID:"0a67f6ae-57aa-431f-bdb1-a7a37f650b5d"
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.523 DBG nat/mapping/port_mapping.go:154          > Deleting port mapping for port: 49120
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.537 DBG nat/mapping/port_mapping.go:154          > Deleting port mapping for port: 48117
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.549 DBG session/pingpong/invoice_tracker.go:621  > Stopping...
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.549 INF services/wireguard/service/service_unix.go:179 > Cleaning up session 0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.550 INF services/wireguard/service/stats_publisher.go:62 > Stopped publishing statistics for session 0a67f6ae-57aa-431f-bdb1-a7a37f650b5d
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.550 DBG consumer/session/session_storage.go:236  > Session 0a67f6ae-57aa-431f-bdb1-a7a37f650b5d updated with final data
Jul 11 11:44:06 grin-miner sudo[13178]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev myst0 root
Jul 11 11:44:06 grin-miner sudo[13178]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.556 ??? vendor/github.com/rs/zerolog/log.go:403  > Error: Cannot delete qdisc with handle of zero
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.556 ??? vendor/github.com/rs/zerolog/log.go:403  > .
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.557 ??? vendor/github.com/rs/zerolog/log.go:403  >
Jul 11 11:44:06 grin-miner sudo[13178]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner sudo[13180]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev myst0 ingress
Jul 11 11:44:06 grin-miner sudo[13180]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.563 ??? vendor/github.com/rs/zerolog/log.go:403  > Error: Cannot find specified qdisc on specified device
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.564 ??? vendor/github.com/rs/zerolog/log.go:403  > .
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.564 ??? vendor/github.com/rs/zerolog/log.go:403  >
Jul 11 11:44:06 grin-miner sudo[13180]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner sudo[13182]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev ifb0 root
Jul 11 11:44:06 grin-miner sudo[13182]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.573 ??? vendor/github.com/rs/zerolog/log.go:403  > Cannot find device "ifb0"
Jul 11 11:44:06 grin-miner sudo[13182]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner sudo[13186]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/tc qdisc del dev ifb0 ingress
Jul 11 11:44:06 grin-miner sudo[13186]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.582 ??? vendor/github.com/rs/zerolog/log.go:403  > Cannot find device "ifb0"
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.583 INF nat/service_iptables.go:75               > Deleting NAT/Firewall rules
Jul 11 11:44:06 grin-miner sudo[13186]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner sudo[13190]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol udp --dport 53 --jump REDIRECT --to-ports 11253 --table nat
Jul 11 11:44:06 grin-miner sudo[13190]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13190]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.589 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol udp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:
Jul 11 11:44:06 grin-miner sudo[13192]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol tcp --dport 53 --jump REDIRECT --to-ports 11253 --table nat
Jul 11 11:44:06 grin-miner sudo[13192]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13192]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.596 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D PREROUTING --source 10.182.0.2/24 --destination 10.182.0.1 --protocol tcp --dport 53 --jump REDIRECT --to-ports 11253 --table nat" output:
Jul 11 11:44:06 grin-miner sudo[13194]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 10.0.0.0/8 --jump DROP
Jul 11 11:44:06 grin-miner sudo[13194]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13194]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.603 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 10.0.0.0/8 --jump DROP" output:
Jul 11 11:44:06 grin-miner sudo[13196]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 172.16.0.0/12 --jump DROP
Jul 11 11:44:06 grin-miner sudo[13196]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13196]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.609 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 172.16.0.0/12 --jump DROP" output:
Jul 11 11:44:06 grin-miner sudo[13198]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 192.168.0.0/16 --jump DROP
Jul 11 11:44:06 grin-miner sudo[13198]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13198]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.616 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 192.168.0.0/16 --jump DROP" output:
Jul 11 11:44:06 grin-miner sudo[13200]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 127.0.0.0/8 --jump DROP
Jul 11 11:44:06 grin-miner sudo[13200]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13200]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.623 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D FORWARD --source 10.182.0.2/24 --destination 127.0.0.0/8 --jump DROP" output:
Jul 11 11:44:06 grin-miner sudo[13202]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/iptables -D POSTROUTING --source 10.182.0.2/24 ! --destination 10.182.0.2/24 --jump SNAT --to 192.168.0.186 --table nat
Jul 11 11:44:06 grin-miner sudo[13202]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13202]: pam_unix(sudo:session): session closed for user root
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.629 DBG nat/service_iptables.go:169              > "/usr/sbin/iptables -D POSTROUTING --source 10.182.0.2/24 ! --destination 10.182.0.2/24 --jump SNAT --to 192.168.0.186 --table nat" output:
Jul 11 11:44:06 grin-miner myst[1673]: 2020-07-11T11:44:06.630 INF nat/service_iptables.go:87               > Deleting NAT/Firewall rules... done
Jul 11 11:44:06 grin-miner sudo[13204]: mysterium-node : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip link del dev myst0
Jul 11 11:44:06 grin-miner sudo[13204]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 11 11:44:06 grin-miner sudo[13204]: pam_unix(sudo:session): session closed for user root

Node logs while connecting via mobile:

Jul 11 11:44:09 grin-miner myst[1673]: 2020-07-11T11:44:09.817 DBG session/manager.go:277                   > Received p2p keepalive ping with SessionID=e465ac1d-a0e3-4c6c-b1ae-6af695ca97bf
Jul 11 11:44:10 grin-miner myst[1673]: 2020-07-11T11:44:10.843 DBG services/wireguard/endpoint/kernelspace/client.go:143 > "ip link del dev myst1" output:
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.144 DBG p2p/listener.go:209                      > Received consumer public key 9e8cee1c2f833daed095058ea2bb2e13b3a783f4bde2df46a0286e1b6f0c6477
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.144 DBG core/ip/cached_resolver.go:79            > Public IP cache is empty, fetching IP
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.746 DBG core/ip/resolver.go:101                  > IP detected: 213.101.138.37
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.746 INF core/port/pool.go:68                     > Supplying port 46549
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.746 INF core/port/pool.go:68                     > Supplying port 44796
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.747 DBG nat/mapping/port_mapping.go:119          > Detected router public IP address: 213.101.138.37
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.750 INF nat/mapping/port_mapping.go:149          > Mapped network port: 46549
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.750 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:44:28 grin-miner myst[1673]: 2020-07-11T11:44:28.750 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.050 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.051 DBG nat/mapping/port_mapping.go:119          > Detected router public IP address: 213.101.138.37
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.053 INF nat/mapping/port_mapping.go:149          > Mapped network port: 44796
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.054 DBG eventbus/event_bus.go:81                 > Published topic="Traversal" event={Stage:port_mapping Successful:true Error:<nil>}
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.054 INF nat/event/tracker.go:53                  > Got NAT event event={"stage":"port_mapping","successful":true}
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.354 DBG core/ip/cached_resolver.go:75            > Found cached public IP
Jul 11 11:44:29 grin-miner myst[1673]: 2020-07-11T11:44:29.354 DBG p2p/listener.go:244                      > Sending reply with public key 6039e68e26a389218a294573e0bc94e0c921f8330810c20fbe328c990f28f14c and encrypted config to consumer
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/listener.go:328                      > Decrypted consumer config: publicIP:"90.131.46.14" ports:48127 ports:43566
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/listener.go:147                      > Skipping consumer ping
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/channel.go:200                       > Creating p2p channel with local addr: 192.168.0.186:46549, UDP session addr: 127.0.0.1:47251, proxy addr: 127.0.0.1:48527, remote peer addr: x.x.x.x:48127
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/channel.go:519                       > Will use service conn with local port: 44796, remote port: 43566
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/listener.go:349                      > Sending handlers ready message
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.283 DBG p2p/listener.go:137                      > Delaying pings from consumer for 100 ms
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.518 DBG core/service/subscription.go:64          > Received P2P message for "p2p-session-create": consumer:{id:"0x53a51a8bb055187a21ad5fcbdf2ea4e11ba3cd71" accountantID:"0x0214281cf15C1a66b51990e2E65e1f7b7C363318" paymentVersion:"v3"} proposalID:1 config:"{\"PublicKey\":\"WOQ2qE9Fqmns+D9tj/y7NdXqLSpWtcIUZwjPiIjR3jg=\",\"Ports\":null}"
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.518 INF session/manager.go:175                   > Using new payments
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.518 INF session/manager.go:195                   > Waiting for a first invoice to be paid
Jul 11 11:44:30 grin-miner myst[1673]: 2020-07-11T11:44:30.518 DBG session/pingpong/invoice_tracker.go:268  > Starting...
Jul 11 11:44:31 grin-miner myst[1673]: 2020-07-11T11:44:31.699 DBG session/pingpong/price_calculator.go:67  > Calculated price 138. Time component: 138, data component: 0
Jul 11 11:44:31 grin-miner myst[1673]: 2020-07-11T11:44:31.699 DBG session/pingpong/invoice_tracker.go:449  > Being lenient for the first payment, asking for 1
Jul 11 11:44:31 grin-miner myst[1673]: 2020-07-11T11:44:31.700 DBG session/pingpong/invoice_messaging.go:56 > Sending P2P message to "p2p-payment-invoice": AgreementID:14592694435562832525 AgreementTotal:1 Hashlock:"2838f0c50acedb12316b5a17def7763de340a73cc6369eb4699c388c2d4298f5" Provider:"0x5f3ddefe3ccb72eab3393310f8ed62a2f58166b0"
Jul 11 11:44:41 grin-miner myst[1673]: 2020-07-11T11:44:41.700 WRN session/pingpong/invoice_tracker.go:488  > Failed to send first invoice error="timeout waiting for reply to \"p2p-payment-invoice\": p2p send timeout"
Jul 11 11:44:41 grin-miner myst[1673]: 2020-07-11T11:44:41.700 ERR session/manager.go:190                   > Payment engine error error="could not send first invoice: did not sent first invoice"
Jul 11 11:44:41 grin-miner myst[1673]: 2020-07-11T11:44:41.700 ERR session/manager.go:190                   > Payment engine error error="could not send first invoice: did not sent first invoice"
chompomonim commented 4 years ago

Can't attach consumer logs because of #2455

chompomonim commented 4 years ago

People are reporting similar cased on twitter, but exact opposite of mine ;)

https://twitter.com/Amorphous223/status/1275246330395258881

zolia commented 4 years ago

This is already fixed on desktop app.