Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

UPnP leases not created/refreshed ? #3295

Closed
sudokai0 opened this issue May 17, 2021 · 8 comments
Closed

UPnP leases not created/refreshed ? #3295

sudokai0 opened this issue May 17, 2021 · 8 comments
Assignees
Labels
Milestone

Comments

@sudokai0
Copy link
Contributor

Summary

UPnP leases are not created / refreshed for me in V22. Conditions for creating a lease seems to be OK. IGD devices are found:
[2021-May-17 21:15:42.807454]: UPnP local address: 192.168.1.230, discovery: 0, IGD search: 1
[2021-May-17 21:15:42.807454]: UPnP device url: http://192.168.1.251:39446/rootDesc.xml st: urn:schemas-upnp-org:device:InternetGatewayDevice:1 usn: uuid:ef526755-528c-4513-b89c-cdc8891c669d::urn:schemas-upnp-org:device:InternetGatewayDevice:1
[2021-May-17 21:15:42.807454]: UPnP device url: http://192.168.1.1:5000/rootDesc.xml st: urn:schemas-upnp-org:device:InternetGatewayDevice:1 usn: uuid:ea29f574-55d2-493c-aa12-4f8c5bbed04c::urn:schemas-upnp-org:device:InternetGatewayDevice:1
[2021-May-17 21:15:42.822414]: UPnP TCP mapping verification response: 714, external ip response: 0, external ip: , internal ip: 192.168.1.230, lease: <- this line repeats periodically, but the lease value is never set to anything

No other UPnP-related logs are generated (I have detailed UPnP-logging enabled)

My analysis for possible root cause:
#3035 was merged to fix refreshing of "lost" UPnP leases. As I understand it, the intention is to trigger a refresh of a lease when more than half of the lease time has passed, instead of when it had already expired.

On this line:

if (verify_port_mapping_error_l == UPNPCOMMAND_SUCCESS || atoi (remaining_mapping_duration_l.data ()) <= (network_params.portmapping.lease_duration.count () / 2))
, I think || should be &&. We should skip the refresh if there is an existing lease AND less than half the lease time has passed. Other cases (error case or too much of lease time has passed), we should refresh the lease. But the second part of the if-expression is not evalauted in the success case. In the error case it will be evaluated however, and then "remaining_mapping_duration_l" is likely set to 0 (or remain unmodified of value 0), which would make the second part of the if-expression evaluate to true and the refresh will be skipped.

If the above analysis is correct, then initial leases will never be triggered to be created, since check_mapping() won't trigger it to be added (due to the ||-logic described above), and nothing else seems to trigger it either. Could be verified by never seeing "UPnP %1%:%2% mapped to %3%") % protocol.external_address % config_port_l % node_port_l));" (with values for each % part) in the node log when the node starts up. I tried it on my local node, and I didn't see it in my log file at least.

Even if creating of initial leases is fixed, then another problem could still occur if a lease is "lost" and the fix doesn't take it into account. These are normally detected by calling check_mapping() periodically => lease will still be renewed though to due to refresh_mapping() having scheduled itself to renew created leases. If refresh_mapping() fails to add a lease (at startup or when renewing an existing one) at some point, it will never be scheduled to be added again since check_mapping() will not trigger it either (due to using the "||"-logic described above). If the log on line 106 is ever seen in the log file "UPnP failed ...", then I think the lease could be lost until the process is restarted.

Node version

V22

Build details

Official binaries

OS and version

Windows 10

Steps to reproduce the behavior

  1. Make sure there is an IGD device available in the network
  2. Start nano_node
  3. Observe in router admin interface / check node log whether a lease has been created

Expected behavior

  • UPnP leases created in my router
  • Node log indicating that a TCP lease has been created

Actual behavior

  • No UPnP leases created in my router
  • No node log indicating that a TCP lease has been created

Possible solution

Manually forward needed ports in the router

Supporting files

No response

@sudokai0
Copy link
Contributor Author

I was able to confirm that UPnP leases are created properly if I remove the second part of the if-expression, and running a recompiled node. Then I can see the following (new entry) in the log:

[2021-May-18 17:31:37.666290]: UPnP TCP port mapping response: 0
[2021-May-18 17:31:37.667292]: UPnP :54000 mapped to 54000

@thsfs
Copy link
Contributor

thsfs commented May 19, 2021

Please check whether these changes makes sense:
https://github.com/nanocurrency/nano-node/compare/develop...upnp_leases_issue?expand=1

The implementation is leading to UPNP_GetSpecificPortMappingEntry failed 714: NoSuchEntryInArray

