search

celestiaorg / celestia-node

Celestia Data Availability Nodes
Apache License 2.0
922 stars 922 forks source link

Celestia Light node: failed to get recent head, returning current subjective #3621

Open CroutonDigital opened 1 month ago

CroutonDigital commented 1 month ago

Celestia Node version

Semantic version: v0.14.1, Commit: 6549873516889aebcb787c4e9f2ae3b3258c386a

OS

Debian GNU/Linux

Install tools

docker

Others

No response

Steps to reproduce it

We install celestia node consensus and celestia light node. Celestia Light node point to Celestia consensus node. But on light node we got error: sync/sync_head.go:46 failed to get recent head, returning current subjective {"sbjHead": 2418531, "err": "header: not found"} p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWLvmEfNFBzk7KSRK4JxsHxZybdZs9FA5ke855Xi4jScDy", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}

it seems light node can't get info from peers.

How to fix that?

Expected result

no logs with errors

Actual result

celestia-testnet-light-node  | 2024-08-05T09:22:09.023Z INFO    header/store    store/store.go:367  new head    {"height": 2418532, "hash": "144DDC0E38A732F40F2A1D5F2F23511D88AE6C234535F9E3176C9022BD645291"}
celestia-testnet-light-node  | 2024-08-05T09:22:09.173Z INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2418532, "hash": "144DDC0E38A732F40F2A1D5F2F23511D88AE6C234535F9E3176C9022BD645291", "square width": 64, "data root": "6714B9564D201545145BDBA14508B70AEE1AAEE5FB1D22D8B24362F1D681EF7B", "finished (s)": 0.14972966}
celestia-testnet-light-node  | 2024-08-05T09:22:10.134Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWCmF6WXHjN9Qixzz9sz5aH4NjQ19r7tSCj2i6SbCAupRe", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:10.134Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2418531, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-05T09:22:18.399Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWLvmEfNFBzk7KSRK4JxsHxZybdZs9FA5ke855Xi4jScDy", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:18.399Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWFxEPzWYurL2YEohTGbxukdNjjoYwU9ziQGSC85wK167Z", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:18.399Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWRXX1ntM6TcauLLZYqipZWp4BKRbzDt8ec5sRBMmhPq6k", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:18.400Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2418532, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-05T09:22:18.482Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWQR1LtWjNPynuwWFJF8aDxLpLyaMwMuVvsBeF7eKYENac", "err": "header/p2p: failed to open a new stream: failed to negotiate protocol: protocols not supported: [/mocha-4/header-ex/v0.0.3]"}
celestia-testnet-light-node  | 2024-08-05T09:22:19.968Z INFO    header/store    store/store.go:367  new head    {"height": 2418533, "hash": "51E16BC4462AC6A7C40F5481FE1B0AEF3690AA35F3C3894D166E3A955FB683EF"}
celestia-testnet-light-node  | 2024-08-05T09:22:20.104Z INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2418533, "hash": "51E16BC4462AC6A7C40F5481FE1B0AEF3690AA35F3C3894D166E3A955FB683EF", "square width": 32, "data root": "D7D473CDCB3946110855F30C21403EE12A34270F320FA9974A5BB678C19DDCC1", "finished (s)": 0.136213822}
celestia-testnet-light-node  | 2024-08-05T09:22:20.200Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWJMGLncYpuxbD6NLRfttXoActD2xvuvZxdeWdbzH4kAhA", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:20.200Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2418532, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-05T09:22:30.886Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWN4mNJqLewrmuJbqsfCJHKYKDRXAHDReaFwMapqZgfQZz", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:30.886Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWEAiBw6MF1GDyG2ksfDFZ3V259w7k4GzyMFReSoq3pGNk", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
celestia-testnet-light-node  | 2024-08-05T09:22:30.886Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2418533, "err": "header: not found"}

Relevant log output

No response

Notes

No response

Wondertan commented 1 month ago

Is this behavior consistent upon restarts?

CroutonDigital commented 1 month ago

Yes, when restart celestia light node logs is same.

Wondertan commented 1 month ago

Is syncing continues?

CroutonDigital commented 1 month ago

Yes, but can't get additional header info

Wondertan commented 1 month ago

WDYM by "additional header info"?

CroutonDigital commented 1 month ago

celestia-testnet-light-node | 2024-08-05T09:22:20.200Z WARN header/sync sync/sync_head.go:46 failed to get recent head, returning current subjective {"sbjHead": 2418532, "err": "header: not found"}

@Wondertan what that mean, may be you know?

CroutonDigital commented 1 month ago

When I request celestia node ip sync status is ok: 

