lodestar icon indicating copy to clipboard operation
lodestar copied to clipboard
verified publisher icon ChainSafe

unexpected end of input

Open twoeths opened this issue 7 months ago • 2 comments

Describe the bug

got this issue since we upgrade libp2p #7359

Jun-05 00:00:02.814[network]         ^[[34mdebug^[[39m: Error setting agentVersion for the peer peerId=16Uiu2HAm2KkyPc68YFS3NF7FgsuX7aen5AHA7eppM2SZH8icmom7 - unexpected end of input
Error: unexpected end of input
    at Object.read (file:///usr/src/lodestar/node_modules/it-length-prefixed-stream/node_modules/it-byte-stream/dist/src/index.js:86:31)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Object.read (file:///usr/src/lodestar/node_modules/it-length-prefixed-stream/dist/src/index.js:45:37)
    at async read (file:///usr/src/lodestar/node_modules/@libp2p/multistream-select/dist/src/multistream.js:22:17)
    at async Module.readString (file:///usr/src/lodestar/node_modules/@libp2p/multistream-select/dist/src/multistream.js:33:17)
    at async Module.select (file:///usr/src/lodestar/node_modules/@libp2p/multistream-select/dist/src/select.js:72:20)
    at async ConnectionImpl.newStream [as _newStream] (file:///usr/src/lodestar/node_modules/libp2p/dist/src/upgrader.js:331:50)
    at async ConnectionImpl.newStream (file:///usr/src/lodestar/node_modules/libp2p/dist/src/connection/index.js:94:24)
    at async Identify._identify (file:///usr/src/lodestar/node_modules/@libp2p/identify/dist/src/identify.js:51:22)
    at async Identify.identify (file:///usr/src/lodestar/node_modules/@libp2p/identify/dist/src/identify.js:68:25)

this is annoying on fusaka-devnet-0

grep -e "Error setting agentVersion" -rn beacon-2025-06-04.log | wc -l
63576

Expected behavior

no error

Steps to reproduce

No response

Additional context

No response

Operating system

Linux

Lodestar version or commit hash

v1.29.0

twoeths avatar Jun 05 '25 03:06 twoeths

I also notice this same error in bun branch https://github.com/ChainSafe/lodestar/pull/7867#issuecomment-2942610578

looks like something in it-length-prefixed-stream or it-byte-stream

grep -e "it-byte-stream" -rn beacon-2025-06-04.log | wc -l
64861

grep -e "unexpected end of input" -rn beacon-2025-06-04.log | wc -l
129404

twoeths avatar Jun 05 '25 03:06 twoeths

error like this

2025-06-05 13:50:02.428 | Jun-05 06:50:02.268[network]       verbose: Req  error method=metadata, version=2, encoding=ssz_snappy, client=Prysm, peer=16...f22nqn, requestId=984164, code=REQUEST_ERROR_DIAL_ERROR, error=unexpected end of input
-- | --

happens since we upgrade libp2p

Image

could be related to this commit on Mar 19 https://github.com/libp2p/js-libp2p/pull/3055/files

twoeths avatar Jun 05 '25 07:06 twoeths

So the "unexpected end of input" error happens here when the consumer of the byte stream asks for N bytes but the source is closed before N bytes are provided.

Looking at the call stack, this is happening here, specifically, during the multistream-select handshake, where we're negotiating the protocol with the peer. It seems that the error is reasonable if the peer closes the stream immediately after we send the identify protocol id. This can happen if the peer doesn't support the protocol or is disconnecting us, for example. (Our multistream select impl should probably catch the error and rethrow a more useful error)

What's not reasonable is how much we're seeing this error. From the logs, it appears that we're spamming a few peers over and over.

Edit: it's happening because these peers are constantly reconnecting and disconnecting...

2025-07-04 09:41:55.768	
Jul-04 13:41:55.767[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:55.242	
Jul-04 13:41:55.241[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:55.106	
Jul-04 13:41:55.104[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAm5uuFgSAUhSt3JpuxA5H2ES4NK6vgtpW9GcXEAECnzz7L - unexpected end of input
2025-07-04 09:41:54.727	
Jul-04 13:41:54.726[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:54.326	
Jul-04 13:41:54.323[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAm5uuFgSAUhSt3JpuxA5H2ES4NK6vgtpW9GcXEAECnzz7L - unexpected end of input
2025-07-04 09:41:54.216	
Jul-04 13:41:54.212[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:53.695	
Jul-04 13:41:53.693[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:53.476	
Jul-04 13:41:53.474[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAm5uuFgSAUhSt3JpuxA5H2ES4NK6vgtpW9GcXEAECnzz7L - unexpected end of input
2025-07-04 09:41:53.185	
Jul-04 13:41:53.183[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input
2025-07-04 09:41:52.673	
Jul-04 13:41:52.672[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAm5uuFgSAUhSt3JpuxA5H2ES4NK6vgtpW9GcXEAECnzz7L - unexpected end of input
2025-07-04 09:41:52.661	
Jul-04 13:41:52.660[network]         debug: Error setting agentVersion for the peer peerId=16Uiu2HAmURC2XfHM9sXKFwRLeTnQuAyJNgyQyswzz8SUJGA4jxXC - unexpected end of input

wemeetagain avatar Jul 04 '25 14:07 wemeetagain

There are many findings that we discussed earlier. Posting here for future reference.

There are different scenarios this error is triggering:

While identifying incoming connection

We see a lot of unexpected end of input error in combination of Error setting agentVersion for the peer. This happens when:

  1. A remote peer tries to connect and initiate an inbound connection
  2. We trigger event handler for onLibp2pPeerConnect in peerManager.
  3. And that initiate indentify protocol. That all happens around the same time.
  4. But external peer disconnect right away when we start indentify protocol.
  5. And that disconnect end up in stack of unexpected end of input error

Tried out to find which IPs are causing this behavior on fusaka-devnet-3

❯ grep "InvalidMessageError: Missing newline" *.log *.log.* | sed -n 's|.*from /ip4/\([0-9]\{1,3\}\.[0-9]\{1,3\}\.[0-9]\{1,3\}\.[0-9]\{1,3\}\)/tcp/.*|\1|p' | xargs -I{} grep '{}' ../../../inventories/devnet-3/inventory.ini
lighthouse-nimbusel-1 ansible_host=147.182.211.241 ipv6=2604:a880:400:d1:0:2:8408:5001 cloud=digitalocean cloud_region=nyc1 ethereum_node_cl_supernode_enabled=True validator_start=48 validator_end=64
lodestar-nimbusel-1 ansible_host=159.89.51.192 ipv6=2604:a880:400:d1:0:2:840a:1001 cloud=digitalocean cloud_region=nyc1 ethereum_node_cl_supernode_enabled=True validator_start=240 validator_end=256

There is a very big list of IPs but from our inventory all leads to the nimbus-el nodes. Seems like Nimus-EL is trying to connect to CL nodes over Discv5. Discussed with Nimbus team and there is relevant issue https://github.com/status-im/nimbus-eth1/issues/3557. For mitigation we refactored the logs in #8188 to show better error message.

While initiating outbound streams

We see a lot of errors during fusaka-devnet-3 which follow as:

2025-08-06T11:20:05.764Z libp2p:connection:outbound:b0wpcs1754478848032:error could not create new outbound stream on connection to /ip4/134.199.152.249/tcp/9000/p2p/16Uiu2HAm25bqxAvb2dZdg7MkFcBApNh2snokvDGNWQ5TSE2dzXRC for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:20:05.764Z libp2p:connection:outbound:b0wpcs1754478848032:error could not create new outbound stream on connection to /ip4/134.199.152.249/tcp/9000/p2p/16Uiu2HAm25bqxAvb2dZdg7MkFcBApNh2snokvDGNWQ5TSE2dzXRC for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:20:05.765Z libp2p:connection:outbound:cq0xc91754479116653:error could not create new outbound stream on connection to /ip4/209.38.90.97/tcp/9000/p2p/16Uiu2HAmADpSsAZFtCUQ4oQW5widjLCWZbRWVC659VkeEKU1GhFx for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:20:05.765Z libp2p:connection:outbound:cq0xc91754479116653:error could not create new outbound stream on connection to /ip4/209.38.90.97/tcp/9000/p2p/16Uiu2HAmADpSsAZFtCUQ4oQW5widjLCWZbRWVC659VkeEKU1GhFx for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:27:05.776Z libp2p:connection:outbound:7n8moz1754479147669:error could not create new outbound stream on connection to /ip4/134.199.163.129/tcp/9000/p2p/16Uiu2HAm3k5Npu6EaYWxiEvzsdLseEkjVyoVhvbxWEuyqdBgBBbq for protocols [ '/eth2/beacon_chain/req/data_column_sidecars_by_root/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:27:05.776Z libp2p:connection:outbound:7n8moz1754479147669:error could not create new outbound stream on connection to /ip4/134.199.163.129/tcp/9000/p2p/16Uiu2HAm3k5Npu6EaYWxiEvzsdLseEkjVyoVhvbxWEuyqdBgBBbq for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T11:27:05.776Z libp2p:connection:outbound:7n8moz1754479147669:error could not create new outbound stream on connection to /ip4/134.199.163.129/tcp/9000/p2p/16Uiu2HAm3k5Npu6EaYWxiEvzsdLseEkjVyoVhvbxWEuyqdBgBBbq for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:08:35.860Z libp2p:connection:outbound:cxfswr1754481794014:error could not create new outbound stream on connection to /ip4/137.184.188.24/tcp/9000/p2p/16Uiu2HAmJ6XXgaUNwhL5ogdZGFZ8KeK1Q2TnQpAVoWCpmSXesjJd for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:08:35.861Z libp2p:connection:outbound:cxfswr1754481794014:error could not create new outbound stream on connection to /ip4/137.184.188.24/tcp/9000/p2p/16Uiu2HAmJ6XXgaUNwhL5ogdZGFZ8KeK1Q2TnQpAVoWCpmSXesjJd for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:08:35.861Z libp2p:connection:outbound:cxfswr1754481794014:error could not create new outbound stream on connection to /ip4/137.184.188.24/tcp/9000/p2p/16Uiu2HAmJ6XXgaUNwhL5ogdZGFZ8KeK1Q2TnQpAVoWCpmSXesjJd for protocols [ '/eth2/beacon_chain/req/status/2/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:09:05.853Z libp2p:connection:outbound:65uden1754482007397:error could not create new outbound stream on connection to /ip4/134.199.164.239/tcp/9000/p2p/16Uiu2HAmRdjHKya24a3qV7rAQ7ceetYY1QEmt6NCaSDqCsyjRydv for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:09:05.853Z libp2p:connection:outbound:65uden1754482007397:error could not create new outbound stream on connection to /ip4/134.199.164.239/tcp/9000/p2p/16Uiu2HAmRdjHKya24a3qV7rAQ7ceetYY1QEmt6NCaSDqCsyjRydv for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:22:35.841Z libp2p:gossipsub:error createOutboundStream error UnexpectedEOFError: unexpected end of input
2025-08-06T12:22:36.780Z libp2p:connection:outbound:1ztsbs1754482956696:error could not create new outbound stream on connection to /ip4/57.129.144.194/tcp/15301/p2p/16Uiu2HAmD7t7V6pstym22EQ7NZhJ8GMRdvFSmGVKi8BNGMXREM7e for protocols [ '/eth2/beacon_chain/req/metadata/3/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T12:26:35.424Z libp2p:connection:outbound:3qqbqj1754482704579:error could not create new outbound stream on connection to /ip4/209.38.88.251/tcp/9000/p2p/16Uiu2HAmN2MJNCyvKHNX5mLQn4A6envukQD6egDv1LC2caGSxJu6 for protocols [ '/eth2/beacon_chain/req/ping/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input
2025-08-06T14:00:06.200Z libp2p:connection:outbound:f4ps051754484936880:error could not create new outbound stream on connection to /ip4/137.184.211.135/tcp/9000/p2p/16Uiu2HAmR8keaUzb6mpqqBMmCiXAWjTGkqKSt457vaNe7k1X4phz for protocols [ '/eth2/beacon_chain/req/goodbye/1/ssz_snappy' ] - UnexpectedEOFError: unexpected end of input

Most of those errors are related to following protocols. When we initiate outbound streams:

  • /eth2/beacon_chain/req/goodbye/1/ssz_snappy
  • /eth2/beacon_chain/req/ping/1/ssz_snappy

All of these happens with this flow:

  • upgrader tries to negotiate the list of protocols given
  • It uses multistream.select
    • That one take off first protocol from the list
    • Prepend '/multistream/1.0.0' to it
    • Write these two protocols to the length-prefixed-streams
    • Then tries to read back with readString
    • While reading that we don't know how many bytes to read
      • So we go read one byte at a time and append to buffer.
      • Try to decode the buffer to an integer
      • If it decodes, that implies we have to read that much bytes more
      • And then convert those bytes to a utf8 string

I suspected this code from it-byte-stream package, what if node responds and end the same time.

while (readBuffer.byteLength < options.bytes) {
  const { value, done } = await raceSignal(source.next(), options?.signal);
  if (done === true) {
    throw new UnexpectedEOFError('unexpected end of input');
  }
  readBuffer.append(value);
}

This is possible with async iterators to respond done and value same time, but the NodeJS streams implementation enforce in a way that when we are done we don't have value. a.ka. It yield value and return separately. So again that issue is some peers are mis-behaving.

There is an issue in libp2p to show better error messages in such cases https://github.com/libp2p/js-libp2p/issues/3210

nazarhussain avatar Aug 14 '25 07:08 nazarhussain