Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
CroutonDigital opened this issue Aug 5, 2024 · 18 comments
Open

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

CroutonDigital opened this issue Aug 5, 2024 · 18 comments
Labels
bug Something isn't working external Issues created by non node team members

Comments

@CroutonDigital
Copy link

Celestia Node version

Semantic version: v0.14.1, Commit: 6549873

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
@CroutonDigital CroutonDigital added the bug Something isn't working label Aug 5, 2024
@github-actions github-actions bot added the external Issues created by non node team members label Aug 5, 2024
@Wondertan
Copy link
Member

Is this behavior consistent upon restarts?

@CroutonDigital
Copy link
Author

Yes, when restart celestia light node logs is same.

@Wondertan
Copy link
Member

Is syncing continues?

@CroutonDigital
Copy link
Author

CroutonDigital commented Aug 6, 2024 •
edited
Loading

Yes, but can't get additional header info

@Wondertan
Copy link
Member

WDYM by "additional header info"?

@CroutonDigital
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:889	2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:889	2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:03.861Z	DEBUG	badger4	[email protected]/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	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:889	2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.140Z	DEBUG	badger4	[email protected]/db.go:889	2 entries written
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z	DEBUG	badger4	[email protected]/db.go:849	writeRequests called. Writing to value log
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z	DEBUG	badger4	[email protected]/db.go:856	Writing to memtable
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z	DEBUG	badger4	[email protected]/db.go:885	Sending updates to subscribers
celestia-testnet-light-node  | 2024-08-07T05:12:04.141Z	DEBUG	badger4	[email protected]/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
Copy link
Author

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

@CroutonDigital
Copy link
Author

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
Copy link
Member

Whats the output of 'celestia header sync-state'

@CroutonDigital
Copy link
Author

@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
Copy link
Member

According to this, syncing is in progress.

@maximdogonov
Copy link

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

@maximdogonov
Copy link

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

@maximdogonov
Copy link

I mean 7 sec ))))

@MichaelLLC
Copy link

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
Copy link

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"}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working external Issues created by non node team members
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@maximdogonov @Wondertan @CroutonDigital @MichaelLLC