Arabica light node fails to run

[PrasoonPratham]

Celestia Node version

v.0.6.0

OS

Alpine image on Docker

Install tools

I created a docker container using this dockerfile.

FROM alpine:latest
FROM golang:1.19.1-alpine

EXPOSE 26659
 
COPY --from=golang:1.19.1-alpine /usr/local/go/ /usr/local/go/
 
ENV PATH="/usr/local/go/bin:${PATH}"

RUN apk update
RUN apk add curl tar wget clang pkgconfig libressl-dev jq alpine-sdk bash 
RUN rm -rf celestia-node && git clone https://github.com/celestiaorg/celestia-node.git && cd celestia-node && git checkout tags/v0.6.0 && make install && make cel-key && celestia light init

Others

None

Steps to reproduce it

Init arabica

celestia light init --p2p.network arabica
celestia light start --p2p.network arabica

Run the light node using the command in the docs
celestia light start --core.ip https://limani.celestia-devops.dev --core.grpc.port 9090 --gateway --gateway.addr localhost --gateway.port 26659 --p2p.network arabica

Expected result

The light node should run as expected.

Actual result

/go # celestia light start --core.ip https://limani.celestia-devops.dev --core.grpc.port 9090 --gateway --gateway.addr localhost --gateway.port 26659 --p2p.network arabica
2022-12-17T15:02:44.451ZINFObadgerv2@v2.2007.4/levels.go:183All 0 tables opened in 0s

2022-12-17T15:02:44.453ZINFObadgerv2@v2.2007.4/value.go:1158Replaying file id: 0 at offset: 0

2022-12-17T15:02:44.453ZINFObadgerv2@v2.2007.4/value.go:1178Replay took: 28.375µs

2022/12/17 15:02:44 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/lucas-clemente/quic-go/wiki/UDP-Receive-Buffer-Size for details.
2022-12-17T15:02:44.466ZINFOmodule/statestate/keyring.go:69constructed keyring signer{"backend": "test", "path": "/root/.celestia-light-arabica-2/keys", "key name": "my_celes_key", "chain-id": "arabica-2"}
2022-12-17T15:02:44.466ZINFOmodule/headerheader/config.go:54No trusted peers in config, initializing with default bootstrappers as trusted peers
2022-12-17T15:02:44.469ZINFOheader/storestore/store.go:166loaded head{"height": 1, "hash": "04EE55B212745B88F29943D7B9528C415473A211F12EEF6E9333EF32E4DEAF3C"}
2022-12-17T15:02:44.469ZINFOheader/syncsync/sync_head.go:39subjective header expired{"height": 1}
2022-12-17T15:02:49.462ZINFObasichostbasic/natmgr.go:94DiscoverNAT error:no NAT found
2022-12-17T15:02:59.471ZERRORnodenodebuilder/node.go:95starting Light Node: OnStart hook added by go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 failed: context deadline exceeded

github.com/celestiaorg/celestia-node/nodebuilder/header.newInitStore.func1() took 656.792µs from:
github.com/celestiaorg/celestia-node/nodebuilder/header.newInitStore (/go/celestia-node/nodebuilder/header/constructors.go:91)
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 46.291µs from:
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/go/pkg/mod/go.uber.org/fx@v1.18.2/annotated.go:447)
github.com/celestiaorg/celestia-node/nodebuilder/header.newP2PExchange.func1.1() took 28.292µs from:
github.com/celestiaorg/celestia-node/nodebuilder/header.newP2PExchange.func1 (/go/celestia-node/nodebuilder/header/constructors.go:57)
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 22.917µs from:
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/go/pkg/mod/go.uber.org/fx@v1.18.2/annotated.go:447)
github.com/celestiaorg/celestia-node/fraud.(*ProofService).Start-fm() took 22.292µs from:
github.com/celestiaorg/celestia-node/nodebuilder/fraud.newFraudService.func1 (/go/celestia-node/nodebuilder/fraud/constructors.go:31)
github.com/celestiaorg/celestia-node/nodebuilder/p2p.PeerRouting.func1() took 792ns from:
github.com/celestiaorg/celestia-node/nodebuilder/p2p.PeerRouting (/go/celestia-node/nodebuilder/p2p/routing.go:43)

