search

mysteriumnetwork / node

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

Node won't come online after multiple attempts at registration #4420

Closed no-good-usernames-left closed 2 years ago

no-good-usernames-left commented 2 years ago

Describe the bug Used MystCLI to register multiple nodes with success, except for my node in France My node in The Netherlands worked perfectly

To Reproduce Steps to reproduce the behavior: Run through Myst CLI on a node on the latest version in France

Expected behavior Node to come online after ~15 seconds after initial registration

Actual behavior Node still offline after 15 hours after initial registration

Environment (please complete the following information):

Additional context It seems that it's trying and failing to look inward to find the Myst Network according to the log?

2021-12-05T00:16:21.194 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:19:30.175 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:30:09.051 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:30:10.625 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:32:12.251 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:32:12.336 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:34:16.805 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:36:17.301 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:36:17.396 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:41:22.367 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled" 2021-12-05T00:47:25.871 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled"

root@skynet2 :/var/lib/mysterium-node/.mysterium/logs#

nslookup pilvytis.mysterium.network Server: 9.9.9.9 Address: 9.9.9.9#53

Non-authoritative answer: Name: pilvytis.mysterium.network Address: 51.158.129.204

tomasmik commented 2 years ago

Provide the identity address you're trying to register so that we can check if there were registration requests.

no-good-usernames-left commented 2 years ago

0x89bb468bd3262106a983fdc91fe3718b3a7fe932

no-good-usernames-left commented 2 years ago

Any updates? French node is still offline...

tomasmik commented 2 years ago

Address you provided appears to be registered: https://hermes.mysterium.network/api/v1/data/consumer/0x89bb468bd3262106a983fdc91fe3718b3a7fe932

no-good-usernames-left commented 2 years ago

Again, registration is not the problem, it's not online according to the dashboard, and every time I've tried dropping and re-registering, it stays offline

Note the log pull shows it cannot resolve that pilvytis which is the thing preventing it from coming online

Please escalate the issue, I've been waiting since 11/22 to get this node online

etherunit commented 2 years ago

Have you tried to restart your node service? It could be that it failes to reconnect to NATs and keeps that state.

djcrawleravp commented 2 years ago

Same here, just installed the node.

2021-12-08T16:04:44.405 WRN requests/dialer_swarm.go:293 > Failed to lookup host: "pilvytis.mysterium.network" error="lookup pilvytis.mysterium.network on 1.0.0.1:53: dial udp 1.0.0.1:53: operation was canceled"

no-good-usernames-left commented 2 years ago

Are you joking @etherunit ? I've rebooted the bloody node 5 times this week! It's fully reachable by it's public IP after every single reboot...

Here's how my EU nodes are set up: It is the same hosting provider in Amsterdam as it is in France, same NAT schemes, same everything, it's just physically located quite a few kilometers away from eachother

AMS came online right away as I migrated to Mainnet PAR did not come online after reinstall, reload, refresh, re-everything! I added a node in Germany on a different host, and it's doing the same thing as the node in France (pilvytis lookup failure)

This is also not a low priority bug, this is a critical design flaw in the Myst Mainnet

For the third time, why is the lookup for pilvytis failing? I feel like I should not have to keep asking this....

djcrawleravp commented 2 years ago

On My Case I'm using docker on ubuntu, Node seems to be ok and connected but the loogs keeps repeating the same error

Snawoot commented 2 years ago

what's not clear for me is nslookup is using quad9 dns servers directly while node does seem to use systemd-resolved DNS stub (127.0.0.53:53). @no-good-usernames-left can you please suggest anything on that mismatch?

for me situation looks like systemd-resolved DNS stub just timed out.

no-good-usernames-left commented 2 years ago

@Snawoot can you please suggest anything on that mismatch?

I have absolutely no clue how MystNode is built and the way it is doing DNS with it's stub/secondary resolver

This is for Mysterium's team to provide advice on, the log says X, I need an answer as to why and what is needed to fix it...

no-good-usernames-left commented 2 years ago

Any updates?

Why is there no progress in resolving this?

