fix: resolve max_subscriptions and share sequence errors

[jcstein]

Overview

This is a PR to test out changing back to the P-OPS RPC once they have changed the config to avoid this celestiaorg/celestia-node#2238 and to test out the fix for celestiaorg/celestia-app#1816 once the validator is updated to https://github.com/celestiaorg/celestia-app/releases/tag/v0.13.3

Resolves #19

Checklist

• New and updated code has appropriate documentation
• New and updated code has new and/or updated testing
• Required CI checks are passing
• Visual proof for any user facing features like CLI or documentation updates
• Linked issues closed with keywords

[jcstein]

darn, no luck. I'm still seeing the max_subscriptions error as I don’t think P-OPS config has been updated yet. i imagine the share sequence has 1 shares but needed 0 shares has something to do with why the last safe block is 98

Here are some example snippets of errors:

Instance of share sequence has 1 shares but needed 0 shares:

op-node_1      | t=2023-05-25T16:35:35+0000 lvl=warn msg="unable to retrieve data from da"        origin=0x2aa86dd3b0a3b4e5fa8a4f0e8344d57675720d6c3daf967c510924f3d8a39282:190 err="share sequence has 1 shares but needed 0 shares"

Example of one of the light node panics:

celestia-light-node | 2023/05/25 16:03:35 http: panic serving 172.19.0.5:54942: runtime error: invalid memory address or nil pointer dereference
celestia-light-node | panic({0x2544a40, 0x4c1e190})
celestia-light-node |   /usr/local/go/src/runtime/panic.go:890 +0x263

Unable to retrieve data from DA:

op-node_1      | t=2023-05-25T17:07:20+0000 lvl=warn msg="unable to retrieve data from da"        origin=0xc26bd0184386e88a4b627a75acd0c973c109941286e6714513ef9c4c8b8db9cf:315 err="Get \"http://da:26659/names
paced_data/e8e5f679bf7116cb/height/572941\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"

Max subscriptions error:

op-batcher_1   | t=2023-05-25T16:58:08+0000 lvl=warn msg="unable to publish tx"               err="rpc error: code = Unknown desc = max_subscriptions_per_client 5 reached" data_size=712                [1/135]
op-batcher_1   | t=2023-05-25T16:58:08+0000 lvl=warn msg="Failed to send transaction"         err="rpc error: code = Unknown desc = max_subscriptions_per_client 5 reached"
op-batcher_1   | t=2023-05-25T16:58:08+0000 lvl=warn msg="unable to publish tx to celestia"   service=batcher err="rpc error: code = Unknown desc = max_subscriptions_per_client 5 reached"
op-batcher_1   | t=2023-05-25T16:58:08+0000 lvl=warn msg="unable to publish tx"               err="rpc error: code = Unknown desc = max_subscriptions_per_client 5 reached" data_size=712
op-batcher_1   | t=2023-05-25T16:58:08+0000 lvl=warn msg="Failed to send transaction"         err="rpc error: code = Unknown desc = max_subscriptions_per_client 5 reached"

head request to trusted peer failed:

celestia-light-node | 2023-05-25T17:07:20.009Z  ERROR   header/p2p      p2p/exchange.go:144     head request to trusted peer failed     {"trustedPeer": "12D3KooWBtxdBzToQwnS4ySGpph9PtGmmjEyATkgX3PfhAo4x[0/11]
"err": "header/p2p: failed to open a new stream: context canceled"}

Full logs

Here are the full logs

[jcstein]

This PR resolves max_subscriptions and share sequence errors, as it is intended to.

However, the safe block is stuck roughly 5.5k blocks behind the latest block, likely due to one of these errors:

One occurrence of head request to trusted peer failed (celestiaorg/celestia-node#2241)

celestia-light-node | 2023-05-26T18:56:02.007Z  ERROR   header/p2p      p2p/exchange.go:144     head request to trusted peer failed     {"trustedPeer": "12D3KooWBtxdBzToQwnS4ySGpph9PtGmmjEyATkgX3PfhAo4xmf7", "err": "header/p2p: failed to open a new stream: context canceled"}

One occurrence of context deadline exceeded (Client.Timeout exceeded while awaiting headers (celestiaorg/celestia-node#2250)

op-node_1      | t=2023-05-26T18:56:02+0000 lvl=warn msg="unable to retrieve data from da"        origin=0x4cacf6ed15337c9b85dfb9e23e693e6f793796e23910dcf44c973ae5017cac3f:221 err="Get \"http://da:26659/namespaced_data/e8e5f679bf7116cb/height/581437\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"

checking for safe and latest blocks

root@jcs-optimism:~/optimism# cast block safe --rpc-url http://localhost:9545 --field number
1208
root@jcs-optimism:~/optimism# cast block latest --rpc-url http://localhost:9545 --field number
6835

Full logs are here

https://drive.google.com/file/d/18N0060e6015HzYr1e6GyUi_U-ARuDiiE/view?usp=share_link (i ran out of space on my free tier of Git LFS)

Screenshot of the current errors and checks for old errors:

[jcstein]

note: the docker image is https://github.com/orgs/celestiaorg/packages/container/celestia-node/96549596?tag=e5efcb0 this because the tag didn't exist for v0.10.1

[tuxcanfly]

OK.

[tuxcanfly]

I debugged these logs https://drive.google.com/file/d/18N0060e6015HzYr1e6GyUi_U-ARuDiiE/view?usp=share_link

and found that

�[34mop-node_1 |�[0m t=2023-05-26T18:56:02+0000 lvl=warn msg="unable to retrieve data from da" origin=0x4cacf6ed15337c9b85dfb9e23e693e6f793796e23910dcf44c973ae5017cac3f:221 err="Get \"http://da:26659/namespaced_data/e8e5f679bf7116cb/height/581437\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"

and at the same time proposer stalls:

�[36;1mop-proposer_1 |�[0m t=2023-05-26T18:55:42+0000 lvl=eror msg="proposer unable to get sync status" err="Post \"http://op-node:8545\": context deadline exceeded" �[36;1mop-proposer_1 |�[0m t=2023-05-26T18:55:52+0000 lvl=eror msg="proposer unable to get sync status" err="Post \"http://op-node:8545\": context deadline exceeded" �[36;1mop-proposer_1 |�[0m t=2023-05-26T18:56:02+0000 lvl=info msg="proposer submission interval has not elapsed" currentBlockNumber=1208 nextBlockNumber=1320

I'm wondering if this was running without the extended proposer timeout fix #50

61518e8

[jcstein]

it was running with fixes from #50 based on L128 of docker-compose-testnet.yml and L11 of devnetL1.json. Also, based on the commit history of this branch

[tuxcanfly]

OK, will need to look at timestamps, maybe it was running past even the 180s timeout? 🤔

[tuxcanfly]

Some more context, at the same time, node was throwing head request to trusted peer failed:

�[36mcelestia-light-node |�[0m 2023-05-26T18:56:02.007Z ERROR header/p2p p2p/exchange.go:144 head request to trusted peer failed {"trustedPeer": "12D3KooWBtxdBzToQwnS4ySGpph9PtGmmjEyATkgX3PfhAo4xmf7", "err": "header/p2p: failed to open a new stream: context canceled"}