Captured log:
[2021-May-19 19:32:08.011936]: Exiting legacy bootstrap attempt with ID auto_bootstrap_0
[2021-May-19 19:32:08.012175]: IPC: server started
[2021-May-19 19:32:10.062735]: UPnP local address: 192.168.0.14, discovery: 0, IGD search: 1
[2021-May-19 19:32:10.063022]: UPnP device url: http://192.168.0.1:5431/dyndev/uuid:ecc0b149-e27d-4330-bdfa-fea50255045d st: urn:schemas-upnp-org:device:InternetGatewayDevice:1 usn: uuid:ecc0b149-e27d-4330-bdfa-fea50255045d::urn:schemas-upnp-org:device:InternetGatewayDevice:1
[2021-May-19 19:32:10.072115]: UPnP leasing time getting old, remaining time: 600, lease time: 1787, below the threshold: 893
[2021-May-19 19:32:10.081308]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 600
[2021-May-19 19:32:10.164790]: UPnP TCP port mapping response: 0
[2021-May-19 19:32:10.165045]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:32:11.012181]: Found a representative at [::ffff:168.119.169.221]:17075
[2021-May-19 19:32:13.012084]: Starting legacy bootstrap attempt with ID auto_bootstrap_1
[2021-May-19 19:32:13.584150]: Received 1 frontiers from [::ffff:95.216.137.218]:17075
[2021-May-19 19:32:13.824060]: Completed frontier request, 0 out of sync accounts according to [::ffff:95.216.137.218]:17075
[2021-May-19 19:32:13.825325]: Exiting legacy bootstrap attempt with ID auto_bootstrap_1
[2021-May-19 19:32:18.012618]: Starting legacy bootstrap attempt with ID auto_bootstrap_2
[2021-May-19 19:32:18.500558]: Received 1 frontiers from [::ffff:168.119.169.116]:17075
[2021-May-19 19:32:18.806504]: Completed frontier request, 0 out of sync accounts according to [::ffff:168.119.169.116]:17075
[2021-May-19 19:32:18.806884]: Exiting legacy bootstrap attempt with ID auto_bootstrap_2
[2021-May-19 19:32:23.012945]: Starting legacy bootstrap attempt with ID auto_bootstrap_3
[2021-May-19 19:32:23.363581]: Received 1 frontiers from [::ffff:173.75.129.5]:17075
[2021-May-19 19:32:23.516705]: Completed frontier request, 0 out of sync accounts according to [::ffff:173.75.129.5]:17075
[2021-May-19 19:32:23.519762]: Exiting legacy bootstrap attempt with ID auto_bootstrap_3
[2021-May-19 19:32:28.013325]: Starting legacy bootstrap attempt with ID auto_bootstrap_4
[2021-May-19 19:32:29.456122]: Received 1 frontiers from [::ffff:173.75.129.5]:17075
[2021-May-19 19:32:29.810275]: Completed frontier request, 0 out of sync accounts according to [::ffff:173.75.129.5]:17075
[2021-May-19 19:32:29.811463]: Exiting legacy bootstrap attempt with ID auto_bootstrap_4
[2021-May-19 19:33:05.213215]: UPnP leasing time getting old, remaining time: 544, lease time: 1787, below the threshold: 893
[2021-May-19 19:33:05.222073]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 544
[2021-May-19 19:33:05.308113]: UPnP TCP port mapping response: 0
[2021-May-19 19:33:05.308334]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:34:00.351365]: UPnP leasing time getting old, remaining time: 489, lease time: 1787, below the threshold: 893
[2021-May-19 19:34:00.360064]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 489
[2021-May-19 19:34:00.444710]: UPnP TCP port mapping response: 0
[2021-May-19 19:34:00.444923]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:34:55.487461]: UPnP leasing time getting old, remaining time: 434, lease time: 1787, below the threshold: 893
[2021-May-19 19:34:55.496475]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 434
[2021-May-19 19:34:55.578960]: UPnP TCP port mapping response: 0
[2021-May-19 19:34:55.579172]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:35:50.626733]: UPnP leasing time getting old, remaining time: 379, lease time: 1787, below the threshold: 893
[2021-May-19 19:35:50.635804]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 379
[2021-May-19 19:35:50.720445]: UPnP TCP port mapping response: 0
[2021-May-19 19:35:50.720679]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:36:45.763822]: UPnP leasing time getting old, remaining time: 324, lease time: 1787, below the threshold: 893
[2021-May-19 19:36:45.772739]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 324
[2021-May-19 19:36:45.856343]: UPnP TCP port mapping response: 0
[2021-May-19 19:36:45.856569]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:37:40.903617]: UPnP leasing time getting old, remaining time: 268, lease time: 1787, below the threshold: 893
[2021-May-19 19:37:40.913169]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 268
[2021-May-19 19:37:40.998649]: UPnP TCP port mapping response: 0
[2021-May-19 19:37:40.998944]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:38:36.043519]: UPnP leasing time getting old, remaining time: 213, lease time: 1787, below the threshold: 893
[2021-May-19 19:38:36.052728]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 213
[2021-May-19 19:38:36.135586]: UPnP TCP port mapping response: 0
[2021-May-19 19:38:36.135821]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:39:31.185563]: UPnP leasing time getting old, remaining time: 158, lease time: 1787, below the threshold: 893
[2021-May-19 19:39:31.194424]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 158
[2021-May-19 19:39:31.284469]: UPnP TCP port mapping response: 0
[2021-May-19 19:39:31.284696]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:40:26.329683]: UPnP leasing time getting old, remaining time: 103, lease time: 1787, below the threshold: 893
[2021-May-19 19:40:26.338792]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 103
[2021-May-19 19:40:26.425812]: UPnP TCP port mapping response: 0
[2021-May-19 19:40:26.426064]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:41:21.470979]: UPnP leasing time getting old, remaining time: 48, lease time: 1787, below the threshold: 893
[2021-May-19 19:41:21.479855]: UPnP TCP mapping verification response: 0, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease: 48
[2021-May-19 19:41:21.570775]: UPnP TCP port mapping response: 0
[2021-May-19 19:41:21.570873]: UPnP 187.20.X.Y:17075 mapped to 17075
[2021-May-19 19:42:16.615691]: UPNP_GetSpecificPortMappingEntry failed 714: NoSuchEntryInArray
[2021-May-19 19:42:16.615915]: UPnP leasing time getting old, remaining time: 0, lease time: 1787, below the threshold: 893
[2021-May-19 19:42:16.627051]: UPnP TCP mapping verification response: 714, external ip response: 0, external ip: 187.20.X.Y, internal ip: 192.168.0.14, lease:
[2021-May-19 19:42:16.693553]: UPnP TCP port mapping response: 0
[2021-May-19 19:42:16.693935]: UPnP 187.20.X.Y:17075 mapped to 17075

