Skip to content

Commit

Permalink
do not panic when upnp fails (#1941)
Browse files Browse the repository at this point in the history 
## Motivation
A user reported that the node panics during startup. The log indicates that they have a UPnP device on their network but an error was returned from it while trying to acquire a port.

<details>
<summary>Logs</summary>

```
2020-03-25T16:34:46.340+0100	INFO	00000.defaultLogger	App version: 0.1.8. Git: HEAD - 59ae536 . Go Version: go1.13.7. OS: darwin-amd64 
2020-03-25T16:34:46.340+0100	INFO	00000.defaultLogger	Welcome to Spacemesh. Spacemesh full node is starting...
2020-03-25T16:34:46.404+0100	INFO	00000.defaultLogger	ntp check from server 0.pool.ntp.org, drift: -11.744261ms, start_check: 2020-03-25 15:34:46.380028 +0000 UTC, latency: 33.17µs, rsp: 2020-03-25 15:34:46.391755676 +0000 UTC
2020-03-25T16:34:46.409+0100	INFO	00000.defaultLogger	ntp check from server time1.google.com, drift: -15.263591ms, start_check: 2020-03-25 15:34:46.378515 +0000 UTC, latency: 175.591µs, rsp: 2020-03-25 15:34:46.393690796 +0000 UTC
2020-03-25T16:34:46.423+0100	INFO	00000.defaultLogger	ntp check from server time.google.com, drift: -15.136321ms, start_check: 2020-03-25 15:34:46.392046 +0000 UTC, latency: 33.748µs, rsp: 2020-03-25 15:34:46.407165447 +0000 UTC
2020-03-25T16:34:46.423+0100	INFO	00000.defaultLogger	ntp check from server 1.pool.ntp.org, drift: -16.431389ms, start_check: 2020-03-25 15:34:46.38955 +0000 UTC, latency: 46.525µs, rsp: 2020-03-25 15:34:46.405958127 +0000 UTC
2020-03-25T16:34:46.431+0100	INFO	00000.defaultLogger	ntp check from server time.asia.apple.com, drift: -14.811929ms, start_check: 2020-03-25 15:34:46.40022 +0000 UTC, latency: 31.873µs, rsp: 2020-03-25 15:34:46.415015993 +0000 UTC
2020-03-25T16:34:46.431+0100	INFO	00000.defaultLogger	System clock synchronized with ntp. drift: -15.070613ms
2020-03-25T16:34:46.431+0100	INFO	00000.defaultLogger	Starting Spacemesh	{"data-dir": "/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata", "post-dir": "/Users/lasseclausen/post/data"}
2020-03-25T16:34:46.431+0100	WARN	00000.defaultLogger	Failed to find identity file: not found
2020-03-25T16:34:46.432+0100	WARN	00000.defaultLogger	Created new identity with public key 22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6
2020-03-25T16:34:46.445+0100	INFO	00000.defaultLogger	Initializing P2P services
2020-03-25T16:34:46.445+0100	INFO	clock	starting global clock now=2020-03-25 16:34:46.445059 +0100 CET m=+0.125221460 genesis=2020-03-19 18:18:42 +0000 +0000
2020-03-25T16:34:46.445+0100	INFO	clock	global clock going to sleep before next layer	{"diff": "3m55.554741s", "next_layer": 1696}
2020-03-25T16:34:46.445+0100	WARN	22ee3.p2p          	failed to load p2p identity from disk at /Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata. creating a new identity, err:directory not found /Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata
2020-03-25T16:34:46.445+0100	INFO	22ee3.p2p          	Local node identity >> 4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ
2020-03-25T16:34:46.487+0100	INFO	00000.defaultLogger	Saved p2p node information (/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata/p2p/nodes/4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ/id.json),  Identity - 4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ
2020-03-25T16:34:46.489+0100	WARN	22ee3.p2p          	Peers not loaded to addrbook since file does not exist. file=/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata/p2p/peers.json	{"P2PID": "4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ"}
2020-03-25T16:34:46.496+0100	INFO	22ee3.stateDbStore 	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:47.665+0100	INFO	22ee3.atxDbStore   	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:47.765+0100	INFO	22ee3.poetDbStore  	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:47.864+0100	INFO	22ee3.stateDbStore 	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:47.939+0100	INFO	22ee3.store        	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.020+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.082+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.174+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.294+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.401+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.511+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.608+0100	INFO	22ee3.appliedTxs   	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:34:48.677+0100	INFO	00000.defaultLogger	started processor with state root 56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421
2020-03-25T16:34:48.677+0100	INFO	22ee3.meshDb       	did not find data to recover on disc	{"node_id": "22ee3"}
2020-03-25T16:34:48.677+0100	INFO	22ee3.trtl         	Tortoise update tables	{"node_id": "22ee3", "layer_id": 0, "n_blocks": 1}
2020-03-25T16:34:48.677+0100	INFO	22ee3.app          	Genesis account created: 0x1, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:34:48.677+0100	INFO	22ee3.app          	Genesis account created: 0x7be017a967db77fd10ac7c891b3d6d946dea7e3e14756e2f0f9e09b9663f0d9c, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:34:48.677+0100	INFO	22ee3.app          	Genesis account created: 0x22a31a84ab876f82fcafba86e77910b4419a4ee0f1d5483d7dd3b5b6b6922ee9, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:34:48.681+0100	INFO	00000.defaultLogger	subscribed to channel
2020-03-25T16:34:48.681+0100	INFO	00000.defaultLogger	subscribed to channel
2020-03-25T16:34:48.681+0100	INFO	22ee3.hare         	Starting HARE_PROTOCOL	{"node_id": "22ee3"}
2020-03-25T16:34:48.682+0100	INFO	00000.defaultLogger	Manual post init
2020-03-25T16:34:48.682+0100	INFO	ticker	started notifying
2020-03-25T16:34:48.681+0100	INFO	22ee3.sync         	Node is out of sync setting gossip-synced to false and starting sync	{"node_id": "22ee3"}
2020-03-25T16:34:48.682+0100	INFO	22ee3.sync         	syncing layer	{"node_id": "22ee3", "current_sync_layer": 1, "last_ticked_layer": 1696}
2020-03-25T16:34:48.682+0100	INFO	22ee3.blockBuilder 	start listening for txs	{"node_id": "22ee3"}
2020-03-25T16:34:48.682+0100	INFO	22ee3.p2p          	Trying to acquire ports using UPnP, this might take a while..	{"P2PID": "4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ"}
2020-03-25T16:34:48.682+0100	INFO	22ee3.blockBuilder 	start listening for atxs	{"node_id": "22ee3"}
2020-03-25T16:34:48.682+0100	INFO	22ee3.sync         .peers        	now connected	{"node_id": "22ee3", "n_peers": 0}
2020-03-25T16:34:48.683+0100	INFO	22ee3.sync         	could not get layer 1 from neighbors: no peers 	{"node_id": "22ee3"}
2020-03-25T16:34:48.683+0100	INFO	00000.defaultLogger	challenge not loaded: leveldb: not found
2020-03-25T16:34:50.802+0100	ERROR	00000.defaultLogger	Fatal: goroutine panicked. Stacktrace: goroutine 1 [running]:
runtime/debug.Stack(0x16, 0xc0004a2b08, 0x1)
	/usr/local/Cellar/go/1.13.7/libexec/src/runtime/debug/stack.go:24 +0x9d
github.com/spacemeshos/go-spacemesh/log.Log.Panic(0xc0002cd260, 0xc0000c83f0, 0xc0000c83e8, 0x4b66054, 0x1f, 0xc0004a2ee0, 0x1, 0x1)
	/Users/avive/dev/go-spacemesh/log/zap.go:44 +0x26
github.com/spacemeshos/go-spacemesh/log.Panic(...)
	/Users/avive/dev/go-spacemesh/log/log.go:185
github.com/spacemeshos/go-spacemesh/cmd/node.(*SpacemeshApp).Start(0xc0001aa5a0, 0x545a640, 0xc000138800, 0x0, 0x8)
	/Users/avive/dev/go-spacemesh/cmd/node/node.go:887 +0xee4
github.com/spacemeshos/go-spacemesh/cmd/node.glob..func1(0x545a640, 0xc000138800, 0x0, 0x8)
	/Users/avive/dev/go-spacemesh/cmd/node/node.go:90 +0x211
github.com/spf13/cobra.(*Command).execute(0x545a640, 0xc0000ce010, 0x8, 0x8, 0x545a640, 0xc0000ce010)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:766 +0x2aa
github.com/spf13/cobra.(*Command).ExecuteC(0x545a640, 0xc000000180, 0xc000161f50, 0x4007b5f)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:850 +0x2fb
github.com/spf13/cobra.(*Command).Execute(...)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:800
main.main()
	/Users/avive/dev/go-spacemesh/main.go:23 +0xac

2020-03-25T16:34:50.802+0100	PANIC	00000.defaultLogger	Error starting p2p services: error getting port: failed to acquire requested port using UPnP: failed to forward port 7153: goupnp: SOAP request got HTTP 500 Internal Server Error
2020-03-25T16:34:50.827+0100	INFO	00000.defaultLogger	App Cleanup starting...
2020-03-25T16:34:50.827+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing block producer	{"node_id": "22ee3"}
2020-03-25T16:34:50.827+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing clock	{"node_id": "22ee3"}
2020-03-25T16:34:50.827+0100	INFO	22ee3.app          	closing PoET listener	{"node_id": "22ee3"}
2020-03-25T16:34:50.827+0100	INFO	22ee3.app          	closing atx builder	{"node_id": "22ee3"}
2020-03-25T16:34:50.827+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing blockListener	{"node_id": "22ee3"}
2020-03-25T16:34:50.827+0100	INFO	22ee3.blockListener	block listener closing, waiting for gorutines	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.sync         	Closing syncer	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.blockListener	listening  stopped	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.poetListener 	listening stopped	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.sync         .blockFetchQueue	done	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.sync         .atxFetchQueue	done	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.sync         .txFetchQueue 	done	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.sync         	sync Closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.blockListener	block listener closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing Hare	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing p2p	{"node_id": "22ee3"}
2020-03-25T16:34:50.828+0100	INFO	22ee3.p2p          	Address manager shutting down	{"P2PID": "4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ"}
2020-03-25T16:34:50.828+0100	WARN	22ee3.hare         	Broker exiting	{"node_id": "22ee3"}
2020-03-25T16:34:50.832+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing mesh	{"node_id": "22ee3"}
2020-03-25T16:34:50.832+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.832+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.832+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.stateDbStore 	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.atxDbStore   	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.833+0100	INFO	22ee3.poetDbStore  	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.834+0100	INFO	22ee3.stateDbStore 	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.834+0100	INFO	22ee3.store        	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.834+0100	INFO	22ee3.appliedTxs   	Database closed	{"node_id": "22ee3"}
2020-03-25T16:34:50.834+0100	INFO	00000.defaultLogger	App Cleanup completed


2020-03-25T16:45:14.670+0100	INFO	00000.defaultLogger	App version: 0.1.8. Git: HEAD - 59ae536 . Go Version: go1.13.7. OS: darwin-amd64 
2020-03-25T16:45:14.671+0100	INFO	00000.defaultLogger	Welcome to Spacemesh. Spacemesh full node is starting...
2020-03-25T16:45:14.711+0100	INFO	00000.defaultLogger	ntp check from server time.google.com, drift: -18.449977ms, start_check: 2020-03-25 15:45:14.680034 +0000 UTC, latency: 220.802µs, rsp: 2020-03-25 15:45:14.698373576 +0000 UTC
2020-03-25T16:45:14.711+0100	INFO	00000.defaultLogger	ntp check from server time1.google.com, drift: -18.106509ms, start_check: 2020-03-25 15:45:14.680028 +0000 UTC, latency: 226.094µs, rsp: 2020-03-25 15:45:14.698021462 +0000 UTC
2020-03-25T16:45:14.725+0100	INFO	00000.defaultLogger	ntp check from server 0.pool.ntp.org, drift: -15.76744ms, start_check: 2020-03-25 15:45:14.698098 +0000 UTC, latency: 38.428µs, rsp: 2020-03-25 15:45:14.713846226 +0000 UTC
2020-03-25T16:45:14.726+0100	INFO	00000.defaultLogger	ntp check from server 1.pool.ntp.org, drift: -17.236638ms, start_check: 2020-03-25 15:45:14.701262 +0000 UTC, latency: 46.514µs, rsp: 2020-03-25 15:45:14.718475381 +0000 UTC
2020-03-25T16:45:14.733+0100	INFO	00000.defaultLogger	ntp check from server time.asia.apple.com, drift: -17.237258ms, start_check: 2020-03-25 15:45:14.702988 +0000 UTC, latency: 33.403µs, rsp: 2020-03-25 15:45:14.720208557 +0000 UTC
2020-03-25T16:45:14.733+0100	INFO	00000.defaultLogger	System clock synchronized with ntp. drift: -17.526801ms
2020-03-25T16:45:14.733+0100	INFO	00000.defaultLogger	Starting Spacemesh	{"data-dir": "/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata", "post-dir": "/Users/lasseclausen/post/data"}
2020-03-25T16:45:14.735+0100	INFO	00000.defaultLogger	Loaded identity from file ('/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata/22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6/key.bin')
2020-03-25T16:45:14.748+0100	INFO	00000.defaultLogger	Initializing P2P services
2020-03-25T16:45:14.749+0100	INFO	clock	starting global clock now=2020-03-25 16:45:14.748889 +0100 CET m=+0.148869062 genesis=2020-03-19 18:18:42 +0000 +0000
2020-03-25T16:45:14.749+0100	INFO	clock	global clock going to sleep before next layer	{"diff": "3m27.250672s", "next_layer": 1698}
2020-03-25T16:45:14.750+0100	INFO	22ee3.p2p          	Local node identity >> 4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ
2020-03-25T16:45:14.767+0100	INFO	00000.defaultLogger	Saved p2p node information (/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata/p2p/nodes/4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ/id.json),  Identity - 4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ
2020-03-25T16:45:14.776+0100	INFO	00000.defaultLogger	Loaded 0 addresses from file '/Users/lasseclausen/Library/Application Support/Spacemesh/spacemeshtestdata/p2p/peers.json'
2020-03-25T16:45:14.778+0100	INFO	22ee3.stateDbStore 	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:14.864+0100	INFO	22ee3.atxDbStore   	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:14.941+0100	INFO	22ee3.poetDbStore  	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.014+0100	INFO	22ee3.stateDbStore 	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.088+0100	INFO	22ee3.store        	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.144+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.242+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.325+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.382+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.456+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.516+0100	INFO	22ee3.meshDb       	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.567+0100	INFO	22ee3.appliedTxs   	Allocated cache and file handles%!(EXTRA string=cache, int=16, string=handles, int=16)	{"node_id": "22ee3"}
2020-03-25T16:45:15.649+0100	INFO	00000.defaultLogger	started processor with state root 56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421
2020-03-25T16:45:15.649+0100	INFO	22ee3.meshDb       	did not find data to recover on disc	{"node_id": "22ee3"}
2020-03-25T16:45:15.649+0100	INFO	22ee3.trtl         	Tortoise update tables	{"node_id": "22ee3", "layer_id": 0, "n_blocks": 1}
2020-03-25T16:45:15.650+0100	INFO	22ee3.app          	Genesis account created: 0x22a31a84ab876f82fcafba86e77910b4419a4ee0f1d5483d7dd3b5b6b6922ee9, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:45:15.650+0100	INFO	22ee3.app          	Genesis account created: 0x1, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:45:15.650+0100	INFO	22ee3.app          	Genesis account created: 0x7be017a967db77fd10ac7c891b3d6d946dea7e3e14756e2f0f9e09b9663f0d9c, Balance: %!s(uint64=100000000000000000)	{"node_id": "22ee3"}
2020-03-25T16:45:15.651+0100	WARN	22ee3.meshDb       	block already exist in database	{"node_id": "22ee3", "block_id": "a9f89"}
2020-03-25T16:45:15.651+0100	WARN	22ee3.mesh         	failed to add block a9f89  block already exist in database	{"node_id": "22ee3"}
2020-03-25T16:45:15.651+0100	ERROR	00000.defaultLogger	error adding genesis block block already exist in database
2020-03-25T16:45:15.653+0100	INFO	00000.defaultLogger	subscribed to channel
2020-03-25T16:45:15.653+0100	INFO	00000.defaultLogger	subscribed to channel
2020-03-25T16:45:15.654+0100	INFO	22ee3.hare         	Starting HARE_PROTOCOL	{"node_id": "22ee3"}
2020-03-25T16:45:15.654+0100	INFO	22ee3.sync         	Node is out of sync setting gossip-synced to false and starting sync	{"node_id": "22ee3"}
2020-03-25T16:45:15.655+0100	INFO	22ee3.sync         	syncing layer	{"node_id": "22ee3", "current_sync_layer": 1, "last_ticked_layer": 1698}
2020-03-25T16:45:15.655+0100	INFO	22ee3.sync         .peers        	now connected	{"node_id": "22ee3", "n_peers": 0}
2020-03-25T16:45:15.655+0100	INFO	22ee3.sync         	could not get layer 1 from neighbors: no peers 	{"node_id": "22ee3"}
2020-03-25T16:45:15.655+0100	INFO	00000.defaultLogger	Manual post init
2020-03-25T16:45:15.656+0100	INFO	ticker	started notifying
2020-03-25T16:45:15.656+0100	INFO	22ee3.p2p          	Trying to acquire ports using UPnP, this might take a while..	{"P2PID": "4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ"}
2020-03-25T16:45:15.656+0100	INFO	22ee3.blockBuilder 	start listening for atxs	{"node_id": "22ee3"}
2020-03-25T16:45:15.656+0100	INFO	22ee3.blockBuilder 	start listening for txs	{"node_id": "22ee3"}
2020-03-25T16:45:15.656+0100	INFO	00000.defaultLogger	challenge not loaded: leveldb: not found
2020-03-25T16:45:17.774+0100	ERROR	00000.defaultLogger	Fatal: goroutine panicked. Stacktrace: goroutine 1 [running]:
runtime/debug.Stack(0x16, 0xc003344b08, 0x1)
	/usr/local/Cellar/go/1.13.7/libexec/src/runtime/debug/stack.go:24 +0x9d
github.com/spacemeshos/go-spacemesh/log.Log.Panic(0xc0001cfce0, 0xc0001be240, 0xc0001be238, 0x4b66054, 0x1f, 0xc003344ee0, 0x1, 0x1)
	/Users/avive/dev/go-spacemesh/log/zap.go:44 +0x26
github.com/spacemeshos/go-spacemesh/log.Panic(...)
	/Users/avive/dev/go-spacemesh/log/log.go:185
github.com/spacemeshos/go-spacemesh/cmd/node.(*SpacemeshApp).Start(0xc00028e5a0, 0x545a640, 0xc0001c4200, 0x0, 0x8)
	/Users/avive/dev/go-spacemesh/cmd/node/node.go:887 +0xee4
github.com/spacemeshos/go-spacemesh/cmd/node.glob..func1(0x545a640, 0xc0001c4200, 0x0, 0x8)
	/Users/avive/dev/go-spacemesh/cmd/node/node.go:90 +0x211
github.com/spf13/cobra.(*Command).execute(0x545a640, 0xc0000320a0, 0x8, 0x8, 0x545a640, 0xc0000320a0)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:766 +0x2aa
github.com/spf13/cobra.(*Command).ExecuteC(0x545a640, 0xc000000180, 0xc00014bf50, 0x4007b5f)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:850 +0x2fb
github.com/spf13/cobra.(*Command).Execute(...)
	/Users/avive/dev/go/pkg/mod/github.com/spf13/cobra@v0.0.4/command.go:800
main.main()
	/Users/avive/dev/go-spacemesh/main.go:23 +0xac

2020-03-25T16:45:17.774+0100	PANIC	00000.defaultLogger	Error starting p2p services: error getting port: failed to acquire requested port using UPnP: failed to forward port 7153: goupnp: SOAP request got HTTP 500 Internal Server Error
2020-03-25T16:45:17.789+0100	INFO	00000.defaultLogger	App Cleanup starting...
2020-03-25T16:45:17.789+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing block producer	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing clock	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.app          	closing PoET listener	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.app          	closing atx builder	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing blockListener	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.blockListener	block listener closing, waiting for gorutines	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.sync         	Closing syncer	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.sync         .blockFetchQueue	done	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.sync         .atxFetchQueue	done	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.sync         .txFetchQueue 	done	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.blockListener	listening  stopped	{"node_id": "22ee3"}
2020-03-25T16:45:17.790+0100	INFO	22ee3.poetListener 	listening stopped	{"node_id": "22ee3"}
2020-03-25T16:45:17.789+0100	INFO	22ee3.sync         	Node is out of sync setting gossip-synced to false and starting sync	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.sync         	syncing layer	{"node_id": "22ee3", "current_sync_layer": 1, "last_ticked_layer": 1698}
2020-03-25T16:45:17.792+0100	INFO	22ee3.sync         	receive interrupt	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.sync         	sync Closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.blockListener	block listener closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing Hare	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing p2p	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	WARN	22ee3.hare         	Broker exiting	{"node_id": "22ee3"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.p2p          	Address manager shutting down	{"P2PID": "4xUAmVYKhanbajf2Js6i33DYAaMWMq1CjckrNA2sTdfJ"}
2020-03-25T16:45:17.792+0100	INFO	22ee3.app          	22ee3ba3c83f8b241bf535abc46e0e82d4c9659f721a4d61ea4aa6b9d42629e6 closing mesh	{"node_id": "22ee3"}
2020-03-25T16:45:17.793+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.793+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.793+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.793+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.793+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.794+0100	INFO	22ee3.meshDb       	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.794+0100	INFO	22ee3.stateDbStore 	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.794+0100	INFO	22ee3.atxDbStore   	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.794+0100	INFO	22ee3.poetDbStore  	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.794+0100	INFO	22ee3.stateDbStore 	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.795+0100	INFO	22ee3.store        	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.795+0100	INFO	22ee3.appliedTxs   	Database closed	{"node_id": "22ee3"}
2020-03-25T16:45:17.795+0100	INFO	00000.defaultLogger	App Cleanup completed
```
</details>

## Changes
The method that acquires ports now doesn't return an error due to UPnP failures. It now prints a warning if a specific port was requested. If a random port was requested, there's now a limit of 20 retries due to UPnP failures. After those retries, the node will just continue without obtaining the port.

## Test Plan
Unit tests have been updated.
  • Loading branch information
@noamnelke
noamnelke committed Apr 5, 2020
1 parent 59ae536 commit 9a6dfe8
Show file tree
Hide file tree
Showing 2 changed files with 21 additions and 13 deletions.
31 changes: 20 additions & 11 deletions p2p/swarm.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,9 @@ import (
// ConnectingTimeout is the timeout we wait when trying to connect a neighborhood
const ConnectingTimeout = 20 * time.Second //todo: add to the config

// UPNPRetries is the number of times to retry obtaining a port due to a UPnP failure
const UPNPRetries = 20

type cPool interface {
GetConnection(address inet.Addr, pk p2pcrypto.PublicKey) (net.Connection, error)
GetConnectionIfExists(pk p2pcrypto.PublicKey) (net.Connection, error)
Expand Down Expand Up @@ -900,6 +903,7 @@ func (s *swarm) getListeners(
}
}

upnpFails := 0
for {
tcpAddr := &inet.TCPAddr{IP: listeningIp, Port: port}
tcpListener, err := getTcpListener(tcpAddr)
Expand All @@ -925,22 +929,27 @@ func (s *swarm) getListeners(
if gateway != nil {
err := nat_traversal.AcquirePortFromGateway(gateway, uint16(port))
if err != nil {
if err := tcpListener.Close(); err != nil {
s.logger.With().Error("error closing tcp listener", log.Err(err))
}
if err := udpListener.Close(); err != nil {
s.logger.With().Error("error closing udp listener", log.Err(err))
if upnpFails >= UPNPRetries {
return tcpListener, udpListener, nil
}
if randomPort {
if err := tcpListener.Close(); err != nil {
s.logger.With().Error("error closing tcp listener", log.Err(err))
}
if err := udpListener.Close(); err != nil {
s.logger.With().Error("error closing udp listener", log.Err(err))
}
port = 0
upnpFails++
continue
}
return nil, nil, fmt.Errorf("failed to acquire requested port using UPnP: %v", err)
}
s.releaseUpnp = func() {
err := gateway.Clear(uint16(port))
if err != nil {
s.logger.Warning("failed to release acquired UPnP port %v: %v", port, err)
s.logger.Warning("failed to acquire requested port using UPnP: %v", err)
} else {
s.releaseUpnp = func() {
err := gateway.Clear(uint16(port))
if err != nil {
s.logger.Warning("failed to release acquired UPnP port %v: %v", port, err)
}
}
}
}
Expand Down
3 changes: 1 addition & 2 deletions p2p/swarm_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1256,8 +1256,7 @@ func TestSwarm_getListeners_specificPortUnavailable(t *testing.T) {
1337: {udpResponse{}},
}

r.EqualError(testGetListenersScenario(t, port, tcpResponses, udpResponses, createDiscoverUpnpFunc(nil, 1337, ErrPortUnavailable), true),
"failed to acquire requested port using UPnP: failed to forward port 1337: failed to acquire port")
r.NoError(testGetListenersScenario(t, port, tcpResponses, udpResponses, createDiscoverUpnpFunc(nil, 1337, ErrPortUnavailable), true))
}

func TestSwarm_getListeners_upnpMoreCases(t *testing.T) {
Expand Down

0 comments on commit 9a6dfe8

Please sign in to comment.