Investigate PeerDAS KZG library stack overflow during block production

[jimmygchen]

Description

We've recently switched from the c-kzg library to the Rust peerdas-kzg library on the das branch (#5941). The purpose for the switch was to:

1. Try out a new alternative to c-kzg;
2. Allow us to merge das branch to unstable without having to update c-kzg to a development version

However we've recently ran into some issues during interop testing after the change, and we're getting stack overflow panics, likely during block production:

Jul 15 10:03:55.007 DEBG Fork choice successfully updated before block production, fork_choice_slot: 60, slot: 60, service: beacon
Jul 15 10:03:55.007 DEBG Not attempting re-org                   reason: head not late, service: beacon
Jul 15 10:03:55.008 ERRO No valid eth1_data votes, `votes_to_consider` empty, outcome: casting `state.eth1_data` as eth1 vote, genesis_time: 1721037115, earliest_block_timestamp: 1721037095, lowest_block_number: 0, service: deposit_contract_rpc
Jul 15 10:03:55.008 DEBG Produced vote for eth1 chain            block_hash: 0xcc93bda48e1227e94e768ee757160974267c72c872f4c89213fbee552bb2ecf2, deposit_count: 0, deposit_root: 0xd70a234731285c6804c2a4f56711ddb8c82c99740f207854891028af34e27e5e, service: deposit_contract_rpc
Jul 15 10:03:55.008 DEBG Issuing engine_getPayload               parent_hash: 0xd32b8265b9e5694d48a42d14175d2692fdb918d305b91d336f2fd2c3167a8df5, timestamp: 1721037835, prev_randao: 0x4c74c85276c06a77410fb641d54224b09045bd03cf19c131ac158b534cd31ad6, suggested_fee_recipient: 0x8943545177806ed17b9f23f0a21ee5948ecaa776, service: exec
Jul 15 10:03:55.011 DEBG Processed HTTP API request              method: GET, path: /eth/v1/node/version, status: 200 OK, elapsed: 86.916µs
Jul 15 10:03:55.103 DEBG Produced block on state                 block_size: 2141, service: beacon
Jul 15 10:03:55.115 DEBG Processed HTTP API request              method: GET, path: /eth/v2/validator/blocks/60, status: 200 OK, elapsed: 108.519167ms
Jul 15 10:03:55.115 DEBG Processed HTTP API request              method: GET, path: /eth/v1/config/spec, status: 200 OK, elapsed: 104.2355ms
Jul 15 10:03:55.117 DEBG Processed HTTP API request              method: GET, path: /eth/v1/node/syncing, status: 200 OK, elapsed: 199.834µs
Jul 15 10:03:55.257 DEBG Signed block received in HTTP API       slot: 60

thread '<unknown>' has overflowed its stack
fatal runtime error: stack overflow

Kurtosis config to reproduce:

participants:
# Supernodes
  - cl_type: prysm
    cl_image: ethpandaops/prysm-beacon-chain:peerdas-initial-sync
    cl_extra_params: [--subscribe-all-subnets]
  - cl_type: lighthouse
    cl_image: ethpandaops/lighthouse:das-devnet-2
    cl_extra_params: [--subscribe-all-data-column-subnets]
# Non supernodes
  - cl_type: prysm
    cl_image: ethpandaops/prysm-beacon-chain:peerdas-initial-sync
  - cl_type: lighthouse
    cl_image: ethpandaops/lighthouse:das-devnet-2
network_params:
  eip7594_fork_epoch: 0
  eip7594_fork_version: "0x50000038"
snooper_enabled: true
global_log_level: debug
additional_services:
  - dora
  - goomy_blob

[michaelsproul]

Looks like a panic inside publish_block (after the block is produced)

[jimmygchen]

Yeah, I think Pawan figured it's most likely something to do with the compute_cells_and_kzg_proofs function (which constructs data column sidecars from blobs), which is invoked from here:

lighthouse/beacon_node/beacon_chain/src/block_verification.rs

