node: return an error when node.startRPC returns one

[meowsbits]

Errors returned from this function were getting ignored, resulting in silent-but-deadly startup errors, especially around authrpc, which is a relatively new addition, and the port collision of which causes a lot of people a lot of headaches.

Date: 2023-11-01 07:51:52-06:00

See screenshot from a bug report on Discord --

Now, it'll behave like this:

INFO [11-01|08:05:44.149|core/blockchain.go:518]             Loaded most recent local block           number=0 hash=d4e567..cb8fa3 td=17,179,869,184 age=54y7mo1w
WARN [11-01|08:05:44.150|core/state/snapshot/snapshot.go:214] Failed to load snapshot                  err="missing or corrupted snapshot"
INFO [11-01|08:05:44.163|core/state/snapshot/snapshot.go:738] Rebuilding state snapshot 
DEBUG[11-01|08:05:44.163|core/state/snapshot/generate.go:113] Journalled generator progress            progress=empty
DEBUG[11-01|08:05:44.170|core/state/snapshot/generate.go:80]  Start snapshot generation                root=d7f897..0f0544
INFO [11-01|08:05:44.170|core/state/snapshot/context.go:85]   Resuming state snapshot generation       root=d7f897..0f0544 accounts=0 slots=0 storage=0.00B dangling=0 elapsed=7.007ms
DEBUG[11-01|08:05:44.170|core/txpool/legacypool/legacypool.go:1414] Reinjecting stale transactions           count=0
INFO [11-01|08:05:44.170|core/txpool/legacypool/journal.go:167]     Regenerated local transaction journal    transactions=0 accounts=0
DEBUG[11-01|08:05:44.199|core/txpool/blobpool/blobpool.go:1020]     Blobpool tip threshold updated           tip=1
INFO [11-01|08:05:44.201|eth/gasprice/gasprice.go:106]              Gasprice oracle is ignoring threshold set threshold=2
WARN [11-01|08:05:44.210|core/rawdb/accessors_metadata.go:116]      Error reading unclean shutdown markers   error="pebble: not found"
DEBUG[11-01|08:05:44.213|core/state/snapshot/generate.go:113]       Journalled generator progress            progress=0x3d45dbfe8844979977e1967ae6e5223e5a82ce87b09cab51c2865987fa20ec91
WARN [11-01|08:05:44.217|eth/catalyst/api.go:42]                    Engine API enabled                       protocol=eth
WARN [11-01|08:05:44.217|eth/catalyst/api.go:139]                   Engine API started but chain not configured for merge yet 
INFO [11-01|08:05:44.217|node/node.go:277]                          Starting peer-to-peer node               instance=CoreGeth/v1.12.16-unstable-27134958-20231101/linux-amd64/go1.21.2
DEBUG[11-01|08:05:44.255|p2p/server.go:681]                         UDP listener up                          addr=[::]:30305
DEBUG[11-01|08:05:44.255|p2p/server.go:845]                         TCP listener up                          addr=[::]:30305
INFO [11-01|08:05:44.256|p2p/enode/localnode.go:317]                New local node record                    seq=1,698,847,544,255 id=33df55c50d324344 ip=127.0.0.1 udp=30305 tcp=30305
INFO [11-01|08:05:44.256|p2p/server.go:704]                         Started P2P networking                   self=enode://cffc90c49f837f6822f9e07a0c4b46138202564a6087464cf6bc2d0bdce3a029dd8ca7444fe032012469fe40dc40804464ec75976176431e6c138538e9b85527@127.0.0.1:30305
DEBUG[11-01|08:05:44.258|rpc/endpoints.go:44]                       IPCs registered                          namespaces=admin,debug,web3,eth,txpool,ethash,miner,net,trace,engine
INFO [11-01|08:05:44.258|node/rpcstack.go:605]                      IPC endpoint opened                      url=/tmp/core-geth-classic-dd2/geth.ipc
INFO [11-01|08:05:44.258|node/node.go:454]                          Generated JWT secret                     path=/tmp/core-geth-classic-dd2/geth/jwtsecret
DEBUG[11-01|08:05:44.258|rpc/websocket.go:90]                       Allowed origin(s) for WS RPC interface [localhost] 
DEBUG[11-01|08:05:44.258|rpc/server.go:166]                         RPC server shutting down 
DEBUG[11-01|08:05:44.258|rpc/server.go:166]                         RPC server shutting down 
ERROR[11-01|08:05:44.258|node/node.go:284]                          Failed to open RPC endpoints             error="listen tcp 127.0.0.1:8551: bind: address already in use"
DEBUG[11-01|08:05:44.259|rpc/server.go:166]                         RPC server shutting down 
INFO [11-01|08:05:44.259|node/rpcstack.go:620]                      IPC endpoint closed                      url=/tmp/core-geth-classic-dd2/geth.ipc
DEBUG[11-01|08:05:44.259|rpc/server.go:166]                         RPC server shutting down 
DEBUG[11-01|08:05:44.259|p2p/server.go:885]                         Read error                               err="accept tcp [::]:30305: use of closed network connection"
DEBUG[11-01|08:05:44.259|p2p/discover/v4_udp.go:530]                UDP read error                           err="read udp [::]:30305: use of closed network connection"
DEBUG[11-01|08:05:44.259|core/state/snapshot/generate.go:113]       Journalled generator progress            progress=0x7e3c9d2181192ecfdf638030d6fe66df68a2f678d3b8bedd77faacc1257cd013
DEBUG[11-01|08:05:44.279|core/state/snapshot/generate.go:113]       Journalled generator progress            progress=0xbba51af3f5e64c8c1b0c3335acc4aa270172e67aa87924bbb06bffd08ef4be4b
DEBUG[11-01|08:05:44.300|core/state/snapshot/generate.go:113]       Journalled generator progress            progress=0xfa63c2c56b30333c79307e088be6e27b37ea2b78c808724e15a8ff2d7b70caaf
DEBUG[11-01|08:05:44.307|core/state/snapshot/generate.go:466]       Regenerated state range                  kind=account prefix=0x61 root=d7f897..0f0544 last=0x count=8893 created=8893 updated=0 untouched=0 deleted=0
DEBUG[11-01|08:05:44.308|core/state/snapshot/generate.go:113]       Journalled generator progress            progress=done
INFO [11-01|08:05:44.314|core/state/snapshot/generate.go:710]       Generated state snapshot                 accounts=8893 slots=0 storage=409.64KiB dangling=0 elapsed=150.971ms
DEBUG[11-01|08:05:46.582|p2p/server_nat.go:128]                     External IP changed                      ip="&{ch:0xc000c8c060 clock:{} timer:0xc000dba0a0 deadline:481833902993453}" interface="UPNP IGDv1-IP1"
Fatal: Error starting protocol stack: listen tcp 127.0.0.1:8551: bind: address already in use

[meowsbits]

Good thought, but on looking at it, they don't have this issue. Their diff on this commit looks like this:

diff --git a/node/node.go b/node/node.go
index 41c9971fe8..e58e0a61bb 100644
--- a/node/node.go
+++ b/node/node.go
@@ -272,8 +272,10 @@ func (n *Node) openEndpoints() error {
        // start RPC endpoints
        err := n.startRPC()
        if err != nil {
+               log.Error("Failed to open RPC endpoints", "error", err)
                n.stopRPC()
                n.server.Stop()
+               return err
        }
        return err
 }

core-geth mishandled this because the error was overwritten by the OpenRPC error, where ethereum/go-ethereum, without an OpenRPC service to start, returns the error as-is.

[ziogaschr]

Great @meowsbits. We had this in our tasks for a long time. :) Thanks