search

celestiaorg / celestia-node

Celestia Data Availability Nodes
Apache License 2.0
929 stars 925 forks source link

bug: light node has no peers, even with `GODEBUG="asynctimerchan=1" celestia light start --core.ip rpc-mocha.pops.one --p2p.network mocha` workaround #3771

Closed jcstein closed 1 month ago

jcstein commented 1 month ago

Celestia Node version

v0.16.0

OS

macos

Install tools

docs

Others

No response

Steps to reproduce it

from message in discord after trying the workaround:

  1. GODEBUG="asynctimerchan=1" celestia light start --core.ip rpc-mocha.pops.one --p2p.network mocha my logs are flooded with: 
    2024-09-24T13:13:24.350-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.350-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.350-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.350-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.351-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.351-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6562, "want-count": 1}
2024-09-24T13:13:24.351-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6563, "want-count": 1}
2024-09-24T13:13:24.351-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6563, "want-count": 1}
2024-09-24T13:13:24.351-0400    INFO    bitswap/session session/session.go:477  No peers - broadcasting {"session": 6563, "want-count": 1}

Expected result

finds peers, no flood of "no peers" INFO logs

Actual result

no peers x ♾️

Relevant log output

No response

Is the node "stuck"? Has it stopped syncing?

No response

Notes

No response

distractedm1nd commented 1 month ago

+1

jcstein commented 1 month ago

logs are much cleaner on v0.16.1-mocha

celestia light start --core.ip rpc-mocha.pops.one --p2p.network mocha --rpc.skip-auth

2024-09-24T13:33:06.031-0400    WARN    rpc rpc/flags.go:56 RPC authentication is disabled
2024-09-24T13:33:06.033-0400    INFO    node    nodebuilder/module.go:27    Accessing keyring...
2024-09-24T13:33:06.230-0400    INFO    badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/levels.go:171   All 776 tables opened in 179ms

2024-09-24T13:33:06.237-0400    INFO    badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/discard.go:66   Discard stats nextEmptySlot: 101

2024-09-24T13:33:06.237-0400    INFO    badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:368   Set nextTxnTs to 37090564
2024-09-24T13:33:07.072-0400    INFO    module/p2p  p2p/tls.go:54   using a default ws transport
2024-09-24T13:33:07.088-0400    INFO    pidstore    pidstore/pidstore.go:67 Loaded peers from disk  {"amount": 72}
2024-09-24T13:33:07.088-0400    INFO    module/header   header/config.go:66 No trusted peers in config, initializing with default bootstrappers as trusted peers
2024-09-24T13:33:07.091-0400    INFO    header/p2p  p2p/exchange.go:99  client: starting client {"protocol ID": "/mocha-4/header-ex/v0.0.3"}
2024-09-24T13:33:07.091-0400    INFO    pidstore    pidstore/pidstore.go:67 Loaded peers from disk  {"amount": 72}
2024-09-24T13:33:07.092-0400    INFO    header/store    store/store.go:193  loaded head {"height": 2775826, "hash": "7BBFB409C260851DA1CC7D0E0F4AEC30B75E46397B9940C34B8EAEDC8C5DC9CB"}
2024-09-24T13:33:07.092-0400    INFO    header/p2p  p2p/subscriber.go:80    joining topic   {"topic ID": "/mocha-4/header-sub/v0.0.1"}
2024-09-24T13:33:07.092-0400    INFO    fraudserv   fraudserv/helpers.go:29 joining topic   {"id": "/mocha-4/fraud-sub/badencodingv0.1/v0.0.1"}
2024-09-24T13:33:07.092-0400    INFO    fraudserv   fraudserv/service.go:114    starting fraud proof service    {"protocol ID": "/mocha-4/fraud/v0.0.1"}
2024-09-24T13:33:09.978-0400    INFO    share/discovery discovery/discovery.go:123  started discovery   {"topic": "full"}
2024-09-24T13:33:09.978-0400    INFO    share/discovery discovery/discovery.go:123  started discovery   {"topic": "archival"}
2024-09-24T13:33:10.113-0400    WARN    header/p2p  p2p/exchange.go:199 verifying head received from tracked peer   {"tracked peer": "12D3KooWGRbM76NQeESuiXsZzSjQkjNRnHU3SsDnJrtsY8Qspacd", "height": 2390199, "err": "header verification failed: unordered headers: timestamp '2024-08-01T09:43:24Z' < current '2024-09-24T17:29:58Z'"}
2024-09-24T13:33:10.205-0400    INFO    header/sync sync/sync_head.go:140   new network head    {"height": 2775840, "hash": "0766B834E7C2DB8018DF73B8DF95DD55E143DF6EBF442B8BF4FC00A214D00FBB"}
2024-09-24T13:33:10.206-0400    INFO    header/p2p  p2p/server.go:77    server: listening for inbound header requests   {"protocol ID": "/mocha-4/header-ex/v0.0.3"}
2024-09-24T13:33:10.205-0400    INFO    header/sync sync/sync.go:216    syncing headers {"from": 2775827, "to": 2775840}
2024-09-24T13:33:10.206-0400    INFO    das das/daser.go:113    starting DASer from checkpoint: SampleFrom: 2775827, NetworkHead: 2775826
2024-09-24T13:33:10.206-0400    INFO    rpc rpc/server.go:92    server started  {"listening on": "127.0.0.1:26658"}
2024-09-24T13:33:10.206-0400    INFO    node    nodebuilder/node.go:119 

/_____/  /_____/  /_____/  /_____/  /_____/

Started celestia DA node
node version:   v0.16.1-arabica
node type:  light
network:    mocha-4

/_____/  /_____/  /_____/  /_____/  /_____/

The p2p host is listening on:
*  /ip4/10.0.0.172/tcp/2121/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/10.0.0.172/udp/2121/webrtc-direct/certhash/uEiA-OlajuzSdghF1NLuay_RezRjoNYSYtPSDYupXx0Dg-g/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/10.0.0.172/udp/2121/quic-v1/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/10.0.0.172/udp/2121/quic-v1/webtransport/certhash/uEiCtTHxWPn56JJmiyU_50BenOy2R3yUOLvQsJ3vtTJJEjw/certhash/uEiBlnQOe0AFrXLc5SEfxhb81hMR1yx2uLIGfVJ6r_ksymQ/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/71.200.65.106/tcp/2121/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/71.200.65.106/udp/2121/webrtc-direct/certhash/uEiA-OlajuzSdghF1NLuay_RezRjoNYSYtPSDYupXx0Dg-g/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/71.200.65.106/udp/2121/quic-v1/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/71.200.65.106/udp/2121/quic-v1/webtransport/certhash/uEiCtTHxWPn56JJmiyU_50BenOy2R3yUOLvQsJ3vtTJJEjw/certhash/uEiBlnQOe0AFrXLc5SEfxhb81hMR1yx2uLIGfVJ6r_ksymQ/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/127.0.0.1/udp/2121/webrtc-direct/certhash/uEiA-OlajuzSdghF1NLuay_RezRjoNYSYtPSDYupXx0Dg-g/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip4/127.0.0.1/udp/2121/quic-v1/webtransport/certhash/uEiCtTHxWPn56JJmiyU_50BenOy2R3yUOLvQsJ3vtTJJEjw/certhash/uEiBlnQOe0AFrXLc5SEfxhb81hMR1yx2uLIGfVJ6r_ksymQ/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/::1/tcp/2121/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/::1/udp/2121/webrtc-direct/certhash/uEiA-OlajuzSdghF1NLuay_RezRjoNYSYtPSDYupXx0Dg-g/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/::1/udp/2121/quic-v1/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/::1/udp/2121/quic-v1/webtransport/certhash/uEiCtTHxWPn56JJmiyU_50BenOy2R3yUOLvQsJ3vtTJJEjw/certhash/uEiBlnQOe0AFrXLc5SEfxhb81hMR1yx2uLIGfVJ6r_ksymQ/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/2601:152:c00:2e40:6d9e:4163:d08f:1c57/tcp/2121/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/2601:152:c00:2e40:6d9e:4163:d08f:1c57/udp/2121/webrtc-direct/certhash/uEiA-OlajuzSdghF1NLuay_RezRjoNYSYtPSDYupXx0Dg-g/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/2601:152:c00:2e40:6d9e:4163:d08f:1c57/udp/2121/quic-v1/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE
*  /ip6/2601:152:c00:2e40:6d9e:4163:d08f:1c57/udp/2121/quic-v1/webtransport/certhash/uEiCtTHxWPn56JJmiyU_50BenOy2R3yUOLvQsJ3vtTJJEjw/certhash/uEiBlnQOe0AFrXLc5SEfxhb81hMR1yx2uLIGfVJ6r_ksymQ/p2p/12D3KooWGxxQJZ2vQhYyDxFsVe17yAU5LsVF6iaVtdfNoBgDKCjE