Line 740 in ba8126e

build_gossip_verified_data_columns(chain, &block, blobs.map(|(_, blobs)| blobs))?;

[kevaundray]

I think the stackoverflow in this case was a red-herring -- running the LH node in debug mode on the devnet, shows the issue was that rust-embed was, for some, either:

• Not embedding the trusted setup file
• Not correctly parsing the path to the embedded file

The fix, replacing rust-embed with include_str, has been merged into the das branch -- currently waiting for a few folks who reproduced the issue to confirm the issue is fixed on their end. For quick testing, I've uploaded docker images with the fix here kevaundray/lighthouse-eth:das for use in kurtosis

[jimmygchen]

Hi @kevaundray
I've tried the kevaundray/lighthouse-eth:das image and managed to reproduced the error:

thread '<unknown>' has overflowed its stack
fatal runtime error: stack overflow

I can take another look tomorrow too.

[kevaundray]

Hi @kevaundray

I've tried the kevaundray/lighthouse-eth:das image and managed to reproduced the error:

thread '<unknown>' has overflowed its stack

fatal runtime error: stack overflow

I can take another look tomorrow too.

Oh that's surprising -- if you run it in debug mode, then that should give a stacktrace

No rush on this, I can try running it on a different machine x86_64 too and in the meantime, I will update the image to use debug mode

[kevaundray]

To help debugging further, I have created three docker images in debug mode based on the last three commits on the das branch and pasted the output of them in gist files.

Parts of the code I modified

Full backtrace

• Went into lighthouse/src/main.rs and changed:

    if std::env::var("RUST_BACKTRACE").is_err() {
        std::env::set_var("RUST_BACKTRACE", "1");
    }

to

    if std::env::var("RUST_BACKTRACE").is_err() {
        std::env::set_var("RUST_BACKTRACE", "full");
    }

Enabling debug mode

So I could have just modified the Dockerfile and used the dev profile. I went a roundabout way by adding --debug to the MakeFile on cargo install and commenting out the places in the DockerFile and MakeFile that use the profile flag/env variable.

How the images were created

Created a bash script that checked out the following commits from the das branch:

• 04d9eef (chore: update peerdas-kzg library)
• 55a3be7 (Various fixes to custody range sync)
• 018f382 (Avoid retrying same sampling peer that previously failed)

These are in order of newest to oldest.

Then just ran, built and published each of these commits with the commit hash in the tag name.

Docker Images

• kevaundray/lighthouse-eth:das-dbg-04d9eef8a
• kevaundray/lighthouse-eth:das-dbg-55a3be72b
• kevaundray/lighthouse-eth:das-dbg-018f38257

Kurtosis config

# filename: peerdas.yaml
participants:
  # Supernodes
  - cl_type: prysm
    cl_image: ethpandaops/prysm-beacon-chain:peerdas-initial-sync
    cl_extra_params: [--subscribe-all-subnets]
  - cl_type: lighthouse
    cl_image: kevaundray/lighthouse-eth:das-dbg-{COMMIT_HASH}
    cl_extra_params: [--subscribe-all-data-column-subnets]
  # Non supernodes
  - cl_type: prysm
    cl_image: ethpandaops/prysm-beacon-chain:peerdas-initial-sync
  - cl_type: lighthouse
    cl_image: kevaundray/lighthouse-eth:das-dbg-{COMMIT_HASH}
network_params:
  eip7594_fork_epoch: 0
  eip7594_fork_version: "0x50000038"
snooper_enabled: true
global_log_level: debug
additional_services:
  - dora
  - goomy_blob

Running the docker images

Using Kurtosis, I run the following command:

kurtosis run --enclave local-testnet github.com/ethpandaops/ethereum-package --args-file peerdas.yaml --image-download always

The main difference here between the start_local_testnet script is that I have --image-download always -- the default for Kurtosis seems to be to use any cached image on the system locally, regardless of the tag. The docs mention it here

Results

