cvl
commented
3 years ago One more log file from the same user.
Closed cvl closed 3 years ago
cvl
commented
3 years ago One more log file from the same user.
vkuznecovas
commented
3 years ago The issue was caused by the downtime of the location service. The user should be able to connect with no problems now.
We'll also fix the problem with location oracle being mandatory for operation, see https://github.com/mysteriumnetwork/node/issues/3045
cvl
commented
3 years ago Thank you for fast response!
cvl
commented
3 years ago I believe it's down again:
2021-01-25T11:33:27.255 ERR source/core/location/cache.go:102 > Location update failed error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: x509: certificate has expired or is not yet valid"
Can't connect.
cvl
commented
3 years ago After 10 minutes, I can connect, although the error "certificate has expired or is not yet valid" is still there
cvl
commented
3 years ago Unfortunately, it's not working again, for all our users :\
cvl
commented
3 years ago Android as well.
cvl
commented
3 years ago Here're the logs from my MacOS app:
2021-01-25T12:08:11.053 DBG source/logconfig/rollingwriter/rollingwriter.go:76 > Found 0 old log files in log directory, skipping cleanup
2021-01-25T12:08:11.053 INF source/cmd/di.go:188 > Starting Mysterium Node 0.41.2
2021-01-25T12:08:11.053 DBG source/config/config.go:196 > Returning default value outgoing-firewall:false
2021-01-25T12:08:11.054 DBG source/config/config.go:196 > Returning default value incoming-firewall:false
2021-01-25T12:08:11.054 INF source/firewall/incoming_firewall_noop.go:32 > Rules bootstrap was requested
2021-01-25T12:08:11.054 DBG source/config/config.go:187 > Returning CLI value usermode:true
2021-01-25T12:08:11.054 INF source/cmd/di.go:650 > Using local DNS: testnet2-quality.mysterium.network -> [116.202.100.246]
2021-01-25T12:08:11.054 INF source/cmd/di.go:650 > Using local DNS: badupnp.benjojo.co.uk -> [104.22.70.70 104.22.71.70 172.67.25.154]
2021-01-25T12:08:11.054 INF source/cmd/di.go:650 > Using local DNS: testnet2-trust.mysterium.network -> [95.216.204.232]
2021-01-25T12:08:11.054 INF source/cmd/di.go:650 > Using local DNS: testnet2-broker.mysterium.network -> [95.216.204.232]
2021-01-25T12:08:11.054 INF source/cmd/di.go:650 > Using local DNS: testnet2-transactor.mysterium.network -> [135.181.82.67]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: testnet-location.mysterium.network -> [82.196.15.9]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: testnet2-location.mysterium.network -> [95.216.204.232]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: feedback.mysterium.network -> [116.203.17.150]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: api.ipify.org -> [54.204.14.42 54.225.153.147 54.235.83.248 54.243.161.145 23.21.109.69 23.21.126.66 50.19.252.36 174.129.214.20]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: testnet2-api.mysterium.network -> [78.47.55.197]
2021-01-25T12:08:11.055 INF source/cmd/di.go:650 > Using local DNS: testnet2.mysterium.network -> [138.201.174.94]
2021-01-25T12:08:11.055 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222]
2021-01-25T12:08:11.055 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-25T12:08:11.055 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-25T12:08:11.055 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-25T12:08:11.217 INF source/cmd/di.go:675 > Using Eth endpoint: wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637
2021-01-25T12:08:12.202 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-25T12:08:12.203 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-25T12:08:12.203 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-25T12:08:12.203 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-25T12:08:12.203 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-25T12:08:12.203 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-25T12:08:12.203 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-25T12:08:12.203 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-25T12:08:12.203 DBG source/cmd/di.go:725 > Using lightweight keystore
2021-01-25T12:08:12.329 INF source/core/discovery/dhtdiscovery/node.go:86 > DHT node started on [/ip4/127.0.0.1/tcp/54403 /ip4/192.168.50.146/tcp/54403] with ID=QmU4wMbx4DCPMo4b95PUGtGwU77jX7Sotp5xzhLxxcBNnR
2021-01-25T12:08:12.329 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-25T12:08:12.329 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-25T12:08:12.329 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-25T12:08:12.329 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-25T12:08:12.329 DBG source/config/config.go:196 > Returning default value data-dir:/Users/userzzz/.mysterium
2021-01-25T12:08:12.330 DBG source/config/config.go:187 > Returning CLI value testnet2:true
2021-01-25T12:08:12.330 DBG source/config/config.go:196 > Returning default value testnet:false
2021-01-25T12:08:12.330 DBG source/config/config.go:196 > Returning default value data-dir:/Users/userzzz/.mysterium
2021-01-25T12:08:12.330 DBG source/config/config.go:196 > Returning default value data-dir:/Users/userzzz/.mysterium
2021-01-25T12:08:12.330 DBG source/config/config.go:196 > Returning default value mmn.api-address:https://testnet2.mysterium.network/api/v1
2021-01-25T12:08:12.330 DBG source/cmd/di.go:888 > Experimental NAT punching enabled, creating a pinger
2021-01-25T12:08:12.335 DBG source/config/config.go:196 > Returning default value nat-port-mapping:true
2021-01-25T12:08:12.335 DBG source/cmd/di_desktop.go:57 > Skipping services bootstrap for consumer mode
2021-01-25T12:08:12.335 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-25T12:08:12.335 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-25T12:08:12.335 DBG source/cmd/di_desktop.go:191 > Skipping hermes promise settler for consumer mode
2021-01-25T12:08:12.335 DBG source/cmd/di_desktop.go:163 > Skipping provider registrar for consumer mode
2021-01-25T12:08:12.335 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 239.255.255.250 access
2021-01-25T12:08:12.336 DBG source/config/config.go:196 > Returning default value access-policy.address:https://testnet2-trust.mysterium.network/api/v1/access-policies/
2021-01-25T12:08:12.336 INF source/pilvytis/order_status_tracker.go:102 > Tracking order statuses...
2021-01-25T12:08:12.338 DBG source/config/config.go:196 > Returning default value pprof.enable:false
2021-01-25T12:08:12.338 DBG source/sleep/sleep_darwin.go:32 > Register for sleep events
2021-01-25T12:08:12.339 INF source/tequilapi/http_api_server.go:77 > API started on: 127.0.0.1:4050
2021-01-25T12:08:12.339 DBG source/ui/noop/noop.go:35 > Start: NOOP UI server
2021-01-25T12:08:12.339 DBG source/eventbus/event_bus.go:81 > Published topic="Node" event={Status:Started}
2021-01-25T12:08:12.339 INF source/cmd/di.go:271 > Mysterium node started!
2021-01-25T12:08:12.339 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:12.339 DBG source/core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP
2021-01-25T12:08:12.339 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-25T12:08:12.339 DBG source/identity/registry/registry_userzzzct.go:106 > event received {Started}
2021-01-25T12:08:12.340 INF source/identity/registry/registry_userzzzct.go:272 > Starting registry...
2021-01-25T12:08:12.340 DBG source/identity/registry/registry_userzzzct.go:283 > Loading initial state
2021-01-25T12:08:12.340 DBG source/identity/registry/registry_userzzzct.go:298 > Identity {"0x266d85bfdff630f0cec5fec2993e23e9468661b6"} already registered, skipping
2021-01-25T12:08:12.459 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-25T12:08:12.468 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:12.471 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:12.479 WRN source/core/location/cache.go:121 > Failed to detect original location error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: x509: certificate has expired or is not yet valid"
2021-01-25T12:08:12.591 DBG source/identity/manager.go:148 > Caching unlocked address: 0x266d85bfdff630f0cec5fec2993e23e9468661b6
2021-01-25T12:08:12.592 DBG source/identity/manager.go:135 > Unlocked identity found in cache, skipping keystore: 0x266d85bfdff630f0cec5fec2993e23e9468661b6
2021-01-25T12:08:12.592 DBG source/eventbus/event_bus.go:81 > Published topic="identity-unlocked" event={ChainID:5 ID:{Address:0x266d85bfdff630f0cec5fec2993e23e9468661b6}}
2021-01-25T12:08:12.827 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 321 supported: 321
2021-01-25T12:08:12.828 INF source/core/discovery/repository.go:91 > Returning 321 unique proposals
2021-01-25T12:08:12.915 DBG source/session/pingpong/consumer_balance_tracker.go:436 > Loaded hermes state: already promised: 29849289454324230
2021-01-25T12:08:12.943 DBG source/eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+29849289454324230 ChainID:5 HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] ConsumerID:{Address:0x266d85bfdff630f0cec5fec2993e23e9468661b6}}
2021-01-25T12:08:13.266 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x266d85bfdff630f0cec5fec2993e23e9468661b6} Previous:+0 Current:+4970150710545675770}
2021-01-25T12:08:13.267 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x266d85bfdff630f0cec5fec2993e23e9468661b6} Previous:+4970150710545675770 Current:+4970150710545675770}
2021-01-25T12:08:13.412 INF source/session/pingpong/consumer_balance_tracker.go:217 > Subscribed to channel 0x45621c6e067E424278161B2195ec1335E785a8FF balance events
2021-01-25T12:08:14.442 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:WPS Access Point manufacturer:ASUSTeK Computer Inc. modelName:Wi-Fi Protected Setup Router modelNo:RT-AX58U server:Unspecified, UPnP/1.0, Unspecified]
2021-01-25T12:08:14.445 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:WPS Access Point manufacturer:ASUSTeK Computer Inc. modelName:Wi-Fi Protected Setup Router modelNo:RT-AX58U server:Unspecified, UPnP/1.0, Unspecified]
2021-01-25T12:08:14.448 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:WPS Access Point manufacturer:ASUSTeK Computer Inc. modelName:Wi-Fi Protected Setup Router modelNo:RT-AX58U server:Unspecified, UPnP/1.0, Unspecified]
2021-01-25T12:08:14.451 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:WPS Access Point manufacturer:ASUSTeK Computer Inc. modelName:Wi-Fi Protected Setup Router modelNo:RT-AX58U server:Unspecified, UPnP/1.0, Unspecified]
2021-01-25T12:08:14.455 INF source/nat/upnp/discover.go:58 > UPnP gateways detected: 1
2021-01-25T12:08:14.455 INF source/nat/upnp/discover.go:60 > UPnP gateway detected map[deviceType:urn:schemas-upnp-org:device:InternetGatewayDevice:1 friendlyName:RT-AX58U-37A0 manufacturer:ASUSTeK Computer Inc. modelName:RT-AX58U modelNo:3.0.0.4.384 server:AsusWRT/3.0.0.4 UPnP/1.1 MiniUPnPd/1.9]
2021-01-25T12:08:20.442 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-25T12:08:20.712 INF source/core/discovery/repository.go:91 > Returning 329 unique proposals
2021-01-25T12:08:30.443 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-25T12:08:30.700 INF source/core/discovery/repository.go:91 > Returning 339 unique proposals
2021-01-25T12:08:33.703 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:33.703 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:33.703 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xbb3dd5828ecb040c23e80ec7ccda16066bc1bc9f ConsumerID:0x266d85bfdff630f0cec5fec2993e23e9468661b6 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-25T12:08:33.703 INF source/tequilapi/endpoints/connection.go:184 > identity "0x266d85bfdff630f0cec5fec2993e23e9468661b6" is registered, continuing...
2021-01-25T12:08:33.927 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-25T12:08:33.927 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-25T12:08:33.927 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-25T12:08:33.927 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-25 12:08:33.927593 +0200 EET m=+22.930760364 ConsumerID:{Address:0x266d85bfdff630f0cec5fec2993e23e9468661b6} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:EE City:Harjumaa ASN:207408 ISP:servinga GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:EE City:Harjumaa ASN:207408 ISP:servinga GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:5m0s Bytes:5368709 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xbb3dd5828ecb040c23e80ec7ccda16066bc1bc9f ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:
cvl
commented
3 years ago @vkuznecovas 0.41.3 update didn't help. After first launch with 0.41.3 update - it worked, after quitting and launching it again, it doesn't work again (can't connect).
Please find logs attached. after-0.41.3.txt
tomasmik
commented
3 years ago I've just tested this running both client and node in version 0.41.3 and everything seems to work just fine. Make sure you're using proper versions for both.
Worked fine before the upgrade. Logs: 2021-01-24T06:58:43.371 DBG source/logconfig/rollingwriter/rollingwriter.go:76 > Found 0 old log files in log directory, skipping cleanup 2021-01-24T06:58:43.371 INF source/cmd/di.go:188 > Starting Mysterium Node 0.41.2 2021-01-24T06:58:43.371 INF source/core/node/options_directory.go:95 > Directory does not exist, creating a new one: C:\Users\userxxx.mysterium\testnet2\db 2021-01-24T06:58:43.372 DBG source/config/config.go:196 > Returning default value outgoing-firewall:false 2021-01-24T06:58:43.372 DBG source/config/config.go:196 > Returning default value incoming-firewall:false 2021-01-24T06:58:43.374 INF source/firewall/incoming_firewall_noop.go:32 > Rules bootstrap was requested 2021-01-24T06:58:43.376 INF source/core/storage/boltdb/migrator/migrator.go:66 > Running migration session-to-session-history 2021-01-24T06:58:43.377 INF source/core/storage/boltdb/migrator/migrator.go:71 > Saving migration session-to-session-history 2021-01-24T06:58:43.378 INF source/core/storage/boltdb/migrator/migrator.go:66 > Running migration settlements-to-rows 2021-01-24T06:58:43.379 INF source/core/storage/boltdb/migrator/migrator.go:71 > Saving migration settlements-to-rows 2021-01-24T06:58:43.380 DBG source/config/config.go:187 > Returning CLI value usermode:true 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: feedback.mysterium.network -> [116.203.17.150] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: api.ipify.org -> [54.204.14.42 54.225.153.147 54.235.83.248 54.243.161.145 23.21.109.69 23.21.126.66 50.19.252.36 174.129.214.20] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: badupnp.benjojo.co.uk -> [104.22.70.70 104.22.71.70 172.67.25.154] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-trust.mysterium.network -> [95.216.204.232] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-api.mysterium.network -> [78.47.55.197] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet-location.mysterium.network -> [82.196.15.9] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-location.mysterium.network -> [95.216.204.232] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-quality.mysterium.network -> [116.202.100.246] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-broker.mysterium.network -> [95.216.204.232] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2-transactor.mysterium.network -> [135.181.82.67] 2021-01-24T06:58:43.380 INF source/cmd/di.go:650 > Using local DNS: testnet2.mysterium.network -> [138.201.174.94] 2021-01-24T06:58:43.380 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222] 2021-01-24T06:58:43.380 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access 2021-01-24T06:58:43.380 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access 2021-01-24T06:58:43.380 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access 2021-01-24T06:58:43.960 INF source/cmd/di.go:675 > Using Eth endpoint: wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 2021-01-24T06:58:44.588 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access 2021-01-24T06:58:44.588 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-api.mysterium.network/v1 access 2021-01-24T06:58:44.588 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access 2021-01-24T06:58:44.588 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access 2021-01-24T06:58:44.588 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access 2021-01-24T06:58:44.588 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-api.mysterium.network/v1 access 2021-01-24T06:58:44.588 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access 2021-01-24T06:58:44.588 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access 2021-01-24T06:58:44.588 DBG source/cmd/di.go:725 > Using lightweight keystore 2021-01-24T06:58:44.659 INF source/core/discovery/dhtdiscovery/node.go:86 > DHT node started on [/ip4/192.168.2.166/tcp/2178 /ip4/169.254.203.247/tcp/2178 /ip4/169.254.82.79/tcp/2178 /ip4/169.254.147.99/tcp/2178 /ip4/169.254.147.75/tcp/2178 /ip4/169.254.194.210/tcp/2178 /ip4/127.0.0.1/tcp/2178] with ID=Qmbq4yXFVEtLDorgLfJixLcmfzgGVs7Zr3bucPr4Qty2su 2021-01-24T06:58:44.659 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access 2021-01-24T06:58:44.660 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access 2021-01-24T06:58:44.660 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access 2021-01-24T06:58:44.660 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium 2021-01-24T06:58:44.661 DBG source/config/config.go:187 > Returning CLI value testnet2:true 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value testnet:false 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value mmn.api-address:https://testnet2.mysterium.network/api/v1 2021-01-24T06:58:44.661 DBG source/cmd/di.go:888 > Experimental NAT punching enabled, creating a pinger 2021-01-24T06:58:44.661 DBG source/config/config.go:196 > Returning default value nat-port-mapping:true 2021-01-24T06:58:44.661 DBG source/cmd/di_desktop.go:57 > Skipping services bootstrap for consumer mode 2021-01-24T06:58:44.661 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access 2021-01-24T06:58:44.661 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access 2021-01-24T06:58:44.661 DBG source/cmd/di_desktop.go:191 > Skipping hermes promise settler for consumer mode 2021-01-24T06:58:44.661 DBG source/cmd/di_desktop.go:163 > Skipping provider registrar for consumer mode 2021-01-24T06:58:44.661 INF source/feedback/reporter.go:40 > Using feedback API at: https://feedback.mysterium.network 2021-01-24T06:58:44.662 DBG source/config/config.go:196 > Returning default value access-policy.address:https://testnet2-trust.mysterium.network/api/v1/access-policies/ 2021-01-24T06:58:44.662 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 239.255.255.250 access 2021-01-24T06:58:44.662 DBG source/config/config.go:196 > Returning default value pprof.enable:false 2021-01-24T06:58:44.661 INF source/pilvytis/order_status_tracker.go:102 > Tracking order statuses... 2021-01-24T06:58:44.662 INF source/tequilapi/http_api_server.go:77 > API started on: 127.0.0.1:4050 2021-01-24T06:58:44.662 DBG source/sleep/sleep_windows.go:27 > Register for sleep log events 2021-01-24T06:58:44.662 DBG source/ui/noop/noop.go:35 > Start: NOOP UI server 2021-01-24T06:58:44.662 DBG source/eventbus/event_bus.go:81 > Published topic="Node" event={Status:Started} 2021-01-24T06:58:44.662 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver 2021-01-24T06:58:44.662 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:58:44.662 INF source/cmd/di.go:271 > Mysterium node started! 2021-01-24T06:58:44.662 DBG source/identity/registry/registry_contract.go:106 > event received {Started} 2021-01-24T06:58:44.662 DBG source/core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP 2021-01-24T06:58:44.662 INF source/identity/registry/registry_contract.go:272 > Starting registry... 2021-01-24T06:58:44.662 DBG source/identity/registry/registry_contract.go:283 > Loading initial state 2021-01-24T06:58:44.695 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories 2021-01-24T06:58:44.697 INF source/config/config.go:90 > Saving user configuration 2021-01-24T06:58:44.802 DBG source/eventbus/event_bus.go:81 > Published topic="identity-created" event=0x999999 2021-01-24T06:58:45.072 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:58:45.072 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:58:45.120 DBG source/identity/manager.go:148 > Caching unlocked address: 0x999999 2021-01-24T06:58:45.120 DBG source/identity/manager.go:135 > Unlocked identity found in cache, skipping keystore: 0x999999 2021-01-24T06:58:45.120 DBG source/eventbus/event_bus.go:81 > Published topic="identity-unlocked" event={ChainID:5 ID:{Address:0x999999}} 2021-01-24T06:58:45.314 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 331 supported: 331 2021-01-24T06:58:45.314 INF source/core/discovery/repository.go:91 > Returning 331 unique proposals 2021-01-24T06:58:46.764 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:ASUS WPS Router manufacturer:ASUSTeK Corporation modelName:WPS Router modelNo:X1 server:POSIX UPnP/1.0 UPnP Stack/7.14.164.3] 2021-01-24T06:58:46.773 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-upnp-org:device:MediaServer:1 friendlyName:Home Hub 2000 manufacturer:PacketVideo modelName:TwonkyMedia modelNo:4.4.18 server:Linux/2.x.x, UPnP/1.0, pvConnect UPnP SDK/1.0] 2021-01-24T06:58:46.773 INF source/nat/upnp/discover.go:58 > UPnP gateways detected: 1 2021-01-24T06:58:46.773 INF source/nat/upnp/discover.go:60 > UPnP gateway detected map[deviceType:urn:schemas-upnp-org:device:InternetGatewayDevice:1 friendlyName:Home Hub 2000 Internet Gateway Device manufacturer:Sagemcom modelName:Sagemcom IDG WAN modelNo: server:Linux/2.6.28.8, UPnP/1.0, Portable SDK for UPnP devices/1.6.18] 2021-01-24T06:58:52.696 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories 2021-01-24T06:58:53.321 INF source/core/discovery/repository.go:91 > Returning 342 unique proposals 2021-01-24T06:58:58.688 WRN source/core/location/cache.go:121 > Failed to detect original location error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond." 2021-01-24T06:59:02.694 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories 2021-01-24T06:59:03.296 INF source/core/discovery/repository.go:91 > Returning 347 unique proposals 2021-01-24T06:59:09.710 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:59:09.710 INF source/config/config.go:90 > Saving user configuration 2021-01-24T06:59:10.750 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:59:11.048 DBG source/eventbus/event_bus.go:81 > Published topic="transactor_identity_registration" event={RegistryAddress:0x15B1281F4e58215b2c3243d864BdF8b9ddDc0DA2 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Stake:+0 Fee:+4853788337750852000 Beneficiary:0xf6db82e43c272d30c087e6a4503f6066a74ac58b Signature:0x75191e2e8a4df57af09712619e272c5f8aa80081b75fd7fcd5d2cb9d972a53d81d8bafea2761c04660fd6dcf14cf4c173a54d6344978b8d9ab120ee288f0b0e91c Identity:0x999999 ChainID:5} 2021-01-24T06:59:11.048 DBG source/eventbus/event_bus.go:81 > Published topic="registration_event_topic" event={ID:{Address:0x999999} Status:InProgress ChainID:5} 2021-01-24T06:59:11.051 INF source/identity/registry/registry_contract.go:184 > Waiting on identities 0x999999 hermes 0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 2021-01-24T06:59:11.233 DBG source/session/pingpong/consumer_balance_tracker.go:390 > Loaded transactor state, current balance: 5000000000000000000 MYST 2021-01-24T06:59:11.233 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+0 Current:+5000000000000000000} 2021-01-24T06:59:12.162 DBG source/session/pingpong/consumer_balance_tracker.go:436 > Loaded hermes state: already promised: 0 2021-01-24T06:59:12.164 DBG source/eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+0 ChainID:5 HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] ConsumerID:{Address:0x999999}} 2021-01-24T06:59:12.165 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+5000000000000000000 Current:+5000000000000000000} 2021-01-24T06:59:12.308 INF source/session/pingpong/consumer_balance_tracker.go:217 > Subscribed to channel 0xF6Db82e43c272d30c087E6a4503F6066a74aC58b balance events 2021-01-24T06:59:12.690 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories 2021-01-24T06:59:13.175 INF source/core/discovery/repository.go:91 > Returning 355 unique proposals 2021-01-24T06:59:15.111 INF source/pilvytis/order_status_tracker.go:126 > Pausing order status tracking 2021-01-24T06:59:16.610 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:59:16.610 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:59:16.723 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_in_progress} 2021-01-24T06:59:16.723 INF source/tequilapi/endpoints/connection.go:181 > identity "0x999999" registration is in progress, continuing... 2021-01-24T06:59:17.217 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1 2021-01-24T06:59:17.217 DBG source/config/config.go:196 > Returning default value chain-id:5 2021-01-24T06:59:17.217 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting 2021-01-24T06:59:17.217 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 06:59:17.2173957 -0500 EST m=+33.893260001 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting} LocationOriginate:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:1h40m0s Bytes:10737418 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T06:59:17.217 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T06:59:17.217 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T06:59:17.217 INF source/core/state/state.go:404 > Session ID Connecting duration: 0s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T06:59:17.217 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T06:59:17.689 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 03247e47fdd71efc4ff6ffa8593b20109753ed2771fe4c4a952ede8482284603 to provider 0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06
2021-01-24T06:59:22.692 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T06:59:23.412 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 331 supported: 331
2021-01-24T06:59:23.412 INF source/core/discovery/repository.go:91 > Returning 368 unique proposals
2021-01-24T06:59:25.172 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+5000000000000000000 Current:+14853788337750852000}
2021-01-24T06:59:32.698 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T06:59:33.290 INF source/core/discovery/repository.go:91 > Returning 377 unique proposals
2021-01-24T06:59:42.690 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T06:59:43.129 INF source/core/discovery/repository.go:91 > Returning 381 unique proposals
2021-01-24T06:59:52.696 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T06:59:53.297 INF source/core/discovery/repository.go:91 > Returning 385 unique proposals
2021-01-24T06:59:55.878 INF source/tequilapi/endpoints/stop.go:44 > Application stop requested
2021-01-24T06:59:55.878 INF source/core/connection/manager.go:601 > Connection state: Connecting -> Disconnecting
2021-01-24T06:59:55.878 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Disconnecting SessionInfo:{StartedAt:2021-01-24 06:59:17.2173957 -0500 EST m=+33.893260001 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Disconnecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting} LocationOriginate:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:1h40m0s Bytes:10737418 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T06:59:55.878 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T06:59:55.879 INF source/core/connection/manager.go:601 > Connection state: Disconnecting -> NotConnected
2021-01-24T06:59:55.879 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T06:59:55.879 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T06:59:55.879 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 06:59:17.2173957 -0500 EST m=+33.893260001 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting} LocationOriginate:{Continent:NA Country:CA City:Ontario ASN:54913 ISP:Kamatera Inc NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:1h40m0s Bytes:10737418 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/core/state/state.go:404 > Session ID Disconnecting duration: 38.6623332s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T06:59:55.879 INF source/cmd/node.go:94 > Connection closed
2021-01-24T06:59:55.879 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/core/state/state.go:404 > Session ID NotConnected duration: 38.6623332s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T06:59:55.879 INF source/cmd/node.go:98 > API stopped
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 DBG source/ui/noop/noop.go:40 > Stop: NOOP UI server
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="Node" event={Status:Stopped}
2021-01-24T06:59:55.879 INF source/cmd/node.go:101 > Web UI server stopped
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 INF source/cmd/node.go:104 > NAT pinger stopped
2021-01-24T06:59:55.879 DBG source/sleep/sleep_windows.go:51 > Unregister sleep log events watcher
2021-01-24T06:59:55.879 ERR source/cmd/commands/daemon/command.go:68 > Terminating application due to error error="accept tcp 127.0.0.1:4050: use of closed network connection"
2021-01-24T06:59:55.879 DBG source/identity/registry/registry_contract.go:106 > event received {Stopped}
2021-01-24T06:59:55.879 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06.wireguard.p2p-config-exchange: context canceled"
2021-01-24T06:59:55.879 INF source/cmd/node.go:107 > Sleep notifier stopped
2021-01-24T06:59:55.879 INF source/cmd/node.go:89 > No active connection - proceeding
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:38.6623332s}
2021-01-24T06:59:55.879 INF source/communication/nats/receiver.go:99 > Unsubscribed from .proposal-ping
2021-01-24T06:59:55.879 INF source/identity/registry/registry_contract.go:266 > Stopping registry...
2021-01-24T06:59:55.879 INF source/cmd/node.go:98 > API stopped
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:38.6623332s}
2021-01-24T06:59:55.879 INF source/communication/nats/receiver.go:99 > Unsubscribed from .proposal-unregister
2021-01-24T06:59:55.879 DBG source/ui/noop/noop.go:40 > Stop: NOOP UI server
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:471.858ms}
2021-01-24T06:59:55.879 INF source/communication/nats/receiver.go:99 > Unsubscribed from *.proposal-register
2021-01-24T06:59:55.879 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T06:59:55.879 INF source/cmd/node.go:101 > Web UI server stopped
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:38.1904752s}
2021-01-24T06:59:55.879 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T06:59:55.879 INF source/cmd/node.go:104 > NAT pinger stopped
2021-01-24T06:59:55.879 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T06:59:55.879 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T06:59:55.879 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 38.6623332s, "Consumer P2P channel creation" took 38.6623332s, "Consumer P2P connect" took 471.858ms, "Consumer P2P exchange" took 38.1904752s
2021-01-24T06:59:55.879 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T06:59:55.879 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/cmd/node.go:107 > Sleep notifier stopped
2021-01-24T06:59:55.879 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06.wireguard.p2p-config-exchange: context canceled Stage:connection_unknown_error}
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x4fafa8b72aa51bf97fdba4b3bef89ca114910f06.wireguard.p2p-config-exchange: context canceled"
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/incoming_firewall_noop.go:38 > Rules reset was requested
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T06:59:55.879 INF source/firewall/outgoing_firewall_noop.go:35 > Rules reset was requested
2021-01-24T06:59:55.879 INF source/firewall/incoming_firewall_noop.go:38 > Rules reset was requested
2021-01-24T06:59:55.880 INF source/firewall/outgoing_firewall_noop.go:35 > Rules reset was requested
2021-01-24T06:59:55.880 INF source/utils/stopper.go:58 > Good bye
2021-01-24T06:59:55.880 ERR source/cmd/mysterium_node/mysterium_node.go:68 > Failed to execute command: error="accept tcp 127.0.0.1:4050: use of closed network connection"
2021-01-24T07:01:37.977 DBG source/logconfig/rollingwriter/rollingwriter.go:76 > Found 0 old log files in log directory, skipping cleanup
2021-01-24T07:01:37.977 INF source/cmd/di.go:188 > Starting Mysterium Node 0.41.2
2021-01-24T07:01:37.978 DBG source/config/config.go:196 > Returning default value outgoing-firewall:false
2021-01-24T07:01:37.978 DBG source/config/config.go:196 > Returning default value incoming-firewall:false
2021-01-24T07:01:37.978 INF source/firewall/incoming_firewall_noop.go:32 > Rules bootstrap was requested
2021-01-24T07:01:37.978 DBG source/config/config.go:187 > Returning CLI value usermode:true
2021-01-24T07:01:37.978 INF source/cmd/di.go:650 > Using local DNS: feedback.mysterium.network -> [116.203.17.150]
2021-01-24T07:01:37.978 INF source/cmd/di.go:650 > Using local DNS: testnet2-broker.mysterium.network -> [95.216.204.232]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2.mysterium.network -> [138.201.174.94]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2-api.mysterium.network -> [78.47.55.197]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2-location.mysterium.network -> [95.216.204.232]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2-quality.mysterium.network -> [116.202.100.246]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: api.ipify.org -> [54.204.14.42 54.225.153.147 54.235.83.248 54.243.161.145 23.21.109.69 23.21.126.66 50.19.252.36 174.129.214.20]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: badupnp.benjojo.co.uk -> [104.22.70.70 104.22.71.70 172.67.25.154]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2-transactor.mysterium.network -> [135.181.82.67]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet2-trust.mysterium.network -> [95.216.204.232]
2021-01-24T07:01:37.979 INF source/cmd/di.go:650 > Using local DNS: testnet-location.mysterium.network -> [82.196.15.9]
2021-01-24T07:01:37.979 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222]
2021-01-24T07:01:37.979 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:37.979 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:37.979 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:01:38.338 INF source/cmd/di.go:675 > Using Eth endpoint: wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637
2021-01-24T07:01:38.578 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-24T07:01:38.578 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-24T07:01:38.578 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-24T07:01:38.578 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-24T07:01:38.578 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-24T07:01:38.578 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-24T07:01:38.578 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-24T07:01:38.578 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-24T07:01:38.578 DBG source/cmd/di.go:725 > Using lightweight keystore
2021-01-24T07:01:38.706 INF source/core/discovery/dhtdiscovery/node.go:86 > DHT node started on [/ip4/192.168.2.166/tcp/2264 /ip4/169.254.203.247/tcp/2264 /ip4/169.254.82.79/tcp/2264 /ip4/169.254.147.99/tcp/2264 /ip4/169.254.147.75/tcp/2264 /ip4/169.254.194.210/tcp/2264 /ip4/127.0.0.1/tcp/2264] with ID=QmRFyvLPY6isXsaivGZ1cFvTgBatp5kfGiTasBtcdvFFm2
2021-01-24T07:01:38.706 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:01:38.706 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:01:38.706 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:01:38.706 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:01:38.706 DBG source/config/config.go:187 > Returning CLI value testnet2:true
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value testnet:false
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value mmn.api-address:https://testnet2.mysterium.network/api/v1
2021-01-24T07:01:38.706 DBG source/cmd/di.go:888 > Experimental NAT punching enabled, creating a pinger
2021-01-24T07:01:38.706 DBG source/config/config.go:196 > Returning default value nat-port-mapping:true
2021-01-24T07:01:38.706 DBG source/cmd/di_desktop.go:57 > Skipping services bootstrap for consumer mode
2021-01-24T07:01:38.706 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-24T07:01:38.706 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-24T07:01:38.706 DBG source/cmd/di_desktop.go:191 > Skipping hermes promise settler for consumer mode
2021-01-24T07:01:38.706 DBG source/cmd/di_desktop.go:163 > Skipping provider registrar for consumer mode
2021-01-24T07:01:38.707 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 239.255.255.250 access
2021-01-24T07:01:38.816 INF source/pilvytis/order_status_tracker.go:102 > Tracking order statuses...
2021-01-24T07:01:38.816 DBG source/config/config.go:196 > Returning default value access-policy.address:https://testnet2-trust.mysterium.network/api/v1/access-policies/
2021-01-24T07:01:38.816 DBG source/config/config.go:196 > Returning default value pprof.enable:false
2021-01-24T07:01:38.816 INF source/tequilapi/http_api_server.go:77 > API started on: 127.0.0.1:4050
2021-01-24T07:01:38.816 DBG source/sleep/sleep_windows.go:27 > Register for sleep log events
2021-01-24T07:01:38.816 DBG source/ui/noop/noop.go:35 > Start: NOOP UI server
2021-01-24T07:01:38.816 DBG source/eventbus/event_bus.go:81 > Published topic="Node" event={Status:Started}
2021-01-24T07:01:38.816 INF source/cmd/di.go:271 > Mysterium node started!
2021-01-24T07:01:38.816 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:01:38.816 DBG source/core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP
2021-01-24T07:01:38.816 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:38.817 DBG source/identity/registry/registry_contract.go:106 > event received {Started}
2021-01-24T07:01:38.817 INF source/identity/registry/registry_contract.go:272 > Starting registry...
2021-01-24T07:01:38.817 DBG source/identity/registry/registry_contract.go:283 > Loading initial state
2021-01-24T07:01:38.817 DBG source/identity/registry/registry_contract.go:298 > Identity {"0x999999"} already registered, skipping
2021-01-24T07:01:39.460 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:01:39.464 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:39.464 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:39.514 DBG source/identity/manager.go:148 > Caching unlocked address: 0x999999
2021-01-24T07:01:39.514 DBG source/eventbus/event_bus.go:81 > Published topic="identity-unlocked" event={ChainID:5 ID:{Address:0x999999}}
2021-01-24T07:01:39.514 DBG source/identity/manager.go:135 > Unlocked identity found in cache, skipping keystore: 0x999999
2021-01-24T07:01:40.167 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:01:40.167 INF source/core/discovery/repository.go:91 > Returning 330 unique proposals
2021-01-24T07:01:40.170 DBG source/session/pingpong/consumer_balance_tracker.go:436 > Loaded hermes state: already promised: 0
2021-01-24T07:01:40.172 DBG source/eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+0 ChainID:5 HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] ConsumerID:{Address:0x999999}}
2021-01-24T07:01:40.368 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+0 Current:+5000000000000000000}
2021-01-24T07:01:40.378 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+5000000000000000000 Current:+5000000000000000000}
2021-01-24T07:01:40.471 INF source/session/pingpong/consumer_balance_tracker.go:217 > Subscribed to channel 0xF6Db82e43c272d30c087E6a4503F6066a74aC58b balance events
2021-01-24T07:01:40.809 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:ASUS WPS Router manufacturer:ASUSTeK Corporation modelName:WPS Router modelNo:X1 server:POSIX UPnP/1.0 UPnP Stack/7.14.164.3]
2021-01-24T07:01:40.818 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-upnp-org:device:MediaServer:1 friendlyName:Home Hub 2000 manufacturer:PacketVideo modelName:TwonkyMedia modelNo:4.4.18 server:Linux/2.x.x, UPnP/1.0, pvConnect UPnP SDK/1.0]
2021-01-24T07:01:40.819 INF source/nat/upnp/discover.go:58 > UPnP gateways detected: 1
2021-01-24T07:01:40.819 INF source/nat/upnp/discover.go:60 > UPnP gateway detected map[deviceType:urn:schemas-upnp-org:device:InternetGatewayDevice:1 friendlyName:Home Hub 2000 Internet Gateway Device manufacturer:Sagemcom modelName:Sagemcom IDG WAN modelNo: server:Linux/2.6.28.8, UPnP/1.0, Portable SDK for UPnP devices/1.6.18]
2021-01-24T07:01:47.464 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:01:47.951 INF source/core/discovery/repository.go:91 > Returning 337 unique proposals
2021-01-24T07:01:49.438 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:49.438 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:49.438 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:01:49.438 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:01:49.927 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:01:49.927 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:01:52.865 WRN source/core/location/cache.go:121 > Failed to detect original location error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."
2021-01-24T07:01:52.865 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:01:52.865 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:01:49.9279561 -0500 EST m=+11.996361401 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:Washington ASN:7922 ISP:Comcast Cable NodeType:residential} LocationOriginate:{Continent:NA Country:US City:Washington ASN:7922 ISP:Comcast Cable NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:6m40s Bytes:107374182400 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:01:52.866 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:01:52.866 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:52.866 INF source/core/state/state.go:404 > Session ID Connecting duration: 2.93833s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:01:52.866 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:01:53.398 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 4c7e02933ee10ef8af124c8466275dc909fc87f2a29b136f41f9d6e96a9c5d33 to provider 0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859
2021-01-24T07:01:57.458 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:01:58.209 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:01:58.209 INF source/core/discovery/repository.go:91 > Returning 348 unique proposals
2021-01-24T07:02:07.461 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:08.040 INF source/core/discovery/repository.go:91 > Returning 354 unique proposals
2021-01-24T07:02:09.361 INF source/pilvytis/order_status_tracker.go:126 > Pausing order status tracking
2021-01-24T07:02:17.470 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:18.051 INF source/core/discovery/repository.go:91 > Returning 363 unique proposals
2021-01-24T07:02:27.465 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:28.080 INF source/core/discovery/repository.go:91 > Returning 375 unique proposals
2021-01-24T07:02:37.460 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:37.991 INF source/core/discovery/repository.go:91 > Returning 382 unique proposals
2021-01-24T07:02:47.471 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:48.094 INF source/core/discovery/repository.go:91 > Returning 384 unique proposals
2021-01-24T07:02:52.876 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T07:02:52.876 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:02:52.876 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:02:52.876 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:02:52.876 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T07:02:52.876 INF source/core/connection/manager.go:601 > Connection state: Connecting -> NotConnected
2021-01-24T07:02:52.876 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 07:01:49.9279561 -0500 EST m=+11.996361401 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:Washington ASN:7922 ISP:Comcast Cable NodeType:residential} LocationOriginate:{Continent:NA Country:US City:Washington ASN:7922 ISP:Comcast Cable NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:6m40s Bytes:107374182400 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:02:52.876 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:1m2.948449s}
2021-01-24T07:02:52.876 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:1m0.010119s}
2021-01-24T07:02:52.876 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:02:52.876 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:02:52.876 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:532.4342ms}
2021-01-24T07:02:52.876 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:02:52.876 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:02:52.876 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:59.4776848s}
2021-01-24T07:02:52.876 INF source/core/state/state.go:404 > Session ID NotConnected duration: 1m2.948449s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:02:52.877 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 1m2.948449s, "Consumer P2P channel creation" took 1m0.010119s, "Consumer P2P connect" took 532.4342ms, "Consumer P2P exchange" took 59.4776848s
2021-01-24T07:02:52.876 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:02:52.877 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:02:52.877 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859.wireguard.p2p-config-exchange: context deadline exceeded Stage:connection_unknown_error}
2021-01-24T07:02:52.877 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xd46c4a30a1860fe1e3e32e4dfdb0de4aff4f9859.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:02:52.883 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:02:52.883 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:02:52.883 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:02:52.884 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:02:53.441 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:02:53.441 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:02:57.461 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:02:58.203 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:02:58.205 INF source/core/discovery/repository.go:91 > Returning 391 unique proposals
2021-01-24T07:03:06.921 ERR source/core/location/cache.go:102 > Location update failed error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."
2021-01-24T07:03:06.921 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:03:06.921 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:02:53.4417475 -0500 EST m=+75.510152801 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:New York ASN:40545 ISP:Empire Access NodeType:residential} LocationOriginate:{Continent:NA Country:US City:New York ASN:40545 ISP:Empire Access NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:10m0s Bytes:26843545 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:03:06.921 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:03:06.921 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:03:06.921 INF source/core/state/state.go:404 > Session ID Connecting duration: 13.4795041s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:03:06.921 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:03:07.457 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 7fb5a694d99a5738e9d8bdb2f195f7dc89d0801f3136477b1b202535faa91813 to provider 0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9
2021-01-24T07:03:07.464 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:07.998 INF source/core/discovery/repository.go:91 > Returning 398 unique proposals
2021-01-24T07:03:17.457 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:18.106 INF source/core/discovery/repository.go:91 > Returning 407 unique proposals
2021-01-24T07:03:27.467 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:28.043 INF source/core/discovery/repository.go:91 > Returning 417 unique proposals
2021-01-24T07:03:37.464 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:37.866 INF source/core/discovery/repository.go:91 > Returning 420 unique proposals
2021-01-24T07:03:47.457 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:47.870 INF source/core/discovery/repository.go:91 > Returning 428 unique proposals
2021-01-24T07:03:57.457 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:03:57.942 INF source/core/discovery/repository.go:91 > Returning 434 unique proposals
2021-01-24T07:04:06.926 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:04:06.926 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:04:06.926 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:04:06.926 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:04:06.926 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T07:04:06.926 INF source/core/connection/manager.go:601 > Connection state: Connecting -> NotConnected
2021-01-24T07:04:06.926 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 07:02:53.4417475 -0500 EST m=+75.510152801 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:New York ASN:40545 ISP:Empire Access NodeType:residential} LocationOriginate:{Continent:NA Country:US City:New York ASN:40545 ISP:Empire Access NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:10m0s Bytes:26843545 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:04:06.926 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:1m13.4842695s}
2021-01-24T07:04:06.926 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:04:06.926 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:1m0.0047654s}
2021-01-24T07:04:06.926 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:04:06.926 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:535.9704ms}
2021-01-24T07:04:06.926 INF source/core/state/state.go:404 > Session ID NotConnected duration: 1m13.4842695s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:04:06.926 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:04:06.926 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:04:06.927 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:59.468795s}
2021-01-24T07:04:06.927 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:04:06.927 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 1m13.4842695s, "Consumer P2P channel creation" took 1m0.0047654s, "Consumer P2P connect" took 535.9704ms, "Consumer P2P exchange" took 59.468795s
2021-01-24T07:04:06.927 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:04:06.927 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9.wireguard.p2p-config-exchange: context deadline exceeded Stage:connection_unknown_error}
2021-01-24T07:04:06.927 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x9d58193a1bc61a4c6fbb5f21fd4808939ef516f9.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:04:06.931 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:04:06.931 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:04:06.931 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:04:06.931 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:04:07.351 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:04:07.351 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:04:07.458 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:08.049 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:04:08.049 INF source/core/discovery/repository.go:91 > Returning 439 unique proposals
2021-01-24T07:04:17.457 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:18.026 INF source/core/discovery/repository.go:91 > Returning 444 unique proposals
2021-01-24T07:04:20.957 ERR source/core/location/cache.go:102 > Location update failed error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."
2021-01-24T07:04:20.957 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:04:20.957 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:04:07.3512661 -0500 EST m=+149.419671401 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:Arizona ASN:22773 ISP:Cox Communications NodeType:residential} LocationOriginate:{Continent:NA Country:US City:Arizona ASN:22773 ISP:Cox Communications NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:20m0s Bytes:10737418 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:04:20.957 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:04:20.957 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:04:20.957 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:04:20.957 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:04:20.957 INF source/core/state/state.go:404 > Session ID Connecting duration: 13.6065587s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:04:20.957 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:04:20.958 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:04:20.958 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:04:20.958 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:04:20.958 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:04:20.958 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:04:21.422 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 74d0d49f2bc38d582ba31b90734d611e6f3e9fea0173a909016995a4053a9970 to provider 0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2
2021-01-24T07:04:27.468 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:28.044 INF source/core/discovery/repository.go:91 > Returning 449 unique proposals
2021-01-24T07:04:37.463 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:37.957 INF source/core/discovery/repository.go:91 > Returning 454 unique proposals
2021-01-24T07:04:47.470 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:47.903 INF source/core/discovery/repository.go:91 > Returning 461 unique proposals
2021-01-24T07:04:57.468 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:04:57.877 INF source/core/discovery/repository.go:91 > Returning 461 unique proposals
2021-01-24T07:05:07.460 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:07.997 INF source/core/discovery/repository.go:91 > Returning 461 unique proposals
2021-01-24T07:05:17.462 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:17.921 INF source/core/discovery/repository.go:91 > Returning 461 unique proposals
2021-01-24T07:05:20.965 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:05:20.965 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:05:20.965 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:05:20.965 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:05:20.965 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T07:05:20.965 INF source/core/connection/manager.go:601 > Connection state: Connecting -> NotConnected
2021-01-24T07:05:20.965 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 07:04:07.3512661 -0500 EST m=+149.419671401 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:NA Country:US City:Arizona ASN:22773 ISP:Cox Communications NodeType:residential} LocationOriginate:{Continent:NA Country:US City:Arizona ASN:22773 ISP:Cox Communications NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:20m0s Bytes:10737418 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:05:20.966 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:1m13.6149838s}
2021-01-24T07:05:20.966 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:05:20.966 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:05:20.966 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:1m0.0074222s}
2021-01-24T07:05:20.966 INF source/core/state/state.go:404 > Session ID NotConnected duration: 1m13.6149838s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:05:20.966 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:464.967ms}
2021-01-24T07:05:20.966 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:05:20.966 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:05:20.966 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:59.5424552s}
2021-01-24T07:05:20.966 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:05:20.966 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 1m13.6149838s, "Consumer P2P channel creation" took 1m0.0074222s, "Consumer P2P connect" took 464.967ms, "Consumer P2P exchange" took 59.5424552s
2021-01-24T07:05:20.966 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:05:20.966 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2.wireguard.p2p-config-exchange: context deadline exceeded Stage:connection_unknown_error}
2021-01-24T07:05:20.966 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0xfe42f63dea9c34591ef7870c4da28eb97b6bd6a2.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:05:20.972 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:20.972 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:20.972 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x54f0985efd1e9365ba776e60aa19d551c8c5f969 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:05:20.972 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:05:21.551 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:05:21.551 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:27.458 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:27.786 INF source/tequilapi/endpoints/stop.go:44 > Application stop requested
2021-01-24T07:05:28.109 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:05:28.110 INF source/core/discovery/repository.go:91 > Returning 461 unique proposals
2021-01-24T07:05:28.641 ??? github.com/rs/zerolog@v1.17.2/log.go:403 > http: superfluous response.WriteHeader call from github.com/mysteriumnetwork/node/tequilapi/utils.WriteAsJSON (utils.go:38)
2021-01-24T07:05:36.607 DBG source/logconfig/rollingwriter/rollingwriter.go:76 > Found 0 old log files in log directory, skipping cleanup
2021-01-24T07:05:36.607 INF source/cmd/di.go:188 > Starting Mysterium Node 0.41.2
2021-01-24T07:05:36.608 DBG source/config/config.go:196 > Returning default value outgoing-firewall:false
2021-01-24T07:05:36.608 DBG source/config/config.go:196 > Returning default value incoming-firewall:false
2021-01-24T07:05:36.608 INF source/firewall/incoming_firewall_noop.go:32 > Rules bootstrap was requested
2021-01-24T07:05:36.608 DBG source/config/config.go:187 > Returning CLI value usermode:true
2021-01-24T07:05:36.608 INF source/cmd/di.go:650 > Using local DNS: testnet2-location.mysterium.network -> [95.216.204.232]
2021-01-24T07:05:36.608 INF source/cmd/di.go:650 > Using local DNS: feedback.mysterium.network -> [116.203.17.150]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: api.ipify.org -> [54.204.14.42 54.225.153.147 54.235.83.248 54.243.161.145 23.21.109.69 23.21.126.66 50.19.252.36 174.129.214.20]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2-broker.mysterium.network -> [95.216.204.232]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2-transactor.mysterium.network -> [135.181.82.67]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2.mysterium.network -> [138.201.174.94]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet-location.mysterium.network -> [82.196.15.9]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: badupnp.benjojo.co.uk -> [104.22.70.70 104.22.71.70 172.67.25.154]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2-trust.mysterium.network -> [95.216.204.232]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2-api.mysterium.network -> [78.47.55.197]
2021-01-24T07:05:36.609 INF source/cmd/di.go:650 > Using local DNS: testnet2-quality.mysterium.network -> [116.202.100.246]
2021-01-24T07:05:36.609 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222]
2021-01-24T07:05:36.609 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:36.609 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:36.609 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:05:37.061 INF source/cmd/di.go:675 > Using Eth endpoint: wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637
2021-01-24T07:05:37.510 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-24T07:05:37.510 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-24T07:05:37.510 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-24T07:05:37.510 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-24T07:05:37.510 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL wss://goerli.infura.io/ws/v3/c2c7da73fcc84ec5885a7bb0eb3c3637 access
2021-01-24T07:05:37.510 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-api.mysterium.network/v1 access
2021-01-24T07:05:37.510 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-transactor.mysterium.network/api/v1 access
2021-01-24T07:05:37.510 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://betanet-hermes.mysterium.network/api/v2 access
2021-01-24T07:05:37.510 DBG source/cmd/di.go:725 > Using lightweight keystore
2021-01-24T07:05:37.699 INF source/core/discovery/dhtdiscovery/node.go:86 > DHT node started on [/ip4/192.168.2.166/tcp/2398 /ip4/169.254.203.247/tcp/2398 /ip4/169.254.82.79/tcp/2398 /ip4/169.254.147.99/tcp/2398 /ip4/169.254.147.75/tcp/2398 /ip4/169.254.194.210/tcp/2398 /ip4/127.0.0.1/tcp/2398] with ID=QmcWG8Nx74neUjWcQdm3keKMRUQbULAZULcE2hEZoXWytQ
2021-01-24T07:05:37.700 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:05:37.700 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:05:37.700 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:05:37.700 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet-location.mysterium.network/api/v1/location access
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:05:37.700 DBG source/config/config.go:187 > Returning CLI value testnet2:true
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value testnet:false
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value data-dir:C:\Users\userxxx.mysterium
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value mmn.api-address:https://testnet2.mysterium.network/api/v1
2021-01-24T07:05:37.700 DBG source/cmd/di.go:888 > Experimental NAT punching enabled, creating a pinger
2021-01-24T07:05:37.700 DBG source/config/config.go:196 > Returning default value nat-port-mapping:true
2021-01-24T07:05:37.700 DBG source/cmd/di_desktop.go:57 > Skipping services bootstrap for consumer mode
2021-01-24T07:05:37.700 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-24T07:05:37.700 INF source/firewall/incoming_firewall_noop.go:53 > Allow URL https://testnet2-quality.mysterium.network/api/v2 access
2021-01-24T07:05:37.701 DBG source/cmd/di_desktop.go:191 > Skipping hermes promise settler for consumer mode
2021-01-24T07:05:37.701 DBG source/cmd/di_desktop.go:163 > Skipping provider registrar for consumer mode
2021-01-24T07:05:37.701 INF source/firewall/outgoing_firewall_noop.go:48 > Allow IP 239.255.255.250 access
2021-01-24T07:05:37.701 INF source/pilvytis/order_status_tracker.go:102 > Tracking order statuses...
2021-01-24T07:05:37.701 DBG source/config/config.go:196 > Returning default value access-policy.address:https://testnet2-trust.mysterium.network/api/v1/access-policies/
2021-01-24T07:05:37.701 DBG source/config/config.go:196 > Returning default value pprof.enable:false
2021-01-24T07:05:37.701 INF source/tequilapi/http_api_server.go:77 > API started on: 127.0.0.1:4050
2021-01-24T07:05:37.701 DBG source/sleep/sleep_windows.go:27 > Register for sleep log events
2021-01-24T07:05:37.701 DBG source/ui/noop/noop.go:35 > Start: NOOP UI server
2021-01-24T07:05:37.701 DBG source/eventbus/event_bus.go:81 > Published topic="Node" event={Status:Started}
2021-01-24T07:05:37.702 INF source/cmd/di.go:271 > Mysterium node started!
2021-01-24T07:05:37.702 DBG source/core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP
2021-01-24T07:05:37.702 DBG source/identity/registry/registry_contract.go:106 > event received {Started}
2021-01-24T07:05:37.702 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:37.702 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:05:37.702 INF source/identity/registry/registry_contract.go:272 > Starting registry...
2021-01-24T07:05:37.702 DBG source/identity/registry/registry_contract.go:283 > Loading initial state
2021-01-24T07:05:37.702 DBG source/identity/registry/registry_contract.go:298 > Identity {"0x999999"} already registered, skipping
2021-01-24T07:05:38.091 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:38.095 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:38.095 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:38.145 DBG source/identity/manager.go:148 > Caching unlocked address: 0x999999
2021-01-24T07:05:38.146 DBG source/identity/manager.go:135 > Unlocked identity found in cache, skipping keystore: 0x999999
2021-01-24T07:05:38.146 DBG source/eventbus/event_bus.go:81 > Published topic="identity-unlocked" event={ChainID:5 ID:{Address:0x999999}}
2021-01-24T07:05:38.859 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:05:38.859 INF source/core/discovery/repository.go:91 > Returning 330 unique proposals
2021-01-24T07:05:38.875 DBG source/session/pingpong/consumer_balance_tracker.go:436 > Loaded hermes state: already promised: 0
2021-01-24T07:05:38.876 DBG source/eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+0 ChainID:5 HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] ConsumerID:{Address:0x999999}}
2021-01-24T07:05:39.002 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+0 Current:+5000000000000000000}
2021-01-24T07:05:39.011 DBG source/eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x999999} Previous:+5000000000000000000 Current:+5000000000000000000}
2021-01-24T07:05:39.101 INF source/session/pingpong/consumer_balance_tracker.go:217 > Subscribed to channel 0xF6Db82e43c272d30c087E6a4503F6066a74aC58b balance events
2021-01-24T07:05:39.802 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-wifialliance-org:device:WFADevice:1 friendlyName:ASUS WPS Router manufacturer:ASUSTeK Corporation modelName:WPS Router modelNo:X1 server:POSIX UPnP/1.0 UPnP Stack/7.14.164.3]
2021-01-24T07:05:39.812 DBG source/nat/upnp/discover.go:90 > not a gateway device: map[deviceType:urn:schemas-upnp-org:device:MediaServer:1 friendlyName:Home Hub 2000 manufacturer:PacketVideo modelName:TwonkyMedia modelNo:4.4.18 server:Linux/2.x.x, UPnP/1.0, pvConnect UPnP SDK/1.0]
2021-01-24T07:05:39.812 INF source/nat/upnp/discover.go:58 > UPnP gateways detected: 1
2021-01-24T07:05:39.812 INF source/nat/upnp/discover.go:60 > UPnP gateway detected map[deviceType:urn:schemas-upnp-org:device:InternetGatewayDevice:1 friendlyName:Home Hub 2000 Internet Gateway Device manufacturer:Sagemcom modelName:Sagemcom IDG WAN modelNo: server:Linux/2.6.28.8, UPnP/1.0, Portable SDK for UPnP devices/1.6.18]
2021-01-24T07:05:46.097 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:46.689 INF source/core/discovery/repository.go:91 > Returning 332 unique proposals
2021-01-24T07:05:51.730 WRN source/core/location/cache.go:121 > Failed to detect original location error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."
2021-01-24T07:05:51.829 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:51.829 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:51.829 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:05:51.829 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:05:52.419 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:05:52.419 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:05:52.419 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:05:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:05:52.4190688 -0500 EST m=+15.857173601 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential} LocationOriginate:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:1h40m0s Bytes:107374182 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:05:52.419 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:52.419 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:52.419 INF source/core/state/state.go:404 > Session ID Connecting duration: 0s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:05:52.419 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:05:52.420 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:05:52.420 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:05:52.852 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 00de7c48ea90c9cdacf1bd16383e09ad17f10f34f9e40d2ca37d6d07202eb06e to provider 0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef
2021-01-24T07:05:56.094 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:05:56.803 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:05:56.804 INF source/core/discovery/repository.go:91 > Returning 338 unique proposals
2021-01-24T07:06:06.094 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:06.678 INF source/core/discovery/repository.go:91 > Returning 344 unique proposals
2021-01-24T07:06:08.242 INF source/pilvytis/order_status_tracker.go:126 > Pausing order status tracking
2021-01-24T07:06:16.093 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:16.675 INF source/core/discovery/repository.go:91 > Returning 354 unique proposals
2021-01-24T07:06:26.085 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:26.558 INF source/core/discovery/repository.go:91 > Returning 362 unique proposals
2021-01-24T07:06:36.096 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:36.546 INF source/core/discovery/repository.go:91 > Returning 365 unique proposals
2021-01-24T07:06:46.091 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:46.702 INF source/core/discovery/repository.go:91 > Returning 375 unique proposals
2021-01-24T07:06:52.419 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:06:52.419 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:06:52.419 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:06:52.419 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:06:52.419 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T07:06:52.419 INF source/core/connection/manager.go:601 > Connection state: Connecting -> NotConnected
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 07:05:52.4190688 -0500 EST m=+15.857173601 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential} LocationOriginate:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:1h40m0s Bytes:107374182 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:1m0.0008254s}
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:1m0.0008254s}
2021-01-24T07:06:52.419 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:06:52.419 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:431.9173ms}
2021-01-24T07:06:52.419 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:59.5689081s}
2021-01-24T07:06:52.419 INF source/core/state/state.go:404 > Session ID NotConnected duration: 1m0.0008254s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:06:52.419 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:06:52.419 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 1m0.0008254s, "Consumer P2P channel creation" took 1m0.0008254s, "Consumer P2P connect" took 431.9173ms, "Consumer P2P exchange" took 59.5689081s
2021-01-24T07:06:52.419 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:06:52.419 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef.wireguard.p2p-config-exchange: context deadline exceeded Stage:connection_unknown_error}
2021-01-24T07:06:52.419 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:06:52.420 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x425b1d639d7b4101669cdf1fb0ee5dcfc1c0f0ef.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:06:52.427 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:06:52.427 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:06:52.427 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:06:52.427 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:06:52.918 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:06:52.918 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:06:53.956 ERR source/core/location/cache.go:102 > Location update failed error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: No connection could be made because the target machine actively refused it.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: No connection could be made because the target machine actively refused it."
2021-01-24T07:06:53.956 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:06:53.956 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:06:52.9182008 -0500 EST m=+76.356305601 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential} LocationOriginate:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:50m0s Bytes:107374182 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:06:53.956 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:06:53.956 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:06:53.956 INF source/core/state/state.go:404 > Session ID Connecting duration: 1.0381686s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:06:53.956 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:06:54.501 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key 1c3f48dd493d45e0d5df64016b510223403debcd15cdd4437ed9dd09fcb85251 to provider 0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06
2021-01-24T07:06:56.093 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:06:56.835 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:06:56.835 INF source/core/discovery/repository.go:91 > Returning 380 unique proposals
2021-01-24T07:07:06.089 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:06.731 INF source/core/discovery/repository.go:91 > Returning 385 unique proposals
2021-01-24T07:07:16.084 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:17.126 INF source/core/discovery/repository.go:91 > Returning 391 unique proposals
2021-01-24T07:07:26.089 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:26.665 INF source/core/discovery/repository.go:91 > Returning 397 unique proposals
2021-01-24T07:07:36.092 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:36.790 INF source/core/discovery/repository.go:91 > Returning 400 unique proposals
2021-01-24T07:07:46.095 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:46.724 INF source/core/discovery/repository.go:91 > Returning 413 unique proposals
2021-01-24T07:07:53.971 WRN source/communication/nats/connection_wrap.go:95 > NATS: disconnected
2021-01-24T07:07:53.971 WRN source/communication/nats/connection_wrap.go:94 > NATS: connection closed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:07:53.971 INF source/firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2021-01-24T07:07:53.971 ERR source/core/connection/manager.go:217 > Connect failed, disconnecting error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:07:53.971 DBG source/core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2021-01-24T07:07:53.971 INF source/core/connection/manager.go:601 > Connection state: Connecting -> NotConnected
2021-01-24T07:07:53.971 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2021-01-24 07:06:52.9182008 -0500 EST m=+76.356305601 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential} LocationOriginate:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:50m0s Bytes:107374182 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:07:53.971 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer whole Connect Duration:1m1.0530136s}
2021-01-24T07:07:53.971 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P channel creation Duration:1m0.014845s}
2021-01-24T07:07:53.971 DBG source/core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2021-01-24T07:07:53.971 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:07:53.971 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:07:53.971 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P connect Duration:545.3047ms}
2021-01-24T07:07:53.971 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:07:53.971 INF source/core/state/state.go:404 > Session ID NotConnected duration: 1m1.0530136s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:07:53.971 DBG source/eventbus/event_bus.go:81 > Published topic="Trace" event={ID: Key:Consumer P2P exchange Duration:59.4695403s}
2021-01-24T07:07:53.971 DBG source/core/connection/manager.go:191 > Consumer connection trace: "Consumer whole Connect" took 1m1.0530136s, "Consumer P2P channel creation" took 1m0.014845s, "Consumer P2P connect" took 545.3047ms, "Consumer P2P exchange" took 59.4695403s
2021-01-24T07:07:53.971 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:07:53.971 WRN source/core/quality/sender.go:297 > Can't recover session context error="unknown session: "
2021-01-24T07:07:53.972 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error:could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06.wireguard.p2p-config-exchange: context deadline exceeded Stage:connection_unknown_error}
2021-01-24T07:07:53.972 ERR source/tequilapi/endpoints/connection.go:221 > Failed to connect error="could not create p2p channel during connect: p2p dialer failed: could not exchange config: could not send signed message: could not send broker request to subject 0x2c1b1b7be1411d9e9b1f6d7032818c8555434c06.wireguard.p2p-config-exchange: context deadline exceeded"
2021-01-24T07:07:53.976 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:07:53.976 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:07:53.976 DBG source/eventbus/event_bus.go:81 > Published topic="connection_events" event={ServiceType:wireguard ProviderID:0xd1aca018e658b0152df25451c7ee0a665fc6f080 ConsumerID:0x999999 HermesID:0xD5d2f5729D4581dfacEBedF46C7014DeFda43585 Error: Stage:registration_registered}
2021-01-24T07:07:53.976 INF source/tequilapi/endpoints/connection.go:184 > identity "0x999999" is registered, continuing...
2021-01-24T07:07:54.584 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 1 supported: 1
2021-01-24T07:07:54.584 DBG source/config/config.go:196 > Returning default value chain-id:5
2021-01-24T07:07:56.083 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:07:56.721 DBG source/market/mysterium/mysterium_api.go:271 > Total proposals: 330 supported: 330
2021-01-24T07:07:56.721 INF source/core/discovery/repository.go:91 > Returning 425 unique proposals
2021-01-24T07:08:06.144 DBG source/core/discovery/repository.go:61 > Retrieving proposals from 3 repositories
2021-01-24T07:08:06.829 INF source/core/discovery/repository.go:91 > Returning 431 unique proposals
2021-01-24T07:08:07.991 ERR source/core/location/cache.go:102 > Location update failed error="failed to execute request: Get https://testnet-location.mysterium.network/api/v1/location: failed to dial testnet-location.mysterium.network:443: all dials failed\n [82.196.15.9:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.\n [testnet-location.mysterium.network:443] dial tcp 0.0.0.0:0->82.196.15.9:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."
2021-01-24T07:08:07.991 INF source/core/connection/manager.go:601 > Connection state: NotConnected -> Connecting
2021-01-24T07:08:07.991 DBG source/eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2021-01-24 07:07:54.5846646 -0500 EST m=+138.022769401 ConsumerID:{Address:0x999999} ConsumerLocation:{IP: ASN:0 ISP: Continent: Country: City: NodeType:} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID: Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential} LocationOriginate:{Continent:EU Country:GB City:England ASN:5089 ISP:Virgin Media NodeType:residential}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYSTT Duration:5m0s Bytes:53687091 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0xd1aca018e658b0152df25451c7ee0a665fc6f080 ProviderContacts:[{Type:nats/p2p/v1 Definition:{BrokerAddresses:[nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]}}] AccessPolicies:}}}
2021-01-24T07:08:07.991 DBG source/communication/nats/connector.go:65 > Connecting to NATS servers: [nats://testnet2-broker.mysterium.network:4222 nats://testnet2-broker.mysterium.network:4222 nats://95.216.204.232:4222]
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:08:07.991 DBG source/config/config.go:196 > Returning default value default-currency:MYSTT
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:08:07.991 INF source/core/state/state.go:404 > Session ID Connecting duration: 13.4065461s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYSTT
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:08:07.991 INF source/firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2021-01-24T07:08:08.456 DBG source/p2p/dialer.go:175 > Consumer 0x999999 sending public key fb3ccb0b68edcdb55004e766b48ff8ab4c2ca7c0dd135e09849ea23d801f8274 to provider 0xd1aca018e658b0152df25451c7ee0a665fc6f080