curl http://<celestia node ip>:27657/status | jq '.result.sync_info'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1085  100  1085    0     0   180k      0 --:--:-- --:--:-- --:--:--  211k
{
  "latest_block_hash": "4171E13E060F4A5EE1D65A1C640CD4FEDB57D3410041C17FEF74645729AD6FFD",
  "latest_app_hash": "A362C791DF80693127AD93473BE63DFDBAFFB0FFAD1C3AB058904CD4CCC0B526",
  "latest_block_height": "2431345",
  "latest_block_time": "2024-08-07T04:49:52.863134162Z",
  "earliest_block_hash": "B93BBE20A0FBFDF955811B6420F8433904664D45DB4BF51022BE4200C1A1680D",
  "earliest_app_hash": "E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855",
  "earliest_block_height": "1",
  "earliest_block_time": "2023-09-06T03:15:51.510579711Z",
  "catching_up": false
}
CroutonDigital commented 1 month ago

Now I switch Log level on celestia light node: 

celestia-testnet-light-node  | 2024-08-07T05:12:03.628Z DEBUG   shrex/peer-manager  peers/manager.go:378    got hash from shrex-sub {"peer": "12D3KooWGU65f1W9wv5nqRVfhkGqgfQp781Q3cFt68tmGzPdcnFo", "hash": "BD8541975D21332C31764163972D40FD8141F2C2D3D32A42341DDCAD722729BE"}
celestia-testnet-light-node  | 2024-08-07T05:12:03.860Z DEBUG   routedhost  routed/routed.go:119    failed to find more peer addresses 12D3KooWCvE6XUD1Q1JMmPdczocEc9sCCN5tgbaWYJxRR6g5rcLq: routing: not found
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.057Z DEBUG   share/discovery discovery/discovery.go:273  reached soft peer limit, skipping discovery {"topic": "archival", "size": 5}
celestia-testnet-light-node  | 2024-08-07T05:12:04.057Z DEBUG   share/discovery discovery/discovery.go:273  reached soft peer limit, skipping discovery {"topic": "full", "size": 5}
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   routedhost  routed/routed.go:119    failed to find more peer addresses 12D3KooWMZkMdP7DMfRXNJrgjHktqQStKgC6woY9biR6HrH9EVZq: routing: not found
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:849   writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:856   Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:885   Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z DEBUG   badger4 v4@v4.2.1-0.20240106094458-1c417aa3799c/db.go:889   2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:123 requesting head
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:156 requesting head from tracked peers  {"amount": 4}
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:386 requesting peer {"peer": "12D3KooWHofp1zjaGkEibn85LmPuKQoq9fTHxZU9JZdB7stKj2Rh"}
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:386 requesting peer {"peer": "12D3KooWS328pJu6Y2eTWFNjQ7dBc5ExNzyuuBozU2ovdmbrz6ri"}
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:386 requesting peer {"peer": "12D3KooWH4wjJvFMwRsxpF78X4BBVpXswNFTM3QbAcashftUFf9u"}
celestia-testnet-light-node  | 2024-08-07T05:12:04.338Z DEBUG   header/p2p  p2p/exchange.go:386 requesting peer {"peer": "12D3KooWCfiLMAcL6X5DxX6o9NR2aub2vkVofGF8ZRdobeAMixBH"}
celestia-testnet-light-node  | 2024-08-07T05:12:04.438Z DEBUG   header/p2p  p2p/exchange.go:199 verifying head received from tracked peer   {"tracked peer": "12D3KooWCfiLMAcL6X5DxX6o9NR2aub2vkVofGF8ZRdobeAMixBH", "height": 2431453, "err": "header verification failed: known header: '2431453' <= current '2431453'"}
celestia-testnet-light-node  | 2024-08-07T05:12:04.467Z DEBUG   header/p2p  p2p/exchange.go:199 verifying head received from tracked peer   {"tracked peer": "12D3KooWH4wjJvFMwRsxpF78X4BBVpXswNFTM3QbAcashftUFf9u", "height": 2431453, "err": "header verification failed: known header: '2431453' <= current '2431453'"}

"err": "header verification failed: known header: '2431453' <= current '2431453'"

What does that mean?

CroutonDigital commented 1 month ago

It seems p2p port is closed. Now I open port 2121 and I can see other logs

CroutonDigital commented 1 month ago

Some log is fixed:

I upgrade to v0.15.0 and I see: 