2024-09-24T13:33:10.334-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775839, "hash": "0C57509DCDFB5A6A7104BB9B0195B8BDEE9202DAE79480ACF1AD1A13B7978AB6"}
2024-09-24T13:33:10.334-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775840, "hash": "0766B834E7C2DB8018DF73B8DF95DD55E143DF6EBF442B8BF4FC00A214D00FBB"}
2024-09-24T13:33:10.334-0400    INFO    header/sync sync/sync.go:234    finished syncing headers    {"from": 2775827, "to": 2775840, "elapsed time": 0.12811325}
2024-09-24T13:33:11.636-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775841, "hash": "8A07032403B15E9A0B039CE3A30A7994971C38923CB73577CE39575B3179309A"}
2024-09-24T13:33:11.880-0400    INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2775841, "hash": "8A07032403B15E9A0B039CE3A30A7994971C38923CB73577CE39575B3179309A", "EDS square width": 64, "data root": "FB72B5319E4A2A683CC57AE15D64B9597C236C43D54D76B91EF34B3B733F0E0D", "finished (s)": 0.243876459}
2024-09-24T13:33:16.007-0400    WARN    header/sync sync/sync_head.go:187   invalid network header  {"height_of_invalid": 2775838, "hash_of_invalid": "0DC5E15A22219C43BDDF5B1D09FA23826AC2A18510995EA9C6846961F545636A", "height_of_subjective": 2775841, "hash_of_subjective": "8A07032403B15E9A0B039CE3A30A7994971C38923CB73577CE39575B3179309A", "reason": "unordered headers: timestamp '2024-09-24T17:32:23Z' < current '2024-09-24T17:32:59Z'"}
2024-09-24T13:33:16.521-0400    INFO    das das/worker.go:94    finished sampling headers   {"type": "catchup", "from": 2775827, "to": 2775841, "errors": 0, "# of headers skipped as outside of sampling window": 0, "finished (s)": 4.884974417}
2024-09-24T13:33:18.430-0400    WARN    header/sync sync/sync_head.go:187   invalid network header  {"height_of_invalid": 2775837, "hash_of_invalid": "3E7AD8E6025D19A600952E30AAAEA28D62C0A4CCC0EE0349E23C07393F460FAA", "height_of_subjective": 2775841, "hash_of_subjective": "8A07032403B15E9A0B039CE3A30A7994971C38923CB73577CE39575B3179309A", "reason": "unordered headers: timestamp '2024-09-24T17:32:10Z' < current '2024-09-24T17:32:59Z'"}
2024-09-24T13:33:23.432-0400    WARN    header/sync sync/sync_head.go:187   invalid network header  {"height_of_invalid": 2775839, "hash_of_invalid": "0C57509DCDFB5A6A7104BB9B0195B8BDEE9202DAE79480ACF1AD1A13B7978AB6", "height_of_subjective": 2775841, "hash_of_subjective": "8A07032403B15E9A0B039CE3A30A7994971C38923CB73577CE39575B3179309A", "reason": "unordered headers: timestamp '2024-09-24T17:32:35Z' < current '2024-09-24T17:32:59Z'"}
2024-09-24T13:33:23.839-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775842, "hash": "70E45482DFB4E2BA48FE7B24770A596FCBFA619215FA2FBF3528ACDB4868A571"}
2024-09-24T13:33:24.080-0400    INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2775842, "hash": "70E45482DFB4E2BA48FE7B24770A596FCBFA619215FA2FBF3528ACDB4868A571", "EDS square width": 64, "data root": "E3DA02CF0553876A1EC2C40EC28832C583DBA332F477D62AD81DEEC86E5E58C8", "finished (s)": 0.240353667}
2024-09-24T13:33:26.439-0400    INFO    share/discovery discovery/discovery.go:325  discovered wanted peers {"topic": "full", "amount": 5}
2024-09-24T13:33:26.439-0400    INFO    share/discovery discovery/discovery.go:325  discovered wanted peers {"topic": "archival", "amount": 5}
2024-09-24T13:33:34.751-0400    INFO    canonical-log   swarm/swarm_listen.go:168   CANONICAL_PEER_STATUS: peer=12D3KooWHtbD64VFTbWiiUAKjW8frmuSgcuZzPto4ykcQqXEgJnB addr=/ip4/65.109.143.239/udp/2121/quic-v1 sample_rate=100 connection_status="established" dir="inbound"
2024-09-24T13:33:35.894-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775843, "hash": "37F42AD92AAD9D76357AEBB96BF45A2E27EFF3963E7AD4BE3C70281ED6B2EEF1"}
2024-09-24T13:33:36.729-0400    INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2775843, "hash": "37F42AD92AAD9D76357AEBB96BF45A2E27EFF3963E7AD4BE3C70281ED6B2EEF1", "EDS square width": 64, "data root": "994AA9D5B156CCBA21BF636CA09097E8EAE6D712F26C8040CFA9C628A40E0E4E", "finished (s)": 0.835762167}
2024-09-24T13:33:41.391-0400    INFO    canonical-log   swarm/swarm_listen.go:168   CANONICAL_PEER_STATUS: peer=12D3KooWLqfDsx8sshqiXVcizbX4gQbtfjRFxHrk9jWXdbesPcxK addr=/ip4/3.74.32.154/udp/2121/quic-v1 sample_rate=100 connection_status="established" dir="inbound"
2024-09-24T13:33:47.890-0400    INFO    header/store    store/store.go:367  new head    {"height": 2775844, "hash": "39939161C3876BEB067837A8FB70EC4EF35A6DB2793FCD890F637CAF9A9A1A96"}
2024-09-24T13:33:48.631-0400    INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2775844, "hash": "39939161C3876BEB067837A8FB70EC4EF35A6DB2793FCD890F637CAF9A9A1A96", "EDS square width": 64, "data root": "6EDF8FCED0F93E1DE94D78D7F5B1F44E2E760CA582A13747E2032087D6260FFD", "finished (s)": 0.73934325}
^C2024-09-24T13:33:53.160-0400  INFO    rpc rpc/server.go:110   server stopped
2024-09-24T13:33:53.160-0400    INFO    das das/store.go:60 stored checkpoint to disk: SampleFrom: 2775845, NetworkHead: 2775844
2024-09-24T13:33:53.160-0400    INFO    das das/store.go:60 stored checkpoint to disk: SampleFrom: 2775845, NetworkHead: 2775844
2024-09-24T13:33:53.160-0400    INFO    header/p2p  p2p/server.go:86    server: stopping server
2024-09-24T13:33:53.171-0400    INFO    pidstore    pidstore/pidstore.go:84 Persisted peers successfully    {"amount": 86}
2024-09-24T13:33:53.193-0400    INFO    badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:546   Lifetime L0 stalled for: 0s

2024-09-24T13:33:54.406-0400    INFO    badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:625   
Level 0 [ ]: NumTables: 00. Size: 0 B of 0 B. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 16 MiB
Level 1 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 2 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 3 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB
Level 4 [ ]: NumTables: 00. Size: 0 B of 78 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 4.0 MiB
Level 5 [B]: NumTables: 111. Size: 772 MiB of 779 MiB. Score: 0.00->0.00 StaleData: 84 KiB Target FileSize: 8.0 MiB
Level 6 [ ]: NumTables: 667. Size: 7.6 GiB of 7.6 GiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 16 MiB
Level Done