@thsfs thsfs self-assigned this May 19, 2021
@DarrenAlex
Copy link

I don't see an external IP in your logs. Try adding external_address = "::ffff:99.99.99.99" (replace 99.99.99.99 with your external IP) and external_port = 7075 under the [node] section in config-node.toml. This resolved the issue for me

@sudokai0
Copy link
Contributor Author

sudokai0 commented May 20, 2021

@thsfs : I think that the changes makes sense, in that will enable leases at startup to be created again. But I wonder, won't the scheduled refresh created by refresh_mapping() already handle to renew leases?

I wonder a bit what the original purpose of adding the remaining lease time check in check_mapping was (in #3035)? Before #3035, check_mapping() was responsible for triggering the initial lease to be created, by detecting that there was no existing lease. Once a lease has been setup however, refresh_mapping() will schedule to refresh it on it's own (with a timer of "configured lease time - 10 seconds"):

node.workers.add_timed_task (std::chrono::steady_clock::now () + network_params.portmapping.lease_duration - std::chrono::seconds (10), [node_l = node.shared ()] () {
With this fix, there are now seems to be two "competing" timers that refreshes the lease, either "configured lease time - 10 seconds" from refresh_mapping(), or "configured lease time / 2" from check_mappings(), whichever comes first. In the failure case where the router has lost the lease somehow, or failed to add a new lease in refresh_mapping(), the check for remaining lease time doesn't matter.

I don't know the full history of this implementation , and my analysis of the source code might miss something, but maybe worth to check this a bit more?

@dsiganos
Copy link
Contributor

dsiganos commented May 20, 2021

Hi @sudokai0, your analysis makes sense to me. I think refresh_mapping spawned from inside refresh_mapping should not be needed since there is an outer loop checking regularly. We just have to make sure that the outer loop checks at least twice as fast as the lease time. Currently it checks every 5 minutes irrespective of the lease time.

@thsfs
Copy link
Contributor

thsfs commented May 20, 2021

Thanks for your inputs @sudokai0 , I added a PR for this #3298 with some changes, but I'm afraid there is still more work to do, because despite all this implementation, I noticed that the leasing time is not getting refreshed sooner.

@thsfs
Copy link
Contributor

thsfs commented May 20, 2021

I don't see an external IP in your logs. Try adding external_address = "::ffff:99.99.99.99" (replace 99.99.99.99 with your external IP) and external_port = 7075 under the [node] section in config-node.toml. This resolved the issue for me

the port is different (17075) because I ran it on a different network. The external IP address is this "187.20.X.Y" with the end changed to X.Y.

@thsfs thsfs closed this as completed May 25, 2021
@thsfs
Copy link
Contributor

thsfs commented May 25, 2021

Code already merged (#3298)

@thsfs thsfs modified the milestones: V23.0, V22.1 May 25, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants