Lighthouse: LibP2P start-up ignores `AddrInUse` error

[michaelsproul]

Description

When starting up, if port 9000 is already in use, the node will log a _debug-level_ log (invisible to many users) and silently fail to start listening.

Aug 07 16:15:29.784 WARN Ethereum 2.0 is pre-release. This software is experimental.
Aug 07 16:15:29.784 INFO Configured for testnet                  name: medalla
Aug 07 16:15:29.785 INFO Data directory initialised              datadir: /home/michael/.lighthouse
Aug 07 16:15:29.854 INFO Starting beacon chain                   method: resume, service: beacon
Aug 07 16:15:30.554 INFO Block production disabled               reason: no eth1 backend configured
Aug 07 16:15:30.578 INFO Beacon chain initialized                head_slot: 63, head_block: 0x5c4d…bde1, head_state: 0xd477…1f68, service: beacon
Aug 07 16:15:30.578 INFO Timer service started                   service: node_timer
Aug 07 16:15:30.578 DEBG Loaded network key from disk.           service: libp2p
Aug 07 16:15:30.579 DEBG ENR loaded from disk                    file: "/home/michael/.lighthouse/beacon/network/enr.dat", service: libp2p
Aug 07 16:15:30.579 INFO Libp2p Service                          peer_id: PeerId("16Uiu2HAkxhy6aMEixiazmcEeuArEZQm4GCWiavX2eKEk1wHyQEfH"), service: libp2p
Aug 07 16:15:30.579 DEBG Attempting to open listening ports      udp_port: 9000, tcp_port: 9000, address: 0.0.0.0, service: libp2p
Aug 07 16:15:30.579 INFO ENR Initialised                         tcp: Some(9000), udp: None, ip: None, id: 0x1f56..77fe, seq: 1, enr: enr:-KO4QMXM91a2QPtS-zNTspf0q18eqy5UYAxUWrJ1CmKimmhPJhZzR1T9LICbLnvVCbLy4uI9bBu7CSAxWPspIWJ5gx4Bh2F0dG5ldHOIAAAAAAAAAACEZXRoMpDnp11aAAAAAf__________gmlkgnY0iXNlY3AyNTZrMaECML-1OUj0rCBGOrSX-NmeJUOudN2u6wOG5rXi8Ef4kRiDdGNwgiMo, service: libp2p
Aug 07 16:15:30.579 DEBG Adding node to routing table            tcp: Some(9000), udp: Some(9000), ip: Some(52.37.3.144), peer_id: 16Uiu2HAmNvRrQiBCBL8amJZFzaiTGGesCirv17TfEnAvzfLiZRPB, node_id: 0x88a2..07f7, service: libp2p
Aug 07 16:15:30.579 DEBG Adding node to routing table            tcp: Some(9000), udp: Some(9000), ip: Some(13.251.44.198), peer_id: 16Uiu2HAm3k4PUxH5xVorayPLjQGNK6KLQhR56Gr9dg7kiRPyco2J, node_id: 0xfcf5..5792, service: libp2p
Aug 07 16:15:30.579 DEBG Adding node to routing table            tcp: Some(9000), udp: Some(9000), ip: Some(10.0.1.97), peer_id: 16Uiu2HAmDozn3ksBmKS83i9KD6QETymzPCTw9ZxszGYvmKxfDmDK, node_id: 0xb39b..4cd6, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: None, udp: Some(4000), ip: Some(18.223.219.100), peer_id: 16Uiu2HAm32wHVEwmLAUNprAGo1tXyTamBEXvgPMEZ2Ne1nZUFgeb, node_id: 0x652d..a80d, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: None, udp: Some(4000), ip: Some(18.223.219.100), peer_id: 16Uiu2HAm8fPSyU1y2hmLP9wEdr85tPDS6S7sepU3T6Js9DRtefmz, node_id: 0xe8ff..29e4, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: None, udp: Some(4000), ip: Some(18.223.219.100), peer_id: 16Uiu2HAm4a3gBWVPgFuZnXRsMQfpoFmt8MT4VX4idojPck7VzXYw, node_id: 0x38a5..9b03, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: Some(9000), udp: Some(9000), ip: Some(51.15.97.240), peer_id: 16Uiu2HAmPqBZe1AZzr9FAZ8w5Wd6VE1Hi95DzYD6mGPWY6oiYEjE, node_id: 0x2f5e..0964, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: Some(9000), udp: Some(9000), ip: Some(51.15.70.7), peer_id: 16Uiu2HAmTxXKUd1DFdsudodJostmWRpDVj77e48JKCxUdGm1RLaA, node_id: 0x4262..aa98, service: libp2p
Aug 07 16:15:30.580 DEBG Adding node to routing table            tcp: None, udp: Some(9000), ip: Some(100.27.0.124), peer_id: 16Uiu2HAkvAyboouhSeiDsJPoQrbXbuYfena1XM8mygihG5x1atNW, node_id: 0x31b7..f952, service: libp2p
Aug 07 16:15:30.581 DEBG Discovery service started               service: libp2p
Aug 07 16:15:30.581 DEBG Queuing a peer discovery request        service: libp2p
Aug 07 16:15:30.581 INFO Listening established                   address: /ip4/0.0.0.0/tcp/9000/p2p/16Uiu2HAkxhy6aMEixiazmcEeuArEZQm4GCWiavX2eKEk1wHyQEfH, service: libp2p
Aug 07 16:15:30.581 DEBG Dialing libp2p peer                     address: /ip4/52.37.3.144/tcp/9000, service: libp2p
Aug 07 16:15:30.581 DEBG Dialing libp2p peer                     address: /ip4/13.251.44.198/tcp/9000, service: libp2p
Aug 07 16:15:30.581 DEBG Dialing libp2p peer                     address: /ip4/10.0.1.97/tcp/9000, service: libp2p
Aug 07 16:15:30.581 DEBG Dialing libp2p peer                     address: /ip4/51.15.97.240/tcp/9000, service: libp2p
Aug 07 16:15:30.581 DEBG Dialing libp2p peer                     address: /ip4/51.15.70.7/tcp/9000, service: libp2p
Aug 07 16:15:30.581 DEBG Subscribed to topic                     topic: /eth2/e7a75d5a/beacon_block/ssz_snappy, service: libp2p
Aug 07 16:15:30.581 DEBG Subscribed to topic                     topic: /eth2/e7a75d5a/beacon_aggregate_and_proof/ssz_snappy, service: libp2p
Aug 07 16:15:30.581 DEBG Subscribed to topic                     topic: /eth2/e7a75d5a/voluntary_exit/ssz_snappy, service: libp2p
Aug 07 16:15:30.581 DEBG Subscribed to topic                     topic: /eth2/e7a75d5a/proposer_slashing/ssz_snappy, service: libp2p
Aug 07 16:15:30.581 DEBG Subscribed to topic                     topic: /eth2/e7a75d5a/attester_slashing/ssz_snappy, service: libp2p
Aug 07 16:15:30.582 INFO Subscribed to topics                    topics: [BeaconBlock, BeaconAggregateAndProof, VoluntaryExit, ProposerSlashing, AttesterSlashing], service: libp2p
Aug 07 16:15:30.582 DEBG Loading peers into the routing table    peers: 9
Aug 07 16:15:30.582 DEBG Sync Manager started                    service: sync
Aug 07 16:15:30.582 DEBG Network message router started
Aug 07 16:15:30.582 DEBG Listener closed                         reason: Err(Custom { kind: Other, error: Custom { kind: Other, error: Other(A(Other(A(Underlying(Os { code: 98, kind: AddrInUse, message: "Address already in use" }))))) } }), addresses: [], service: libp2p

Version

Lighthouse Lighthouse/v0.2.0/7fc1f5593+
BLS Library: blst

One of my slasher commits -- descended from 20ee8939691bcffc2171ef26a18573b1db8f0276

Present Behaviour

Lighthouse starts in a crippled state (not listening on :9000)

Expected Behaviour

Lighthouse quits if it can't obtain exclusive access to port 9000

[AgeManning]

I'm going to increase the log on this one and handle a more sophisticated client shutdown in #1494

[AgeManning]

Partially resolved in #1495 and closing in favour of #1494