2022-12-17T15:02:59.471ZINFOheader/syncsync/sync_head.go:145new network head{"height": 99533, "hash": "BF133D1DA95EBE7567E29679EA0B0933FAED9C25FEC79C6986936D783303119D"}
2022-12-17T15:02:59.471ZWARNheader/syncsync/sync_head.go:55subjective initialization with an old header{"height": 99533}
2022-12-17T15:02:59.471ZWARNheader/syncsync/sync_head.go:57trusted peer is out of sync
2022-12-17T15:02:59.472ZERRORheader/p2pp2p/exchange.go:107head request to trusted peer failed{"trustedPeer": "12D3KooWHX8xpwg8qkP7kLKmKGtgZvmsopvgxc6Fwtu665QC7G8q", "err": "context deadline exceeded"}
2022-12-17T15:02:59.471ZERRORheader/p2pp2p/exchange.go:107head request to trusted peer failed{"trustedPeer": "12D3KooWHX8xpwg8qkP7kLKmKGtgZvmsopvgxc6Fwtu665QC7G8q", "err": "context deadline exceeded"}
2022-12-17T15:02:59.472ZINFObasichostbasic/basic_host.go:758error resolving /dns4/limani.celestia-devops.dev/tcp/2121/p2p/12D3KooWNpRWxpi1APzV6CnwHvdgNRuTUbMNvg4ta2i1fnqYXR7H: lookup limani.celestia-devops.dev: i/o timeout
2022-12-17T15:02:59.472ZERRORheader/p2pp2p/exchange.go:107head request to trusted peer failed{"trustedPeer": "12D3KooWNpRWxpi1APzV6CnwHvdgNRuTUbMNvg4ta2i1fnqYXR7H", "err": "context deadline exceeded"}
2022-12-17T15:02:59.472ZERRORheader/p2pp2p/exchange.go:107head request to trusted peer failed{"trustedPeer": "12D3KooWHr2wqFAsMXnPzpFsgxmePgXb8BqpkePebwUgLyZc95bd", "err": "context deadline exceeded"}
Error: node: failed to start: OnStart hook added by go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 failed: context deadline exceeded

github.com/celestiaorg/celestia-node/nodebuilder/header.newInitStore.func1() took 656.792µs from:
github.com/celestiaorg/celestia-node/nodebuilder/header.newInitStore (/go/celestia-node/nodebuilder/header/constructors.go:91)
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 46.291µs from:
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/go/pkg/mod/go.uber.org/fx@v1.18.2/annotated.go:447)
github.com/celestiaorg/celestia-node/nodebuilder/header.newP2PExchange.func1.1() took 28.292µs from:
github.com/celestiaorg/celestia-node/nodebuilder/header.newP2PExchange.func1 (/go/celestia-node/nodebuilder/header/constructors.go:57)
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1.1() took 22.917µs from:
go.uber.org/fx.(*lifecycleHookAnnotation).Build.func1 (/go/pkg/mod/go.uber.org/fx@v1.18.2/annotated.go:447)
github.com/celestiaorg/celestia-node/fraud.(*ProofService).Start-fm() took 22.292µs from:
github.com/celestiaorg/celestia-node/nodebuilder/fraud.newFraudService.func1 (/go/celestia-node/nodebuilder/fraud/constructors.go:31)
github.com/celestiaorg/celestia-node/nodebuilder/p2p.PeerRouting.func1() took 792ns from:
github.com/celestiaorg/celestia-node/nodebuilder/p2p.PeerRouting (/go/celestia-node/nodebuilder/p2p/routing.go:43)

Relevant log output

No response

Notes

No response

[dougEfresh]

The default bootstrap p2p nodes are configured here
From my debugging the timeout is 15 seconds. This isn't so much a bug, more so these nodes appear overloaded and do not respond quick enough
At the moment, it is unclear to me how to increase the timeout.

[Bidon15]

Still reproducible in latest main. Thanks for creating this bug @PrasoonPratham and flagging additional info @dougEfresh 🙏
We tried to increase the bootstrappers' hw resources but still got these issues.

[PrasoonPratham]

Still reproducible in latest main. Thanks for creating this bug @PrasoonPratham and flagging additional info @dougEfresh 🙏
We tried to increase the bootstrappers' hw resources but still got these issues.

I moved my dev to mocha for the time being until this is resolved 👍

[Bidon15]

After applying #1603 on top of main with #1608 I see issues like this

2023-01-18T10:19:35.191+0100	ERROR	header/p2p	p2p/session.go:142	requesting headers from peer failed.	{"failed peer": "12D3KooWDpJ3SRJwVZGVJcEENVC7Mi8i7TSWzj7dpY7suL4jzHHc", "err": "header/p2p: failed to open a new stream: context deadline exceeded"}
2023-01-18T10:19:35.191+0100	DEBUG	header/p2p	p2p/session.go:148	Retrying the request from different peer
2023-01-18T10:19:35.191+0100	ERROR	header/p2p	p2p/session.go:142	requesting headers from peer failed.	{"failed peer": "12D3KooWPYUXL5nFh9fngu5oXRaqyqzMmVmLnYHvDKLcV1uBg7NJ", "err": "header/p2p: failed to open a new stream: context deadline exceeded"}

After seeing more logs like above, das module is not progressing forward and just receiving latest network head

[Wondertan]

This is now tracked in #1623