2020-12-10T10:46:58.391 DBG eventbus/event_bus.go:81 > Published topic="sleep_notification" event=2
2020-12-10T10:46:58.392 INF sleep/sleep.go:77 > Got sleep notification during live vpn session
2020-12-10T10:47:11.820 DBG core/connection/manager.go:789 > Received p2p keepalive ping with SessionID=d770ccd0-06f6-4a6f-8eb9-c36139fc2959
2020-12-10T10:47:25.952 DBG core/connection/manager.go:789 > Received p2p keepalive ping with SessionID=d770ccd0-06f6-4a6f-8eb9-c36139fc2959
2020-12-10T10:47:26.466 DBG session/pingpong/factory.go:197 > Received P2P message for "p2p-payment-invoice": AgreementID:"24185227721865343437075870666212806174385580513979221850375603822455332971452" AgreementTotal:"21079557279490866" TransactorFee:"0" Hashlock:"d07875bd70468888f64500095f8448705a41c46cb2d8d668d35a8c64aa17aedf" Provider:"0x070a908615c53ff0aa69c4e802142791c7d9ef09" ChainID:5
2020-12-10T10:47:26.466 DBG session/pingpong/invoice_payer.go:144 > Invoice received: {24185227721865343437075870666212806174385580513979221850375603822455332971452 21079557279490866 0 d07875bd70468888f64500095f8448705a41c46cb2d8d668d35a8c64aa17aedf 0x070a908615c53ff0aa69c4e802142791c7d9ef09 5}
2020-12-10T10:47:26.467 DBG session/pingpong/price_calculator.go:72 > Calculated price 79323857407453836. Time component: 5.530151133285891696e+15, data component: 7.379370627416794548e+16
2020-12-10T10:47:26.467 DBG session/pingpong/invoice_payer.go:189 > Estimated tolerance 1.221, upper bound 96881305426714519
2020-12-10T10:47:26.467 DBG session/pingpong/invoice_payer.go:242 > Loaded previous state: already promised: 849192138997465093
2020-12-10T10:47:26.467 DBG session/pingpong/invoice_payer.go:243 > Incrementing promised amount by 1410404974501819
2020-12-10T10:47:26.467 DBG session/pingpong/exchange_messaging.go:68 > Sending P2P message to "p2p-payment-message": Promise:{ChannelID:"`\xc9\x13~\x18\x9b\x9a\xad\x1f\x9a\r)\x13i\xe2\x11\xa0w\x02\xbf" Amount:"850602543971966912" Fee:"0" Hashlock:"\xd0xu\xbdpF\x88\x88\xf6E\x00\t_\x84HpZA\xc4l\xb2\xd8\xd6h\xd3Z\x8cd\xaa\x17\xae\xdf" ChainID:5 Signature:"\xe8G\xec&i\x9b\x1a\xbf\xa4\x05\x81\xee\xf53\xcbM\x8e)Z\xf9\x83)MS:\x9e\x976V\rg\x82 �3\xd9\xdd7\x1b25\xe1u\xc4×vnw\x89>\xe3qD\xf9*\x9b\xda.\x97\x86\xd6@\xaf\x1c"} AgreementID:"24185227721865343437075870666212806174385580513979221850375603822455332971452" AgreementTotal:"21079557279490866" Provider:"0x070a908615c53ff0aa69c4e802142791c7d9ef09" Signature:"65cd7b80b4345ad93b52608f1edb147190cec01de8533780744cc4e988d09002590c294044418fa5f556c42ee73d5bb4fa9ff88f07d26ea55f734da6568b25691c" HermesID:"0xD5d2f5729D4581dfacEBedF46C7014DeFda43585" ChainID:5
2020-12-10T10:47:26.669 DBG eventbus/event_bus.go:81 > Published topic="invoice_paid" event={ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} SessionID:d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Invoice:{AgreementID:+24185227721865343437075870666212806174385580513979221850375603822455332971452 AgreementTotal:+21079557279490866 TransactorFee:+0 Hashlock:d07875bd70468888f64500095f8448705a41c46cb2d8d668d35a8c64aa17aedf Provider:0x070a908615c53ff0aa69c4e802142791c7d9ef09 ChainID:5}}
2020-12-10T10:47:26.699 DBG consumer/session/session_storage.go:271 > Session d770ccd0-06f6-4a6f-8eb9-c36139fc2959 updated
2020-12-10T10:47:26.770 DBG eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+850602543971966912 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:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72}}
2020-12-10T10:47:26.770 DBG eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} Previous:+25000000000000000000 Current:+24149397456028033088}
2020-12-10T10:47:26.908 INF core/state/state.go:447 > Session ID d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Connected duration: 8m2.833831125s data: 4.2MiB/1.0MiB, throughput: 5.2KiBs/3.1KiBs, spent: 0.021080MYST
DEBUG: [userspace-wg]2020/12/10 10:47:27 peer(sptu…VuBY) - Sending handshake initiation
DEBUG: [userspace-wg]2020/12/10 10:47:27 peer(sptu…VuBY) - Received handshake response
DEBUG: [userspace-wg]2020/12/10 10:47:27 peer(sptu…VuBY) - Sending keepalive packet
2020-12-10T10:47:29.947 INF market/mysterium/mysterium_api.go:309 > Session stats sent: d770ccd0-06f6-4a6f-8eb9-c36139fc2959
2020-12-10T10:47:29.948 DBG consumer/statistics/reporter.go:107 > Stats sent
2020-12-10T10:47:40.084 DBG core/connection/manager.go:789 > Received p2p keepalive ping with SessionID=d770ccd0-06f6-4a6f-8eb9-c36139fc2959
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
2020-12-10T10:52:34.088 DBG eventbus/event_bus.go:81 > Published topic="sleep_notification" event=1
2020-12-10T10:52:34.092 INF sleep/sleep.go:79 > Got wake-up from sleep notification - checking if need to reconnect
2020-12-10T10:52:34.095 ERR p2p/channel.go:312 > Write to remote peer conn failed error="write udp4 192.168.0.107:44663->78.47.91.5:42823: sendto: network is down"
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
ERROR: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Failed to send data packet write udp4 0.0.0.0:44890->78.47.91.5:41200: sendto: network is down
2020-12-10T10:52:34.294 INF sleep/sleep.go:86 > Channel dead - reconnecting: keep alive ping failed: timeout waiting for reply to "p2p-keepalive": p2p send timeout
2020-12-10T10:52:34.294 INF core/connection/manager.go:603 > Connection state: Connected -> Disconnecting
2020-12-10T10:52:34.294 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:Disconnecting SessionInfo:{StartedAt:2020-12-10 10:39:21.985951 +0600 +06 m=+16.175853587 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Disconnecting SessionID:d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:34.296 INF firewall/outgoing_firewall_noop.go:42 > Outgoing traffic block removed
2020-12-10T10:52:34.296 INF services/wireguard/connection/connection.go:198 > Stopping WireGuard connection
2020-12-10T10:52:34.296 INF firewall/outgoing_firewall_noop.go:50 > Rule for IP: 78.47.91.5 removed
INFO: [userspace-wg]2020/12/10 10:52:34 Device closing
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: TUN reader - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: event worker - stopped
2020-12-10T10:52:34.297 DBG core/connection/manager.go:798 > Stopping p2p keepalive: context canceled
2020-12-10T10:52:34.297 INF core/state/state.go:404 > Session ID d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Disconnecting duration: 8m22.41928933s data: 4.3MiB/1.0MiB, throughput: 2.5KiBs/435Bs, spent: 0.021080MYST
2020-12-10T10:52:34.297 INF core/connection/stats_publisher.go:63 > Stopped publishing connection statistics
2020-12-10T10:52:34.297 DBG core/connection/manager.go:740 > Connection state received: Disconnecting
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: receive incoming IPv4 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: receive incoming IPv6 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Stopping...
DEBUG: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Routine: sequential receiver - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Routine: sequential sender - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:34 peer(sptu…VuBY) - Routine: nonce worker - stopped
INFO: [userspace-wg]2020/12/10 10:52:34 Interface closed
2020-12-10T10:52:35.588 INF core/connection/manager.go:698 > Connection exited
2020-12-10T10:52:35.588 INF utils/netutil/network.go:79 > Cleaning stale route: 78.47.91.5 192.168.0.1
2020-12-10T10:52:35.588 DBG core/connection/manager.go:740 > Connection state received: NotConnected
2020-12-10T10:52:35.588 DBG core/connection/manager.go:735 > State updater stopCalled
2020-12-10T10:52:35.753 DBG utils/netutil/network_darwin.go:36 > "route delete 78.47.91.5 192.168.0.1" output:
delete host 78.47.91.5: gateway 192.168.0.1
2020-12-10T10:52:35.766 DBG eventbus/event_bus.go:81 > Published topic="Session" event={Status:Ended SessionInfo:{StartedAt:2020-12-10 10:39:21.985951 +0600 +06 m=+16.175853587 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Disconnecting SessionID:d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:35.793 DBG consumer/session/session_storage.go:293 > Session d770ccd0-06f6-4a6f-8eb9-c36139fc2959 updated with final data
2020-12-10T10:52:35.793 DBG consumer/statistics/reporter.go:128 > Session statistics reporter stopping
2020-12-10T10:52:35.793 DBG session/pingpong/invoice_payer.go:282 > Stopping...
2020-12-10T10:52:35.794 DBG core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2020-12-10T10:52:35.794 INF core/connection/manager.go:603 > Connection state: Disconnecting -> NotConnected
2020-12-10T10:52:35.794 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2020-12-10 10:39:21.985951 +0600 +06 m=+16.175853587 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID:d770ccd0-06f6-4a6f-8eb9-c36139fc2959 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:35.794 DBG core/connection/manager.go:509 > Sending P2P message to "p2p-session-destroy": consumerID:"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72" sessionID:"d770ccd0-06f6-4a6f-8eb9-c36139fc2959"
2020-12-10T10:52:35.794 DBG core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2020-12-10T10:52:35.794 INF cmd/di.go:912 > Reconnecting HTTP clients due to VPN connection state change
2020-12-10T10:52:35.794 INF core/state/state.go:404 > Session ID d770ccd0-06f6-4a6f-8eb9-c36139fc2959 NotConnected duration: 8m23.916826538s data: 0b/0b, throughput: 0bs/0bs, spent: %!s(PANIC=String method: runtime error: invalid memory address or nil pointer dereference)
2020-12-10T10:52:36.331 INF market/mysterium/mysterium_api.go:309 > Session stats sent: d770ccd0-06f6-4a6f-8eb9-c36139fc2959
2020-12-10T10:52:36.331 DBG consumer/statistics/reporter.go:100 > Final stats sent
2020-12-10T10:52:38.300 WRN core/connection/manager.go:400 > Cleanup error error="could not send session destroy request: timeout waiting for reply to \"p2p-session-destroy\": p2p send timeout"
2020-12-10T10:52:38.300 INF core/connection/manager.go:839 > Waiting for previous session to cleanup
2020-12-10T10:52:38.300 DBG config/config.go:196 > Returning default value chain-id:5
2020-12-10T10:52:38.481 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential}
2020-12-10T10:52:38.481 DBG core/location/cache.go:106 > Location update succeeded: {5.57.12.18 8449 ElCat Ltd. AS KG Gorod Bishkek residential}
2020-12-10T10:52:38.481 INF core/connection/manager.go:603 > Connection state: NotConnected -> Connecting
2020-12-10T10:52:38.484 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:Connecting SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} 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:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:38.485 DBG 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]
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2020-12-10T10:52:38.485 INF core/state/state.go:404 > Session ID Connecting duration: 184.702855ms data: 0b/0b, throughput: 0bs/0bs, spent: %!s(PANIC=String method: runtime error: invalid memory address or nil pointer dereference)
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://testnet2-broker.mysterium.network:4222 access
2020-12-10T10:52:38.485 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2020-12-10T10:52:38.486 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://95.216.204.232:4222 access
2020-12-10T10:52:38.804 DBG p2p/dialer.go:175 > Consumer 0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72 sending public key e043f434b47e76c53d428d8f940657d66f8d457aa79f40b7f0673e0a3c7b9f29 to provider 0x070a908615c53ff0aa69c4e802142791c7d9ef09
2020-12-10T10:52:39.099 DBG p2p/dialer.go:202 > Consumer 0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72 received provider 0x070a908615c53ff0aa69c4e802142791c7d9ef09 with config: publicIP:"78.47.91.5" ports:46979 ports:44822
2020-12-10T10:52:39.099 DBG core/ip/cached_resolver.go:79 > Public IP cache is empty, fetching IP
2020-12-10T10:52:39.359 DBG eventbus/event_bus.go:81 > Published topic="ether-client-reconnect" event={}
2020-12-10T10:52:39.359 DBG identity/registry/registry_contract.go:269 > Loading initial state
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x0a5daabd6b513021bcbfa63b41751b13edf3515d"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x0d5bfee82db5208a6b1d1e6b8b473231517ed3f4"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x17786686cd8b7c764e9113045496e46423fcbca0"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x2f64da2b9df3085cae6daefcc0e5995cac980db1"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x6a876ab77dcb59733f600ac7c58095bb5d837ca8"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x6bf2e72cc56dc0f7e6d970d30dc300cdbc8bbca7"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x83d216cf8333859195ef9f249b79b9dd9b4e6da1"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0x855b8359f932cc5cfc5a9ac0c9d21f8e8e8783e6"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xad3de59c55f3b9dad98d983a07a0fab4b8669c1d"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xb017775fe27b3f3c5fc796be9a3d99ec7f4d3433"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xba921787f5573f31a98f9b976160674c754328fe"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xc988effa014b22a38092bb7d39d317ad3c289798"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xcadc91ab1ebe5b9b1ff735d099785941aa3e47ab"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xcf4cb02e68595c55694e54c0a79052c8a64a6a0f"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xd0b1ec7f59c1804f5eef19aa1c9f80b07a5738ae"} already registered, skipping
2020-12-10T10:52:39.360 DBG identity/registry/registry_contract.go:284 > Identity {"0xdb8e25744b50a5056b26b29f0dbc52cc35d9e950"} already registered, skipping
2020-12-10T10:52:39.605 INF session/pingpong/consumer_balance_tracker.go:213 > Subscribed to channel 0x60C9137E189B9Aad1f9A0d291369e211A07702bF balance events
2020-12-10T10:52:40.081 DBG core/ip/resolver.go:101 > IP detected: 5.57.12.18
2020-12-10T10:52:40.082 INF core/port/pool.go:68 > Supplying port 47924
2020-12-10T10:52:40.082 INF core/port/pool.go:68 > Supplying port 47594
2020-12-10T10:52:40.082 DBG p2p/dialer.go:228 > Consumer 0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72 sending ack with encrypted config to provider 0x070a908615c53ff0aa69c4e802142791c7d9ef09
2020-12-10T10:52:40.191 INF firewall/outgoing_firewall_noop.go:48 > Allow IP 78.47.91.5 access
2020-12-10T10:52:40.191 DBG p2p/dialer.go:273 > Skipping provider ping
2020-12-10T10:52:40.191 DBG p2p/dialer.go:124 > Received handlers ready message from provider
2020-12-10T10:52:40.191 DBG p2p/channel.go:206 > Creating p2p channel with local addr: 192.168.0.107:47924, UDP session addr: 127.0.0.1:63350, proxy addr: 127.0.0.1:59062, remote peer addr: x.x.x.x:46979
2020-12-10T10:52:40.192 DBG p2p/channel.go:546 > Will use service conn with local port: 47594, remote port: 44822
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2020-12-10T10:52:40.192 WRN communication/nats/connection_wrap.go:95 > NATS: disconnected
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2020-12-10T10:52:40.192 WRN communication/nats/connection_wrap.go:94 > NATS: connection closed
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://testnet2-broker.mysterium.network:4222 removed
2020-12-10T10:52:40.192 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2020-12-10T10:52:40.196 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://95.216.204.232:4222 removed
2020-12-10T10:52:40.196 DBG config/config.go:196 > Returning default value chain-id:5
2020-12-10T10:52:40.196 DBG session/pingpong/invoice_payer.go:125 > Starting...
2020-12-10T10:52:40.196 DBG core/connection/manager.go:472 > Sending P2P message to "p2p-session-create": consumer:{id:"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72" hermesID:"0xD5d2f5729D4581dfacEBedF46C7014DeFda43585" paymentVersion:"v3" location:{country:"KG"}} proposalID:1 config:"{\"PublicKey\":\"yfLzyyS0n2z71hs+sLGZaVc92yKJwAtkCRBLPZIKxTU=\",\"Ports\":null}"
2020-12-10T10:52:40.432 DBG session/pingpong/factory.go:197 > Received P2P message for "p2p-payment-invoice": AgreementID:"55357642357357631246364197615432384077216329141827586571043540548735847003683" AgreementTotal:"1" TransactorFee:"0" Hashlock:"4085b6ed81146b5386be70b0913ac60ca098add08e3c812bbb85abb54656ff7d" Provider:"0x070a908615c53ff0aa69c4e802142791c7d9ef09" ChainID:5
2020-12-10T10:52:40.432 DBG session/pingpong/invoice_payer.go:144 > Invoice received: {55357642357357631246364197615432384077216329141827586571043540548735847003683 1 0 4085b6ed81146b5386be70b0913ac60ca098add08e3c812bbb85abb54656ff7d 0x070a908615c53ff0aa69c4e802142791c7d9ef09 5}
2020-12-10T10:52:40.432 DBG session/pingpong/price_calculator.go:72 > Calculated price 58596775145322463. Time component: 2.7073297700351954021e+12, data component: 5.8594067815552428156e+16
2020-12-10T10:52:40.432 DBG session/pingpong/invoice_payer.go:189 > Estimated tolerance 3, upper bound 175790325435967389
2020-12-10T10:52:40.432 DBG session/pingpong/invoice_payer.go:242 > Loaded previous state: already promised: 850602543971966912
2020-12-10T10:52:40.432 DBG session/pingpong/invoice_payer.go:243 > Incrementing promised amount by 1
2020-12-10T10:52:40.433 DBG session/pingpong/exchange_messaging.go:68 > Sending P2P message to "p2p-payment-message": Promise:{ChannelID:"`\xc9\x13~\x18\x9b\x9a\xad\x1f\x9a\r)\x13i\xe2\x11\xa0w\x02\xbf" Amount:"850602543971966913" Fee:"0" Hashlock:"@\x85\xb6\xed\x81\x14kS\x86\xbep\xb0\x91:\xc6\x0c\xa0\x98\xadЎ<\x81+\xbb\x85\xab\xb5FV\xff}" ChainID:5 Signature:"j\"\xa91\x1f\x88\xa9\xeb\x1b\\\xed6{\xb5Q(ɪ\r\xbd\x95\xceΣ\x16hvܵ\x14 \xe1n\xf0!\r\xf2u\xbd\xee\xf9\xc2|\x05\xdb\xfb\x08\x189|re\xf5X)�%ao\x1e\xe9\xeag\x8b\x1c"} AgreementID:"55357642357357631246364197615432384077216329141827586571043540548735847003683" AgreementTotal:"1" Provider:"0x070a908615c53ff0aa69c4e802142791c7d9ef09" Signature:"6db8866d81e43b91d369ce793ca2fe32c8ed782b38682a9e85edb0fc92c41d0e0ef06127d3e9efd9661c0b3b0758f321cef3b4ad3c7df626012f27e23b3596b91b" HermesID:"0xD5d2f5729D4581dfacEBedF46C7014DeFda43585" ChainID:5
2020-12-10T10:52:40.532 DBG eventbus/event_bus.go:81 > Published topic="invoice_paid" event={ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} SessionID: Invoice:{AgreementID:+55357642357357631246364197615432384077216329141827586571043540548735847003683 AgreementTotal:+1 TransactorFee:+0 Hashlock:4085b6ed81146b5386be70b0913ac60ca098add08e3c812bbb85abb54656ff7d Provider:0x070a908615c53ff0aa69c4e802142791c7d9ef09 ChainID:5}}
2020-12-10T10:52:40.532 WRN consumer/session/session_storage.go:258 > Received a unknown session update
2020-12-10T10:52:40.532 WRN core/quality/sender.go:219 > Can't recover session context error="unknown session: "
2020-12-10T10:52:40.546 DBG eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+850602543971966913 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:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72}}
2020-12-10T10:52:40.547 DBG eventbus/event_bus.go:81 > Published topic="balance_change" event={Identity:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} Previous:+25000000000000000000 Current:+24149397456028033087}
2020-12-10T10:52:40.732 INF core/state/state.go:447 > Session ID Connecting duration: 2.429428024s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-12-10T10:52:40.966 INF core/connection/manager.go:485 > Provider's session config: {"local_port":0,"remote_port":0,"ports":null,"provider":{"public_key":"bEmlWeVWHgoqc5nTVFKVs3xeIXbomZewe9LGYispX10=","endpoint":"78.47.91.5:44822"},"consumer":{"ip_address":"10.182.0.2/24","dns_ips":"10.182.0.1"}}
2020-12-10T10:52:40.966 DBG eventbus/event_bus.go:81 > Published topic="Session" event={Status:Created SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connecting SessionID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:40.980 DBG consumer/session/session_storage.go:314 > Session 827a3d5e-17c4-449e-b3d1-d0b281a21ae5 saved
2020-12-10T10:52:40.980 DBG consumer/statistics/reporter.go:114 > Session statistics reporter started
2020-12-10T10:52:40.980 DBG core/ip/cached_resolver.go:75 > Found cached public IP
2020-12-10T10:52:40.980 INF firewall/outgoing_firewall_noop.go:48 > Allow IP 78.47.91.5 access
2020-12-10T10:52:40.980 DBG core/connection/dns_option.go:85 > Selecting DNS servers using strategy: auto
2020-12-10T10:52:40.980 DBG core/connection/dns_option.go:95 > Attempting to use provider DNS
2020-12-10T10:52:40.980 INF services/wireguard/connection/connection.go:131 > Starting new connection
2020-12-10T10:52:40.980 DBG config/config.go:196 > Returning default value usermode:false
2020-12-10T10:52:40.980 INF services/wireguard/endpoint/wg_client.go:48 > Wireguard kernel space is not supported. Switching to user space implementation.
2020-12-10T10:52:40.981 INF services/wireguard/connection/connection.go:168 > Starting connection endpoint
2020-12-10T10:52:41.070 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun0 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.070 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun0 error="\"ifconfig utun0 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.071 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun0
2020-12-10T10:52:41.124 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun1 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.124 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun1 error="\"ifconfig utun1 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.124 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun1
2020-12-10T10:52:41.172 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun2 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.172 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun2 error="\"ifconfig utun2 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.173 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun2
2020-12-10T10:52:41.242 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun3 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.242 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun3 error="\"ifconfig utun3 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.242 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun3
2020-12-10T10:52:41.279 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun4 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.280 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun4 error="\"ifconfig utun4 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.280 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun4
2020-12-10T10:52:41.336 DBG services/wireguard/endpoint/userspace/tun_darwin.go:25 > "ifconfig utun5 delete" output:
ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address
2020-12-10T10:52:41.337 WRN services/wireguard/endpoint/endpoint.go:142 > Failed to destroy abandoned interface: utun5 error="\"ifconfig utun5 delete\": exit status 1 output: ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address\n: exit status 1"
2020-12-10T10:52:41.337 INF services/wireguard/endpoint/endpoint.go:144 > Abandoned interface destroyed: utun5
2020-12-10T10:52:41.338 DBG services/wireguard/endpoint/endpoint.go:61 > Allocated interface: utun6
2020-12-10T10:52:41.430 DBG utils/netutil/network_darwin.go:28 > "ifconfig utun6 10.182.0.2/24 10.182.0.1" output:
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: event worker - started
INFO: [userspace-wg]2020/12/10 10:52:41 Interface set up
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv4 - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: encryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: decryption worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: handshake worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: TUN reader - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv6 - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 UAPI: Updating private key
DEBUG: [userspace-wg]2020/12/10 10:52:41 UDP bind has been updated
DEBUG: [userspace-wg]2020/12/10 10:52:41 UAPI: Updating listen port
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv4 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv6 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv6 - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 Routine: receive incoming IPv4 - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 UDP bind has been updated
DEBUG: [userspace-wg]2020/12/10 10:52:41 UAPI: Transition to peer configuration
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Starting...
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Routine: sequential receiver - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Routine: sequential sender - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Routine: nonce worker - started
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - UAPI: Created
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - UAPI: Updating persistent keepalive interval
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Sending keepalive packet
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - UAPI: Updating endpoint
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Sending handshake initiation
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - UAPI: Adding allowedip
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - UAPI: Adding allowedip
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Awaiting keypair
2020-12-10T10:52:41.551 DBG utils/netutil/network_darwin.go:32 > "route add -host 78.47.91.5 192.168.0.1" output:
add host 78.47.91.5: gateway 192.168.0.1
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Received handshake response
DEBUG: [userspace-wg]2020/12/10 10:52:41 peer(bEml…pX10) - Obtained awaited keypair
2020-12-10T10:52:41.589 DBG utils/netutil/network_darwin.go:40 > "route add -net 0.0.0.0/1 -interface utun6" output:
add net 0.0.0.0: gateway utun6
2020-12-10T10:52:41.636 DBG utils/netutil/network_darwin.go:44 > "route add -net 128.0.0.0/1 -interface utun6" output:
add net 128.0.0.0: gateway utun6
2020-12-10T10:52:42.087 INF services/wireguard/connection/connection.go:151 > Adding connection peer 78.47.91.5:44822
2020-12-10T10:52:42.087 INF services/wireguard/connection/connection.go:153 > Waiting for initial handshake
2020-12-10T10:52:42.288 DBG core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP
2020-12-10T10:52:42.288 INF firewall/outgoing_firewall_noop.go:40 > Outgoing traffic block requested
2020-12-10T10:52:42.288 DBG core/connection/manager.go:705 > waiting for connected state
2020-12-10T10:52:42.288 DBG core/connection/manager.go:740 > Connection state received: Connecting
2020-12-10T10:52:42.288 DBG core/connection/manager.go:715 > Connected started event received
2020-12-10T10:52:42.288 DBG core/connection/manager.go:740 > Connection state received: Connected
2020-12-10T10:52:42.288 INF core/connection/manager.go:603 > Connection state: Connecting -> Connected
2020-12-10T10:52:42.288 DBG core/connection/manager.go:492 > Sending P2P message to "p2p-session-acknowledge": consumerID:"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72" sessionID:"827a3d5e-17c4-449e-b3d1-d0b281a21ae5"
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:Connected SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Connected SessionID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:42.289 DBG core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer whole Connect Duration:3.982648696s}
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P channel creation Duration:1.709720636s}
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P connect Duration:318.561402ms}
2020-12-10T10:52:42.289 INF cmd/di.go:912 > Reconnecting HTTP clients due to VPN connection state change
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P exchange Duration:295.727981ms}
2020-12-10T10:52:42.289 DBG core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P exchange (ports) Duration:981.43389ms}
2020-12-10T10:52:42.289 INF core/state/state.go:404 > Session ID 827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Connected duration: 3.982577141s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-12-10T10:52:42.289 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P exchange ack Duration:108.661699ms}
2020-12-10T10:52:42.290 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P dial (upnp) Duration:311.927µs}
2020-12-10T10:52:42.290 DBG core/ip/cached_resolver.go:79 > Public IP cache is empty, fetching IP
2020-12-10T10:52:42.290 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer P2P dial ack Duration:517.549µs}
2020-12-10T10:52:42.290 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer session creation Duration:767.950931ms}
2020-12-10T10:52:42.290 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer session creation (start) Duration:14.25861ms}
2020-12-10T10:52:42.291 DBG eventbus/event_bus.go:81 > Published topic="Trace" event={ID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Key:Consumer start connection Duration:1.306067843s}
2020-12-10T10:52:42.291 DBG core/connection/manager.go:192 > Consumer connection trace: "Consumer whole Connect" took 3.982648696s, "Consumer P2P channel creation" took 1.709720636s, "Consumer P2P connect" took 318.561402ms, "Consumer P2P exchange" took 295.727981ms, "Consumer P2P exchange (ports)" took 981.43389ms, "Consumer P2P exchange ack" took 108.661699ms, "Consumer P2P dial (upnp)" took 311.927µs, "Consumer P2P dial ack" took 517.549µs, "Consumer session creation" took 767.950931ms, "Consumer session creation (start)" took 14.25861ms, "Consumer start connection" took 1.306067843s
2020-12-10T10:52:42.291 INF firewall/outgoing_firewall_noop.go:42 > Outgoing traffic block removed
2020-12-10T10:52:42.291 INF services/wireguard/connection/connection.go:198 > Stopping WireGuard connection
2020-12-10T10:52:42.291 INF firewall/outgoing_firewall_noop.go:50 > Rule for IP: 78.47.91.5 removed
INFO: [userspace-wg]2020/12/10 10:52:42 Device closing
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: TUN reader - stopped
2020-12-10T10:52:42.291 INF core/connection/stats_publisher.go:63 > Stopped publishing connection statistics
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: event worker - stopped
2020-12-10T10:52:42.291 DBG core/connection/manager.go:798 > Stopping p2p keepalive: context canceled
2020-12-10T10:52:42.291 DBG core/connection/manager.go:740 > Connection state received: Disconnecting
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: receive incoming IPv4 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: receive incoming IPv6 - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 peer(bEml…pX10) - Stopping...
DEBUG: [userspace-wg]2020/12/10 10:52:42 peer(bEml…pX10) - Routine: sequential receiver - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: encryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: decryption worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 Routine: handshake worker - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 peer(bEml…pX10) - Routine: sequential sender - stopped
DEBUG: [userspace-wg]2020/12/10 10:52:42 peer(bEml…pX10) - Routine: nonce worker - stopped
INFO: [userspace-wg]2020/12/10 10:52:42 Interface closed
2020-12-10T10:52:42.583 DBG core/connection/manager.go:740 > Connection state received: NotConnected
2020-12-10T10:52:42.583 INF core/connection/manager.go:698 > Connection exited
2020-12-10T10:52:42.583 INF utils/netutil/network.go:79 > Cleaning stale route: 78.47.91.5 192.168.0.1
2020-12-10T10:52:42.583 DBG core/connection/manager.go:735 > State updater stopCalled
2020-12-10T10:52:42.583 INF core/connection/manager.go:603 > Connection state: Connected -> Disconnecting
2020-12-10T10:52:42.583 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:Disconnecting SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Disconnecting SessionID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:42.585 INF core/state/state.go:404 > Session ID 827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Disconnecting duration: 4.278366624s data: 0b/0b, throughput: 0bs/0bs, spent: 0.000000MYST
2020-12-10T10:52:42.617 DBG utils/netutil/network_darwin.go:36 > "route delete 78.47.91.5 192.168.0.1" output:
delete host 78.47.91.5: gateway 192.168.0.1
2020-12-10T10:52:42.630 DBG eventbus/event_bus.go:81 > Published topic="Session" event={Status:Ended SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:Disconnecting SessionID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:42.649 DBG consumer/session/session_storage.go:293 > Session 827a3d5e-17c4-449e-b3d1-d0b281a21ae5 updated with final data
2020-12-10T10:52:42.649 DBG consumer/statistics/reporter.go:128 > Session statistics reporter stopping
2020-12-10T10:52:42.649 DBG session/pingpong/invoice_payer.go:282 > Stopping...
2020-12-10T10:52:42.649 DBG core/ip/cached_resolver.go:91 > Clearing ip resolver cache
2020-12-10T10:52:45.556 DBG eventbus/event_bus.go:81 > Published topic="ether-client-reconnect" event={}
2020-12-10T10:52:45.556 DBG identity/registry/registry_contract.go:269 > Loading initial state
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x0a5daabd6b513021bcbfa63b41751b13edf3515d"} already registered, skipping
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x0d5bfee82db5208a6b1d1e6b8b473231517ed3f4"} already registered, skipping
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x17786686cd8b7c764e9113045496e46423fcbca0"} already registered, skipping
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x2f64da2b9df3085cae6daefcc0e5995cac980db1"} already registered, skipping
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72"} already registered, skipping
2020-12-10T10:52:45.557 DBG identity/registry/registry_contract.go:284 > Identity {"0x6a876ab77dcb59733f600ac7c58095bb5d837ca8"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0x6bf2e72cc56dc0f7e6d970d30dc300cdbc8bbca7"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0x83d216cf8333859195ef9f249b79b9dd9b4e6da1"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0x855b8359f932cc5cfc5a9ac0c9d21f8e8e8783e6"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xad3de59c55f3b9dad98d983a07a0fab4b8669c1d"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xb017775fe27b3f3c5fc796be9a3d99ec7f4d3433"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xba921787f5573f31a98f9b976160674c754328fe"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xc988effa014b22a38092bb7d39d317ad3c289798"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xcadc91ab1ebe5b9b1ff735d099785941aa3e47ab"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xcf4cb02e68595c55694e54c0a79052c8a64a6a0f"} already registered, skipping
2020-12-10T10:52:45.558 DBG identity/registry/registry_contract.go:284 > Identity {"0xd0b1ec7f59c1804f5eef19aa1c9f80b07a5738ae"} already registered, skipping
2020-12-10T10:52:45.559 DBG identity/registry/registry_contract.go:284 > Identity {"0xdb8e25744b50a5056b26b29f0dbc52cc35d9e950"} already registered, skipping
2020-12-10T10:52:45.859 INF session/pingpong/consumer_balance_tracker.go:213 > Subscribed to channel 0x60C9137E189B9Aad1f9A0d291369e211A07702bF balance events
2020-12-10T10:52:45.859 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential}
2020-12-10T10:52:45.860 DBG core/location/cache.go:106 > Location update succeeded: {5.57.12.18 8449 ElCat Ltd. AS KG Gorod Bishkek residential}
2020-12-10T10:52:45.860 DBG core/ip/resolver.go:101 > IP detected: 5.57.12.18
2020-12-10T10:52:45.860 INF core/connection/manager.go:603 > Connection state: Disconnecting -> NotConnected
2020-12-10T10:52:45.861 DBG eventbus/event_bus.go:81 > Published topic="State" event={State:NotConnected SessionInfo:{StartedAt:2020-12-10 10:52:38.300876 +0600 +06 m=+521.096012648 ConsumerID:{Address:0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72} ConsumerLocation:{IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential} HermesID:[213 210 245 114 157 69 129 223 172 235 237 244 108 112 20 222 253 164 53 133] State:NotConnected SessionID:827a3d5e-17c4-449e-b3d1-d0b281a21ae5 Proposal:{ID:1 Format:service-proposal/v1 ServiceType:wireguard ServiceDefinition:{Location:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting} LocationOriginate:{Continent:EU Country:DE City:Unknown ASN:24940 ISP:Hetzner Online GmbH NodeType:hosting}} PaymentMethodType:BYTES_TRANSFERRED_WITH_TIME PaymentMethod:{Price:0.000500MYST Duration:43.478260869s Bytes:178956 Type:BYTES_TRANSFERRED_WITH_TIME} ProviderID:0x070a908615c53ff0aa69c4e802142791c7d9ef09 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:0xc000127ac0}}}
2020-12-10T10:52:45.861 DBG core/connection/manager.go:509 > Sending P2P message to "p2p-session-destroy": consumerID:"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72" sessionID:"827a3d5e-17c4-449e-b3d1-d0b281a21ae5"
2020-12-10T10:52:45.862 DBG core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2020-12-10T10:52:45.862 INF core/state/state.go:404 > Session ID 827a3d5e-17c4-449e-b3d1-d0b281a21ae5 NotConnected duration: 7.548858202s data: 0b/0b, throughput: 0bs/0bs, spent: %!s(PANIC=String method: runtime error: invalid memory address or nil pointer dereference)
2020-12-10T10:52:45.862 INF cmd/di.go:912 > Reconnecting HTTP clients due to VPN connection state change
2020-12-10T10:52:46.037 INF market/mysterium/mysterium_api.go:309 > Session stats sent: 827a3d5e-17c4-449e-b3d1-d0b281a21ae5
2020-12-10T10:52:46.037 DBG consumer/statistics/reporter.go:100 > Final stats sent
2020-12-10T10:52:46.752 DBG eventbus/event_bus.go:81 > Published topic="ether-client-reconnect" event={}
2020-12-10T10:52:46.752 DBG identity/registry/registry_contract.go:269 > Loading initial state
2020-12-10T10:52:46.752 DBG identity/registry/registry_contract.go:284 > Identity {"0x0a5daabd6b513021bcbfa63b41751b13edf3515d"} already registered, skipping
2020-12-10T10:52:46.752 DBG identity/registry/registry_contract.go:284 > Identity {"0x0d5bfee82db5208a6b1d1e6b8b473231517ed3f4"} already registered, skipping
2020-12-10T10:52:46.752 DBG identity/registry/registry_contract.go:284 > Identity {"0x17786686cd8b7c764e9113045496e46423fcbca0"} already registered, skipping
2020-12-10T10:52:46.753 DBG identity/registry/registry_contract.go:284 > Identity {"0x2f64da2b9df3085cae6daefcc0e5995cac980db1"} already registered, skipping
2020-12-10T10:52:46.753 DBG identity/registry/registry_contract.go:284 > Identity {"0x4ac7b8dd74ef12238548f196ba12b4d43ae51e72"} already registered, skipping
2020-12-10T10:52:46.753 DBG identity/registry/registry_contract.go:284 > Identity {"0x6a876ab77dcb59733f600ac7c58095bb5d837ca8"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0x6bf2e72cc56dc0f7e6d970d30dc300cdbc8bbca7"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0x83d216cf8333859195ef9f249b79b9dd9b4e6da1"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0x855b8359f932cc5cfc5a9ac0c9d21f8e8e8783e6"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0xad3de59c55f3b9dad98d983a07a0fab4b8669c1d"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0xb017775fe27b3f3c5fc796be9a3d99ec7f4d3433"} already registered, skipping
2020-12-10T10:52:46.754 DBG identity/registry/registry_contract.go:284 > Identity {"0xba921787f5573f31a98f9b976160674c754328fe"} already registered, skipping
2020-12-10T10:52:46.755 DBG identity/registry/registry_contract.go:284 > Identity {"0xc988effa014b22a38092bb7d39d317ad3c289798"} already registered, skipping
2020-12-10T10:52:46.755 DBG identity/registry/registry_contract.go:284 > Identity {"0xcadc91ab1ebe5b9b1ff735d099785941aa3e47ab"} already registered, skipping
2020-12-10T10:52:46.755 DBG identity/registry/registry_contract.go:284 > Identity {"0xcf4cb02e68595c55694e54c0a79052c8a64a6a0f"} already registered, skipping
2020-12-10T10:52:46.755 DBG identity/registry/registry_contract.go:284 > Identity {"0xd0b1ec7f59c1804f5eef19aa1c9f80b07a5738ae"} already registered, skipping
2020-12-10T10:52:46.755 DBG identity/registry/registry_contract.go:284 > Identity {"0xdb8e25744b50a5056b26b29f0dbc52cc35d9e950"} already registered, skipping
2020-12-10T10:52:46.992 INF session/pingpong/consumer_balance_tracker.go:213 > Subscribed to channel 0x60C9137E189B9Aad1f9A0d291369e211A07702bF balance events
2020-12-10T10:52:46.994 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential}
2020-12-10T10:52:46.994 DBG core/location/cache.go:106 > Location update succeeded: {5.57.12.18 8449 ElCat Ltd. AS KG Gorod Bishkek residential}
2020-12-10T10:52:53.827 DBG core/ip/cached_resolver.go:79 > Public IP cache is empty, fetching IP
2020-12-10T10:52:54.696 DBG core/ip/resolver.go:101 > IP detected: 5.57.12.18
2020-12-10T10:52:54.697 DBG core/location/oracle_resolver.go:42 > Detecting with oracle resolver
2020-12-10T10:52:55.583 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:5.57.12.18 ASN:8449 ISP:ElCat Ltd. Continent:AS Country:KG City:Gorod Bishkek NodeType:residential}
2020-12-10T10:52:58.343 WRN communication/nats/connection_wrap.go:95 > NATS: disconnected
2020-12-10T10:52:58.569 WRN communication/nats/connection_wrap.go:96 > NATS: reconnected