celestia-testnet-light-node  | 2024-08-07T17:59:40.415Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2435244, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-07T17:59:42.461Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2435244, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-07T17:59:43.805Z INFO    header/store    store/store.go:367  new head    {"height": 2435245, "hash": "3084775FEF68B71E9F62946912BBD03739EDA76F2D8F8C7C33F4F93BF5E68039"}
celestia-testnet-light-node  | 2024-08-07T17:59:44.187Z INFO    das das/worker.go:161   sampled header  {"type": "recent", "height": 2435245, "hash": "3084775FEF68B71E9F62946912BBD03739EDA76F2D8F8C7C33F4F93BF5E68039", "square width": 32, "data root": "906E0F99F88127222BC30A7B6F7F2C8BEE38E7EE7693629ED8A43B84A4AA35FE", "finished (s)": 0.382040592}
celestia-testnet-light-node  | 2024-08-07T17:59:45.273Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWMuZrMr4Yhr7YFmBoEpTFLe4egPKLoMyDWJoQWrH24K4a", "err": "deadline exceeded"}
celestia-testnet-light-node  | 2024-08-07T17:59:45.273Z WARN    header/sync sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2435244, "err": "header: not found"}
celestia-testnet-light-node  | 2024-08-07T17:59:52.617Z INFO    pidstore    pidstore/pidstore.go:84 Persisted peers successfully    {"amount": 70}
celestia-testnet-light-node  | 2024-08-07T17:59:54.034Z ERROR   header/p2p  p2p/exchange.go:179 head request to peer failed {"peer": "12D3KooWNrnHyKpWTMZHiJvtAQGfGfdc8ZNeugJSmfGvn4DPgJXj", "err": "header/p2p: failed to open a new stream: failed to negotiate protocol: protocols not supported: [/mocha-4/header-ex/v0.0.3]"}
Wondertan commented 1 month ago

Whats the output of 'celestia header sync-state'

CroutonDigital commented 1 month ago

@Wondertan 

root@f9a3e5327274:/# celestia header sync-state --url http://localhost:27658 --node.store ~/.celestia-light/
{
  "result": {
    "id": 1,
    "height": 2438990,
    "from_height": 2435378,
    "to_height": 2435492,
    "from_hash": "9C7A9D0B8D9679323E466795A10D783023D26F8F8CED9508BB95464D87E63663",
    "to_hash": "EA87F2A1C98284CE99352C9980BFF9B5F2C7EA5130AF8C9702D714634271CCC6",
    "start": "2024-08-07T18:49:53.759184984Z",
    "end": "2024-08-07T18:50:02.327218026Z"
  }
}
Wondertan commented 1 month ago

According to this, syncing is in progress.

maximdogonov commented 1 month ago

@Wondertan Worked correctly or syncing can not to be done?

maximdogonov commented 1 month ago

1Minute between "start": "2024-08-07T18:49:53.759184984Z", "end": "2024-08-07T18:50:02.327218026Z" time

maximdogonov commented 1 month ago

I mean 7 sec ))))

MichaelLLC commented 1 month ago

I have encountered a similar problem on both the testnet and mainnet. I previously ran the light node using the following commands:

celestia light start --p2p.network mocha --node.store /root/.celestia-light --log.level info
celestia light start --p2p.network celestia --node.store /root/.celestia-light --log.level info

I attempted to change the RPC endpoint using the parameter --core.ip, but the errors persist.

MichaelLLC commented 1 month ago

When I updated the node to version 0.14.1, new errors occurred "head request to peer failed"

2024-08-08T20:08:18.011Z        ERROR   header/p2p      p2p/exchange.go:179     head request to peer failed     {"peer": "12D3KooWNB4oHUnQTnY5ZXZic5vAhf7GAPRCZoBK97TGYvS9Rhf1", "err": "header/p2p: failed to open a new stream: identify failed to complete: context deadline exceeded"}
2024-08-08T20:08:18.011Z        WARN    header/sync     sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2072713, "err": "header: not found"}
2024-08-08T20:08:26.332Z        WARN    header/sync     sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2072714, "err": "header: not found"}
2024-08-08T20:08:28.931Z        INFO    header/store    store/store.go:367      new head        {"height": 2072715, "hash": "2431A51E90213A18BC933A142852C65EA285AE4CA90EC9056ADDD1C73736E1A6"}
2024-08-08T20:08:29.074Z        INFO    das     das/worker.go:161       sampled header  {"type": "recent", "height": 2072715, "hash": "2431A51E90213A18BC933A142852C65EA285AE4CA90EC9056ADDD1C73736E1A6", "square width": 64, "data root": "FE8BB98DCDFD2F0EC095C145F2D2D2A9A3DD8273E5C89D9D21C63D08E2825738", "finished (s)": 0.142978884}
2024-08-08T20:08:29.623Z        ERROR   header/p2p      p2p/exchange.go:179     head request to peer failed     {"peer": "12D3KooWKZCMcwGCYbL18iuw3YVpAZoyb1VBGbx9Kapsjw3soZgr", "err": "header/p2p: failed to open a new stream: failed to open stream: context deadline exceeded"}
2024-08-08T20:08:29.623Z        ERROR   header/p2p      p2p/exchange.go:179     head request to peer failed     {"peer": "12D3KooWFAuzVdxkYwugdZbrJDxvZs5BnbriyiUBtYrFkvwrw8WG", "err": "header/p2p: failed to open a new stream: identify failed to complete: context deadline exceeded"}
2024-08-08T20:08:29.623Z        WARN    header/sync     sync/sync_head.go:46    failed to get recent head, returning current subjective {"sbjHead": 2072714, "err": "header: not found"}