On the 018f38257 branch, I get the rust-embed issue I mentioned before. Contents have been copied into this gist

On the 55a3be72b branch, I get the rust-embed issue also. Contents have been copied into this gist

On the 04d9eef8a branch, I don't get the rust-embed issue, however there seems to be an issue with the vc-lighthouse-geth pairs. This is possibly related to the timeout. Contents have been copied into this gist

Observations

• A lot of time was spent on Execution in progress, when adding a lighthouse node:

[jimmygchen]

A lot of time was spent on Execution in progress, when adding a lighthouse node:

This is kurtosis waiting for Lighthouse to complete the startup process and wait until it's healthy before proceeding.

[jimmygchen]

Yeah I'm not exactly sure what's taking a long time, but I don't think it's to do with KZG as it loads in about 500ms. I'll look into the slow startup issue.

[jimmygchen]

Seems to load pretty quickly on my amd machine. Would be useful to check the Lighthouse container logs of the while "Execution in progress" is happening.

[kevaundray]

Seems to load pretty quickly on my amd machine. Would be useful to check the Lighthouse container logs of the while "Execution in progress" is happening.

For the latest commit (04d9eef) the logs for vc-geth-lighthouse was :

docker logs -f vc-2-geth-lighthouse--66190c11946b4c7980461b123f308375
Jul 18 08:24:39.178 INFO Logging to file                         path: "/validator-keys/keys/logs/validator.log"
Jul 18 08:24:39.274 INFO Lighthouse started                      version: Lighthouse/v5.2.1-04d9eef+
Jul 18 08:24:39.274 INFO Configured for network                  name: custom (/network-configs)
Unable to initialize validator config: Unable to parse proposer_nodes: Unknown argument or group id.  Make sure you are using the argument id and not the short or long flags

Yeah I'm not exactly sure what's taking a long time, but I don't think it's to do with KZG as it loads in about 500ms.

My current hypothesis is that the lengthy periods of time are due to retries. This is because in the error messages by Kurtosis where the service did not start up, it notes the retry attempts:

  Caused by: Unsuccessful ports check for IP '172.16.0.17' and port spec '{privatePortSpec:0x400088c570}', even after '240' retries with '500' milliseconds in between retries. Timeout '2m0s' has been reached

If this is correct, then the long startup times on 55a3be72b and 04d9eef8a would be due to Kurtosis retrying with the rust-embed issue, and the long startup times on 018f38257 would possibly be due to the Kurtosis retrying on the Unable to initialize validator config issue

[kevaundray]

For completeness, I'll add what the Dockerfile and Makefile looks like, that I used to build the docker images:

FROM rust:1.78.0-bullseye AS builder
RUN apt-get update && apt-get -y upgrade && apt-get install -y cmake libclang-dev
COPY . lighthouse
ARG FEATURES
# ARG PROFILE=release
ARG CARGO_USE_GIT_CLI=true
ENV FEATURES $FEATURES
# ENV PROFILE $PROFILE
ENV CARGO_NET_GIT_FETCH_WITH_CLI=$CARGO_USE_GIT_CLI
RUN cd lighthouse && make

FROM ubuntu:22.04
RUN apt-get update && apt-get -y upgrade && apt-get install -y --no-install-recommends \
  libssl-dev \
  ca-certificates \
  && apt-get clean \
  && rm -rf /var/lib/apt/lists/*
COPY --from=builder /usr/local/cargo/bin/lighthouse /usr/local/bin/lighthouse

The main change is that I remove the PROFILE env variable.

The only parts I changed in the Makefile were the install commands:

install:
	cargo install --debug --path lighthouse --force --locked \
		--features "$(FEATURES)" \
		$(CARGO_INSTALL_EXTRA_FLAGS)

# Builds the lcli binary in release (optimized).
install-lcli:
	cargo install --debug --path lcli --force --locked \
		--features "$(FEATURES)" \
		$(CARGO_INSTALL_EXTRA_FLAGS)

The main changes are that I removed the profile flag and added --debug.