isaackielma commented 2 years ago

Maybe it’s a corrupt config etc., so it would be good to try to reinstall node from scratch? Let me know if you have already done so!

Looking forward to your response.

no-good-usernames-left commented 2 years ago

To update, the node in Paris is now online after the apt-update to latest Myst version Germany is still offline in Mystnodes after updating it

0x129e354d2d6481fdb39c1518064c256b82bbc65a

`2021-12-18T00:59:23.430 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T01:59:23.728 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T02:46:32.857 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T02:46:32.859 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T02:59:24.045 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T03:59:24.382 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T04:59:24.733 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T05:59:25.029 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T06:01:36.202 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: buffer size too small 2021-12-18T06:01:36.202 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: buffer size too small 2021-12-18T06:59:25.371 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T07:59:25.692 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T08:41:25.440 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T08:41:25.442 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T08:59:26.020 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T09:01:56.906 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: overflow unpacking uint16 2021-12-18T09:01:56.909 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: overflow unpacking uint16 2021-12-18T09:42:02.515 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: buffer size too small 2021-12-18T09:42:02.517 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: buffer size too small 2021-12-18T09:59:26.407 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T10:21:20.373 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T10:21:20.376 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T10:21:20.376 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T10:21:20.376 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T10:21:20.376 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T10:21:20.377 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T10:59:26.720 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T11:59:27.026 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T12:55:53.418 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: buffer size too small 2021-12-18T12:55:53.423 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: buffer size too small 2021-12-18T12:59:27.393 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T13:59:27.772 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T14:54:00.201 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T14:54:00.205 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T14:59:28.186 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T15:32:56.423 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T15:32:56.426 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T15:39:44.919 INF cmd/commands/service/command.go:97 > Stopping application 2021-12-18T15:39:44.920 INF cmd/node.go:87 > No active connection - proceeding 2021-12-18T15:39:44.920 DBG eventbus/event_bus.go:81 > Published topic="Node" event={Status:Stopped} 2021-12-18T15:39:44.920 INF cmd/node.go:96 > API stopped 2021-12-18T15:39:44.921 DBG identity/registry/registry_contract.go:158 > event received {Stopped} 2021-12-18T15:39:44.921 INF identity/registry/registry_contract.go:298 > Stopping registry... 2021-12-18T15:39:44.921 INF identity/registry/provider_registrar.go:302 > Stopping provider registrar 2021-12-18T15:39:44.921 DBG session/pingpong/hermes_promise_handler.go:215 > hermes promise handler stopped 2021-12-18T15:39:44.921 INF session/pingpong/hermes_promise_settler.go:335 > Stopped listening for settlement events 2021-12-18T15:39:44.922 INF ui/server.go:135 > Server stopped 2021-12-18T15:39:44.924 INF ui/server.go:135 > Server stopped 2021-12-18T15:39:44.924 INF cmd/node.go:99 > Web UI server stopped 2021-12-18T15:39:44.924 DBG sleep/sleep_noop.go:33 > Unregister noop sleep events 2021-12-18T15:39:44.925 INF cmd/node.go:102 > Sleep notifier stopped 2021-12-18T15:39:44.925 INF services/wireguard/service/service_unix.go:292 > Wireguard: stopping 2021-12-18T15:39:44.926 INF services/wireguard/service/service_unix.go:314 > Wireguard: stopped 2021-12-18T15:39:44.927 DBG eventbus/event_bus.go:81 > Published topic="Service status" event={ID:b0193a10-c0ae-4d7b-bbd3-76c89890cafb ProviderID:0x129e354d2d6481fdb39c1518064c256b82bbc65a Type:wireguard Status:NotRunning} 2021-12-18T15:39:44.928 INF nat/service_iptables.go:80 > Deleting NAT/Firewall rules 2021-12-18T15:39:44.938 ERR core/service/manager.go:209 > Service stop failed error="no such instance" 2021-12-18T15:39:44.939 DBG session/pingpong/hermes_promise_settler.go:243 > Ignoring service event with status NotRunning 2021-12-18T15:39:44.969 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables -D MYST --destination 10.0.0.0/8 --jump DNAT --to-destination 240.0.0.1 --table nat" output:

2021-12-18T15:39:44.990 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables -D MYST --destination 172.16.0.0/12 --jump DNAT --to-destination 240.0.0.1 --table nat" output:

2021-12-18T15:39:45.011 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables -D MYST --destination 192.168.0.0/16 --jump DNAT --to-destination 240.0.0.1 --table nat" output:

2021-12-18T15:39:45.034 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables -D MYST --destination 127.0.0.0/8 --jump DNAT --to-destination 240.0.0.1 --table nat" output:

2021-12-18T15:39:45.034 INF nat/service_iptables.go:92 > Deleting NAT/Firewall rules... done 2021-12-18T15:39:45.055 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables --flush MYST --table nat" output:

2021-12-18T15:39:45.071 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables --delete-chain MYST --table nat" output:

2021-12-18T15:39:45.071 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://broker.mysterium.network:4222 removed 2021-12-18T15:39:45.071 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://broker.mysterium.network:4222 removed 2021-12-18T15:39:45.072 INF firewall/outgoing_firewall_noop.go:61 > Rule for URL: nats://51.158.129.204:4222 removed 2021-12-18T15:39:45.072 INF firewall/incoming_firewall_noop.go:38 > Rules reset was requested 2021-12-18T15:39:45.072 INF firewall/outgoing_firewall_noop.go:35 > Rules reset was requested 2021-12-18T15:39:45.294 DBG logconfig/rollingwriter/rollingwriter.go:76 > Found 0 old log files in log directory, skipping cleanup 2021-12-18T15:39:45.295 INF cmd/di.go:207 > Starting Mysterium Node 1.0.14 2021-12-18T15:39:45.296 INF firewall/incoming_firewall_noop.go:32 > Rules bootstrap was requested 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: feedback.mysterium.network -> [116.203.17.150] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: discovery.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: broker.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: transactor.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: pilvytis.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: location.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.299 INF cmd/di.go:650 > Using local DNS: quality.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.300 INF 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-12-18T15:39:45.300 INF cmd/di.go:650 > Using local DNS: badupnp.benjojo.co.uk -> [104.22.70.70 104.22.71.70 172.67.25.154] 2021-12-18T15:39:45.300 INF cmd/di.go:650 > Using local DNS: trust.mysterium.network -> [51.158.129.204] 2021-12-18T15:39:45.300 DBG communication/nats/connector.go:79 > Connecting to NATS servers: [nats://broker.mysterium.network:4222] 2021-12-18T15:39:45.300 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://broker.mysterium.network:4222 access 2021-12-18T15:39:45.300 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://broker.mysterium.network:4222 access 2021-12-18T15:39:45.300 INF firewall/outgoing_firewall_noop.go:57 > Allow URL nats://51.158.129.204:4222 access 2021-12-18T15:39:46.892 INF cmd/di.go:679 > Using L1 Eth endpoints: [https://ethereum1.mysterium.network/ https://cloudflare-eth.com/] 2021-12-18T15:39:46.893 INF cmd/di.go:680 > Using L2 Eth endpoints: [https://polygon1.mysterium.network/ https://polygon-rpc.com/] 2021-12-18T15:39:46.893 INF cmd/di.go:478 > Node chain id 137 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://discovery.mysterium.network/api/v3 access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://transactor.mysterium.network/api/v1 access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://hermes.mysterium.network/api/v2 access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://pilvytis.mysterium.network access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://ethereum1.mysterium.network/ access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://cloudflare-eth.com/ access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://polygon1.mysterium.network/ access 2021-12-18T15:39:47.063 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://polygon-rpc.com/ access 2021-12-18T15:39:47.063 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://discovery.mysterium.network/api/v3 access 2021-12-18T15:39:47.063 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://transactor.mysterium.network/api/v1 access 2021-12-18T15:39:47.063 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://hermes.mysterium.network/api/v2 access 2021-12-18T15:39:47.063 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://pilvytis.mysterium.network access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://ethereum1.mysterium.network/ access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://cloudflare-eth.com/ access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://polygon1.mysterium.network/ access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://polygon-rpc.com/ access 2021-12-18T15:39:47.064 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://location.mysterium.network/api/v1/location access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://location.mysterium.network/api/v1/location access 2021-12-18T15:39:47.064 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://location.mysterium.network/api/v1/location access 2021-12-18T15:39:47.064 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://location.mysterium.network/api/v1/location access 2021-12-18T15:39:47.064 DBG cmd/di.go:793 > Using lightweight keystore 2021-12-18T15:39:47.066 DBG config/config.go:215 > Returning CLI value data-dir:/var/lib/mysterium-node 2021-12-18T15:39:47.067 DBG core/ip/cached_resolver.go:59 > Outbound IP cache is empty, fetching IP 2021-12-18T15:39:47.093 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables --new MYST --table nat" output:

2021-12-18T15:39:47.128 DBG nat/service_iptables.go:231 > "/usr/sbin/iptables -A MYST --destination 10.0.0.0/8 --jump DNAT --to-destination 240.0.0.1 --table nat" output: Another app is currently holding the xtables lock. Perhaps you want to use the -w option?

2021-12-18T15:39:47.128 WRN nat/service_iptables.go:105 > Failed to prepare iptables setup error="failed to create blackhole rule in the MYST iptables chain: error calling IPTables: \"/usr/sbin/iptables -A MYST --destination 10.0.0.0/8 --jump DNAT --to-destination 240.0.0.1 --table nat\": exit status 4 output: Another app is currently holding the xtables lock. Perhaps you want to use the -w option?\n: exit status 4" 2021-12-18T15:39:47.132 INF nat/service_ipforward.go:46 > IP forwarding already enabled 2021-12-18T15:39:47.133 INF firewall/outgoing_firewall_noop.go:57 > Allow URL https://quality.mysterium.network/api/v2 access 2021-12-18T15:39:47.134 INF firewall/incoming_firewall_noop.go:53 > Allow URL https://quality.mysterium.network/api/v2 access 2021-12-18T15:39:47.134 INF feedback/reporter.go:43 > Using feedback API at: https://feedback.mysterium.network 2021-12-18T15:39:47.149 INF firewall/outgoing_firewall_noop.go:48 > Allow IP 239.255.255.250 access 2021-12-18T15:39:47.330 INF tequilapi/http_api_server.go:121 > API started on: 127.0.0.1:4050 2021-12-18T15:39:47.331 DBG eventbus/event_bus.go:81 > Published topic="Node" event={Status:Started} 2021-12-18T15:39:47.331 DBG core/ip/cached_resolver.go:55 > Found cached outbound IP 2021-12-18T15:39:47.331 DBG core/ip/cached_resolver.go:79 > Public IP cache is empty, fetching IP 2021-12-18T15:39:47.332 DBG sleep/sleep_noop.go:28 > Register for noop sleep events 2021-12-18T15:39:47.333 INF ui/server.go:116 > UI starting on: 116.203.193.101:4449 2021-12-18T15:39:47.333 INF ui/server.go:116 > UI starting on: 127.0.0.1:4449 2021-12-18T15:39:47.334 DBG identity/registry/registry_contract.go:158 > event received {Started} 2021-12-18T15:39:47.335 INF identity/registry/registry_contract.go:304 > Starting registry... 2021-12-18T15:39:47.337 DBG identity/registry/registry_contract.go:315 > Loading initial state 2021-12-18T15:39:47.338 DBG identity/registry/registry_contract.go:330 > Identity {"0x129e354d2d6481fdb39c1518064c256b82bbc65a"} already registered, skipping 2021-12-18T15:39:47.338 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:39:47.339 DBG core/ip/cached_resolver.go:55 > Found cached outbound IP 2021-12-18T15:39:47.339 INF identity/registry/provider_registrar.go:282 > Starting provider registrar 2021-12-18T15:39:47.348 INF session/pingpong/hermes_promise_settler.go:329 > Listening for settlement events 2021-12-18T15:39:47.431 INF session/pingpong/pricing.go:177 > pricing info loaded. expires @ 2021-12-18 15:40:41.318142876 +0000 UTC 2021-12-18T15:39:47.469 WRN ui/discovery/ssdp.go:101 > SSDP publicly accessible. Stopping it to prevent abusing service 2021-12-18T15:39:47.535 DBG core/location/cache.go:123 > original location detected: DE (hosting) 2021-12-18T15:39:47.544 DBG core/ip/resolver.go:105 > IP detected: 116.203.193.101 2021-12-18T15:39:47.545 DBG eventbus/event_bus.go:81 > Published topic="Traversal" event={ID: Stage:public_ip Successful:true Error:} 2021-12-18T15:39:47.545 DBG core/ip/cached_resolver.go:75 > Found cached public IP 2021-12-18T15:39:47.549 DBG session/pingpong/hermes_promise_handler.go:210 > hermes promise handler started 2021-12-18T15:39:47.568 INF session/pingpong/hermes_promise_settler.go:185 > Provider {0x129e354d2d6481fdb39c1518064c256b82bbc65a} not registered, skipping 2021-12-18T15:39:49.250 INF nat/upnp/discover.go:58 > UPnP gateways detected: 0 2021-12-18T15:39:49.250 INF cmd/di.go:291 > Mysterium node started! 2021-12-18T15:39:49.251 ERR core/quality/mysterium_morqa.go:86 > Failed to sign metrics event error="failed to sing metrics event: authentication needed: password or unlock" 2021-12-18T15:39:49.253 DBG identity/selector/handler.go:98 > Attempting to use last identity 2021-12-18T15:39:49.254 DBG identity/selector/handler.go:103 > Found identity in cache: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:39:49.269 DBG tequilapi/endpoints/terms.go:91 > Setting user config value: "terms.consumer-agreed" = %!q(bool=true) 2021-12-18T15:39:49.272 DBG eventbus/event_bus.go:81 > Published topic="config:terms.consumer-agreed" event=true 2021-12-18T15:39:49.272 DBG tequilapi/endpoints/terms.go:91 > Setting user config value: "terms.provider-agreed" = %!q(bool=true) 2021-12-18T15:39:49.272 DBG eventbus/event_bus.go:81 > Published topic="config:terms.provider-agreed" event=true 2021-12-18T15:39:49.272 DBG tequilapi/endpoints/terms.go:91 > Setting user config value: "terms.version" = "0.0.34" 2021-12-18T15:39:49.273 DBG eventbus/event_bus.go:81 > Published topic="config:terms.version" event=0.0.34 2021-12-18T15:39:49.273 INF config/config.go:98 > Saving user configuration 2021-12-18T15:39:49.273 INF config/config.go:117 > User configuration written: {"mmn":{"api-key":"Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9"},"terms":{"consumer-agreed":true,"provider-agreed":true,"version":"0.0.34"}} 2021-12-18T15:39:49.436 DBG identity/manager.go:166 > Caching unlocked address: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:39:49.442 DBG identity/selector/handler.go:108 > Unlocked identity: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:39:49.443 DBG eventbus/event_bus.go:81 > Published topic="identity-unlocked" event={ChainID:137 ID:{Address:0x129e354d2d6481fdb39c1518064c256b82bbc65a}} 2021-12-18T15:39:49.446 DBG eventbus/event_bus.go:81 > Published topic="resident-country" event={ID:0x129e354d2d6481fdb39c1518064c256b82bbc65a Country:DE} 2021-12-18T15:39:49.443 INF cmd/commands/service/command.go:125 > Unlocked identity: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:39:49.449 INF tequilapi/endpoints/service.go:167 > Service start options: {ProviderID:0x129e354d2d6481fdb39c1518064c256b82bbc65a Type:wireguard AccessPolicies:{IDs:[]} Options:{Subnet:{IP:10.182.0.0 Mask:ffff0000}}} 2021-12-18T15:39:49.449 DBG core/service/manager.go:125 > Starting service options={"subnet":"10.182.0.0/16"} policyIDs=[] providerID=0x129e354d2d6481fdb39c1518064c256b82bbc65a serviceType=wireguard 2021-12-18T15:39:49.449 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:39:49.580 DBG session/pingpong/consumer_balance_tracker.go:640 > No previous invoice grand total, assuming zero 2021-12-18T15:39:49.580 DBG session/pingpong/consumer_balance_tracker.go:655 > Loaded hermes state: already promised: 0 2021-12-18T15:39:49.584 DBG eventbus/event_bus.go:81 > Published topic="consumer_grand_total_change" event={Current:+0 ChainID:137 HermesID:0xa62a2A75949d25e17C6F08a7818e7bE97c18a8d2 ConsumerID:{Address:0x129e354d2d6481fdb39c1518064c256b82bbc65a}} 2021-12-18T15:39:49.647 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:116.203.193.101 ASN:24940 ISP:Hetzner Online GmbH Continent:EU Country:DE City:Unknown IPType:hosting} 2021-12-18T15:39:49.647 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:39:49.797 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T15:39:49.819 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:116.203.193.101 ASN:24940 ISP:Hetzner Online GmbH Continent:EU Country:DE City:Unknown IPType:hosting} 2021-12-18T15:39:49.819 INF core/discovery/discovery.go:93 > Starting discovery... 2021-12-18T15:39:49.827 DBG eventbus/event_bus.go:81 > Published topic="Service status" event={ID:4c971564-f942-49c4-85e0-f8495a8ae9c3 ProviderID:0x129e354d2d6481fdb39c1518064c256b82bbc65a Type:wireguard Status:Running} 2021-12-18T15:39:49.827 INF services/wireguard/service/service_unix.go:254 > Wireguard: starting 2021-12-18T15:39:49.828 DBG core/ip/cached_resolver.go:55 > Found cached outbound IP 2021-12-18T15:39:49.828 INF dns/proxy.go:53 > Starting DNS proxy on: :11253 2021-12-18T15:39:49.830 INF services/wireguard/service/service_unix.go:285 > Wireguard: started 2021-12-18T15:39:49.830 DBG config/config.go:220 > Returning user config value mmn.api-key:Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9 2021-12-18T15:39:49.830 DBG config/config.go:220 > Returning user config value mmn.api-key:Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9 2021-12-18T15:39:49.888 DBG mmn/client.go:56 > Registering node to MMN: {LocalIP:116.203.193.101 Identity:0x129e354d2d6481fdb39c1518064c256b82bbc65a APIKey:Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9 VendorID: OS:Ubuntu 20.04.3 LTS Arch:linux/amd64 NodeVersion:1.0.14} 2021-12-18T15:39:49.957 WRN session/pingpong/consumer_balance_tracker.go:475 > Could not get consumer channel error="no contract code at given address" 2021-12-18T15:39:50.051 INF session/pingpong/hermes_promise_settler.go:185 > Provider {0x129e354d2d6481fdb39c1518064c256b82bbc65a} not registered, skipping 2021-12-18T15:39:50.093 INF core/discovery/discovery.go:242 > Identity 0x129e354d2d6481fdb39c1518064c256b82bbc65a not registered, delaying proposal registration until identity is registered 2021-12-18T15:39:50.094 INF core/discovery/discovery.go:181 > Waiting for registration success event 2021-12-18T15:39:50.102 INF identity/registry/provider_registrar.go:203 > Provider "0x129e354d2d6481fdb39c1518064c256b82bbc65a" not registered on BC, will check if elgible for auto-registration 2021-12-18T15:39:50.997 DBG eventbus/event_bus.go:81 > Published topic="transactor_identity_registration" event={RegistryAddress:0x87F0F4b7e0FAb14A565C87BAbbA6c40c92281b51 HermesID:0xa62a2A75949d25e17C6F08a7818e7bE97c18a8d2 Stake:+0 Fee:+66491817834400000 Beneficiary:0x32F3974daBabe7221d71291FE376BF6368677f96 Signature:0xa17a8de3ec13219cbf90f2c4696a3d6107f5cf2a89061745f75816e08e2b4c6969f2f91fb720a9cf88de6adb1503c9239cece45bb9c30f6f5c01d480a3f3c9721b Identity:0x129e354d2d6481fdb39c1518064c256b82bbc65a ChainID:137} 2021-12-18T15:39:50.999 DBG eventbus/event_bus.go:81 > Published topic="registration_event_topic" event={ID:{Address:0x129e354d2d6481fdb39c1518064c256b82bbc65a} Status:InProgress ChainID:137} 2021-12-18T15:39:51.001 INF identity/registry/provider_registrar.go:269 > Registration success for provider "0x129e354d2d6481fdb39c1518064c256b82bbc65a" 2021-12-18T15:39:51.002 DBG core/discovery/discovery.go:162 > Registration event received for 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:39:51.002 INF core/discovery/discovery.go:176 > Received status InProgress ignoring 2021-12-18T15:39:51.003 DBG session/pingpong/hermes_promise_settler.go:264 > Ignoring event InProgress for provider {"0x129e354d2d6481fdb39c1518064c256b82bbc65a"} 2021-12-18T15:40:11.126 ERR identity/registry/registry_contract.go:261 > registration reported as failed by transactor 2021-12-18T15:40:11.132 DBG eventbus/event_bus.go:81 > Published topic="registration_event_topic" event={ID:{Address:0x129e354d2d6481fdb39c1518064c256b82bbc65a} Status:RegistrationError ChainID:137} 2021-12-18T15:40:11.132 DBG core/discovery/discovery.go:162 > Registration event received for 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:40:11.132 INF core/discovery/discovery.go:173 > Cancelled identity registration 2021-12-18T15:40:11.133 DBG session/pingpong/hermes_promise_settler.go:264 > Ignoring event RegistrationError for provider {"0x129e354d2d6481fdb39c1518064c256b82bbc65a"} 2021-12-18T15:41:41.699 DBG config/config.go:220 > Returning user config value terms.provider-agreed:true 2021-12-18T15:41:41.702 DBG config/config.go:220 > Returning user config value terms.consumer-agreed:true 2021-12-18T15:41:41.703 DBG config/config.go:220 > Returning user config value terms.version:0.0.34 2021-12-18T15:41:41.852 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:41:41.873 DBG identity/selector/handler.go:98 > Attempting to use last identity 2021-12-18T15:41:41.874 DBG identity/selector/handler.go:103 > Found identity in cache: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:41:41.875 DBG identity/manager.go:153 > Unlocked identity found in cache, skipping keystore: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:41:41.876 DBG identity/selector/handler.go:108 > Unlocked identity: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:41:42.012 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:116.203.193.101 ASN:24940 ISP:Hetzner Online GmbH Continent:EU Country:DE City:Unknown IPType:hosting} 2021-12-18T15:41:42.100 INF session/pingpong/pricing.go:177 > pricing info loaded. expires @ 2021-12-18 15:45:33.206128662 +0000 UTC 2021-12-18T15:41:42.197 DBG eventbus/event_bus.go:81 > Published topic="registration_event_topic" event={ID:{Address:0x129e354d2d6481fdb39c1518064c256b82bbc65a} Status:Registered ChainID:137} 2021-12-18T15:41:42.198 DBG core/discovery/discovery.go:162 > Registration event received for 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:41:42.199 INF core/discovery/discovery.go:170 > Identity registered, proceeding with proposal registration 2021-12-18T15:41:42.201 INF session/pingpong/hermes_promise_settler.go:267 > Identity registration event received for provider {"0x129e354d2d6481fdb39c1518064c256b82bbc65a"} 2021-12-18T15:41:42.202 INF session/pingpong/hermes_promise_settler.go:272 > Identity registration event handled for provider {"0x129e354d2d6481fdb39c1518064c256b82bbc65a"} 2021-12-18T15:41:42.283 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:41:42.541 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:116.203.193.101 ASN:24940 ISP:Hetzner Online GmbH Continent:EU Country:DE City:Unknown IPType:hosting} 2021-12-18T15:41:42.650 DBG eventbus/event_bus.go:81 > Published topic="NAT-type-detected" event=none 2021-12-18T15:41:45.715 DBG config/config.go:220 > Returning user config value mmn.api-key:Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9 2021-12-18T15:46:35.184 DBG config/config.go:220 > Returning user config value terms.provider-agreed:true 2021-12-18T15:46:35.186 DBG config/config.go:220 > Returning user config value terms.consumer-agreed:true 2021-12-18T15:46:35.187 DBG config/config.go:220 > Returning user config value terms.version:0.0.34 2021-12-18T15:46:35.328 DBG identity/selector/handler.go:98 > Attempting to use last identity 2021-12-18T15:46:35.328 DBG identity/selector/handler.go:103 > Found identity in cache: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:46:35.329 DBG identity/manager.go:153 > Unlocked identity found in cache, skipping keystore: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:46:35.329 DBG identity/selector/handler.go:108 > Unlocked identity: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-18T15:46:36.372 DBG config/config.go:220 > Returning user config value mmn.api-key:Wmb7YMvPx1UqtEcapUv4DRLJjbPBg5gbHNI0mDB9 2021-12-18T15:46:39.027 DBG core/location/oracle_resolver.go:64 > Detecting with oracle resolver 2021-12-18T15:46:39.227 DBG eventbus/event_bus.go:81 > Published topic="location-update-event" event={IP:116.203.193.101 ASN:24940 ISP:Hetzner Online GmbH Continent:EU Country:DE City:Unknown IPType:hosting} 2021-12-18T15:46:39.327 INF session/pingpong/pricing.go:177 > pricing info loaded. expires @ 2021-12-18 15:50:40.286803131 +0000 UTC 2021-12-18T15:46:39.871 DBG eventbus/event_bus.go:81 > Published topic="NAT-type-detected" event=none 2021-12-18T17:14:11.862 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T17:14:11.863 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-18T18:00:12.904 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-18T18:00:12.905 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-19T00:04:01.888 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-19T00:04:01.889 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-19T06:14:37.580 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-19T06:14:37.585 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-19T08:44:58.358 WRN communication/nats/connection_wrap.go:102 > NATS: disconnected error=EOF 2021-12-19T08:44:59.933 WRN communication/nats/connection_wrap.go:103 > NATS: reconnected 2021-12-19T12:01:09.326 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: buffer size too small 2021-12-19T12:01:09.330 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: buffer size too small 2021-12-19T12:36:06.960 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to unpack packet: dns: bad rdata 2021-12-19T12:36:06.962 ??? vendor/github.com/rs/zerolog/log.go:403 > [ERR] bonjour: Failed to handle query: dns: bad rdata 2021-12-19T13:41:28.623 DBG config/config.go:220 > Returning user config value terms.provider-agreed:true 2021-12-19T13:41:28.627 DBG config/config.go:220 > Returning user config value terms.consumer-agreed:true 2021-12-19T13:41:28.627 DBG config/config.go:220 > Returning user config value terms.version:0.0.34 2021-12-19T13:41:28.768 DBG identity/selector/handler.go:98 > Attempting to use last identity 2021-12-19T13:41:28.769 DBG identity/selector/handler.go:103 > Found identity in cache: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-19T13:41:28.770 DBG identity/manager.go:153 > Unlocked identity found in cache, skipping keystore: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-19T13:41:28.771 DBG identity/selector/handler.go:108 > Unlocked identity: 0x129e354d2d6481fdb39c1518064c256b82bbc65a 2021-12-19T13:41:30.054 INF session/pingpong/pricing.go:177 > pricing info loaded. expires @ 2021-12-19 13:45:26.007224652 +0000 UTC 2021-12-19T13:41:30.739 DBG eventbus/event_bus.go:81 > Published topic="NAT-type-detected" event=none`

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 2 years ago

This issue has been automatically closed because it has not had activity for a long time. If this issue is still valid, please ping a maintainer and ask them to label it as "pinned". Thank you for your contributions.