search

hyperledger / besu

An enterprise-grade Java-based, Apache 2.0 licensed Ethereum client https://wiki.hyperledger.org/display/besu
https://www.hyperledger.org/projects/besu
Apache License 2.0
1.51k stars 824 forks source link

poor performance: low peers, slow sync, slow start #2503

Closed meowsbits closed 2 years ago

meowsbits commented 3 years ago

Description

As a person, I want besu to run so that I have blockchains.

Acceptance Criteria

Besu running on --classic syncs the blocks.

Steps to Reproduce (Bug)

root@singapore:~/besu# uname -a 
Linux singapore 5.4.0-73-generic #82-Ubuntu SMP Wed Apr 14 17:39:42 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

root@singapore:~/besu# /root/besu-bin/besu-21.7.0-RC2/bin/besu --version
besu/v21.7.0-RC2/linux-x86_64/openjdk-java-14

Running with systemd, via the following unit file.

root@singapore:~/besu# cat /etc/systemd/system/besu.classic.service 
[Unit]
Description=besu classic service

[Service]
Type=simple
User=root
Restart=always
RestartSec=3
TimeoutStopSec=10min
ExecStart=/bin/sh -c '/root/besu-bin/besu-21.7.0-RC2/bin/besu \
        --network=classic \
        --data-path=/mnt/volume_sgp1_01/besu-classic \
        --logging=trace \
        --rpc-http-enabled=true \
        --rpc-http-api=admin,eth,web3,net \
        --rpc-http-port=8545 \
'

[Install]
WantedBy=default.target

Expected behavior: It runs.

Actual behavior: It doesn't do anything.

Frequency: It only does this. I have restarted several times.

Additional Information

Logs

Jul 06 15:56:11 singapore systemd[1]: Started besu classic service.
Jul 06 15:56:15 singapore sh[25367]: Setting logging level to TRACE
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.689+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@4e0e2f2a for /com/sun/jna/linux-x86-64/libjnidispatch.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.702+00:00 | main | DEBUG | Native | Found library resource at jar:file:/root/besu-bin/besu-21.7.0-RC2/lib/jna-5.6.0.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.705+00:00 | main | DEBUG | Native | Extracting library to /root/.cache/JNA/temp/jna469371276576218112.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.709+00:00 | main | DEBUG | Native | Trying /root/.cache/JNA/temp/jna469371276576218112.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.712+00:00 | main | DEBUG | Native | Found jnidispatch at /root/.cache/JNA/temp/jna469371276576218112.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.770+00:00 | main | DEBUG | NativeLibrary | Looking for library 'eth_pairings'
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.776+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.777+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.779+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.779+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /usr/lib64, /lib64, /usr/lib, /lib]
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.780+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.781+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.782+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.791+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@4e0e2f2a for eth_pairings
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.794+00:00 | main | DEBUG | Native | Found library resource at jar:file:/root/besu-bin/besu-21.7.0-RC2/lib/bls12-381-0.3.0.jar!/linux-x86-64/libeth_pairings.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.797+00:00 | main | DEBUG | Native | Extracting library to /root/.cache/JNA/temp/jna9750795282097414844.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.837+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /root/.cache/JNA/temp/jna9750795282097414844.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.875+00:00 | main | INFO  | AbstractAltBnPrecompiledContract | Using LibEthPairings native alt bn128
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.880+00:00 | main | DEBUG | NativeLibrary | Looking for library 'secp256k1'
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.881+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.882+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.883+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.883+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /usr/lib64, /lib64, /usr/lib, /lib]
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.883+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.884+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.884+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.886+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@4e0e2f2a for secp256k1
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.892+00:00 | main | DEBUG | Native | Found library resource at jar:file:/root/besu-bin/besu-21.7.0-RC2/lib/secp256k1-0.3.0.jar!/linux-x86-64/libsecp256k1.so
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.893+00:00 | main | DEBUG | Native | Extracting library to /root/.cache/JNA/temp/jna10673287134664011761.tmp
Jul 06 15:56:17 singapore sh[25367]: 2021-07-06 15:56:17.900+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /root/.cache/JNA/temp/jna10673287134664011761.tmp

Time of writing date is below, showing at least about 30 minutes of radio silence on TRACE logs.

root@singapore:~/besu# date
Tue Jul  6 16:24:40 UTC 2021

The HTTP RPC API is not yet open, either.

root@singapore:~/besu# curl -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "eth_syncing", "params": []}' http://localhost:8545 
curl: (7) Failed to connect to localhost port 8545: Connection refused
atoulme commented 3 years ago

Can you give more information about the environment? I have seen this happen when you run a besu node in an environment where there isn’t enough entropy and urandom is not initialized. See https://github.com/hyperledger/besu/issues/1464 as an other instance of this issue.

meowsbits commented 3 years ago

Well, this has sort of resolved... although as you'll see in the title change, it still seems wonky. 1464 seems quite related, thanks for finding that! I too once saw Besu start up quickly, but then couldn't reproduce.

Following up on the initial thread of this complaint: Besu started to do other stuff after about an hour. It now seems to spend most of its time looking for peers, and not really being successful in that effort.

Here's a snippet of the logs I'm seeing, where Besu has been running overnight (since the OP). 

Jul 07 10:57:52 singapore sh[26260]: 2021-07-07 10:57:52.780+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:53 singapore sh[26260]: 2021-07-07 10:57:53.449+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:54 singapore sh[26260]: 2021-07-07 10:57:54.129+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:54 singapore sh[26260]: 2021-07-07 10:57:54.808+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:54 singapore sh[26260]: 2021-07-07 10:57:54.896+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:54 singapore sh[26260]: 2021-07-07 10:57:54.898+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:55 singapore sh[26260]: 2021-07-07 10:57:55.673+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:56 singapore sh[26260]: 2021-07-07 10:57:55.747+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncTargetManager | No sync target, waiting for peers: 3
Jul 07 10:57:56 singapore sh[26260]: 2021-07-07 10:57:56.520+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3
Jul 07 10:57:56 singapore sh[26260]: java.lang.InterruptedException
Jul 07 10:57:56 singapore sh[26260]: 2021-07-07 10:57:56.535+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 3

Some RPC status io's: 

root@singapore:~/besu# curl -s -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "eth_syncing", "params": []}' http://localhost:8545                      
{
  "jsonrpc" : "2.0",
  "id" : 1,
  "result" : false
}root@singapore:~/besu# curl -s -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "eth_blockNumber", "params": []}' http://localhost:8545                                                                                    
{
  "jsonrpc" : "2.0",
  "id" : 1,
  "result" : "0x11b98"
}root@singapore:~/besu# echo $((0x11b98))
72600

Here's a closer look at admin_peers:

root@singapore:~/besu# curl -s -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "admin_peers", "params": []}' http://localhost:8545
{
  "jsonrpc" : "2.0",
  "id" : 1,
  "result" : [ {
    "version" : "0x5",
    "name" : "OpenEthereum/v3.2.4-stable/x86_64-linux-musl/rustc1.47.0",
    "caps" : [ "par/1", "par/2", "eth/64" ],
    "network" : {
      "localAddress" : "128.199.181.34:60980",
      "remoteAddress" : "3.142.151.206:30303"
    },
    "port" : "0x765f",
    "id" : "0x9093f1ed0ba9ecff14a4153d8dc893f8abb95050b7ad04677c39fdd3aace253a1888cef4d18d40874e79ec0c3912321de0451d45e113fe890f796fc2ddfd2080",
    "protocols" : {
      "eth" : {
        "difficulty" : "0x400000000",
        "head" : "0xd4e56740f876aef8c010b86a40d5f56745a118d0906a34e69aec8c0db1cb8fa3",
        "version" : 64
      }
    },
    "enode" : "enode://9093f1ed0ba9ecff14a4153d8dc893f8abb95050b7ad04677c39fdd3aace253a1888cef4d18d40874e79ec0c3912321de0451d45e113fe890f796fc2ddfd2080@3.142.151.206:30303"
  }, {
    "version" : "0x5",
    "name" : "Geth/v1.8.27-stable-4bcc0a37/linux-amd64/go1.11.9",
    "caps" : [ "eth/63" ],
    "network" : {
      "localAddress" : "128.199.181.34:47308",
      "remoteAddress" : "13.239.37.208:3051"
    },
    "port" : "0x0",
    "id" : "0x397d4de757f70bbd0be9d6e75d4e9dfb8202a272fe895ea8d6bb7abc5d098d88ecea9bd95e49999861e2e00b90de405992e152deb3e4155280c50e57320ceb3c",
    "protocols" : {
      "eth" : {
        "difficulty" : "0x0",
        "head" : "0x",
        "version" : 0
      }
    },
    "enode" : "enode://397d4de757f70bbd0be9d6e75d4e9dfb8202a272fe895ea8d6bb7abc5d098d88ecea9bd95e49999861e2e00b90de405992e152deb3e4155280c50e57320ceb3c@13.239.37.208:3051"
  }, {
    "version" : "0x5",
    "name" : "mantis/v3.2.4-SNAPSHOT-31a22d9/windows10-amd64/adoptopenjdk-openjdk64bitservervm-java-1.8.0_252",
    "caps" : [ "eth/63" ],
    "network" : {
      "localAddress" : "128.199.181.34:51972",
      "remoteAddress" : "89.79.239.85:9076"
    },
    "port" : "0x2374",
    "id" : "0x1e626996a0892cb27bb7de43187dcf4fe2951819c1bf46a75f9634c25dcaf0e33beb1585569f10d1300c89121e68f7baf35a4d7ab18d4c8d5436163b817613ec",
    "protocols" : {
      "eth" : {
        "difficulty" : "0x0",
        "head" : "0x",
        "version" : 0
      }
    },
    "enode" : "enode://1e626996a0892cb27bb7de43187dcf4fe2951819c1bf46a75f9634c25dcaf0e33beb1585569f10d1300c89121e68f7baf35a4d7ab18d4c8d5436163b817613ec@89.79.239.85:9076?discport=30303"
  } ]

It seems notably lacking CoreGeth peers (since they comprise most of the network).

meowsbits commented 3 years ago

Some more system info for the machine in question.

It's a standard $10/month DigitalOcean droplet (VPS). Except for installing the JavaSDK its right off the shelf. I'm using a mounted SSD for the datadir.

root@singapore:~/besu# cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 63
model name      : DO-Regular
stepping        : 2
microcode       : 0x1
cpu MHz         : 2494.138
cache size      : 4096 KB
physical id     : 0
siblings        : 1
core id         : 0
cpu cores       : 1
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss syscall nx rdtscp lm constant_tsc arch_perfmon rep_good nopl cpuid tsc_known_freq pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm cpuid_fault invpcid_single pti ssbd ibrs ibpb tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid xsaveopt md_clear
bugs            : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs itlb_multihit
bogomips        : 4988.27
clflush size    : 64
cache_alignment : 64
address sizes   : 40 bits physical, 48 bits virtual
power management:

root@singapore:~/besu# [[ -e /dev/urandom ]] && echo random ahoy
random ahoy
meowsbits commented 3 years ago

I'm not sure if these errors in the logs are normal or not, but I see them too.

Jul 07 11:13:34 singapore sh[29612]: 2021-07-07 11:13:34.274+00:00 | EthScheduler-Timer-0 | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 1
Jul 07 11:13:34 singapore sh[29612]: 2021-07-07 11:13:34.275+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncTargetManager | No sync target, waiting for peers: 1
Jul 07 11:13:39 singapore sh[29612]: java.lang.InterruptedException
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1668)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:435)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.Pipe.get(Pipe.java:98)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.BatchingReadPipe.get(BatchingReadPipe.java:48)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.BatchingReadPipe.get(BatchingReadPipe.java:23)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.AsyncOperationProcessor.processNextInput(AsyncOperationProcessor.java:52)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.ProcessingStage.run(ProcessingStage.java:38)
Jul 07 11:13:39 singapore sh[29612]:         at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:152)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
Jul 07 11:13:39 singapore sh[29612]:         at java.base/java.lang.Thread.run(Thread.java:832)
Jul 07 11:13:39 singapore sh[29612]: 2021-07-07 11:13:39.277+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncTargetManager | No sync target, waiting for peers: 1
Jul 07 11:13:39 singapore sh[29612]: 2021-07-07 11:13:39.279+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 1
Jul 07 11:15:32 singapore sh[29612]: 2021-07-07 11:15:32.028+00:00 | EthScheduler-Services-4 (batchDownloadData) | INFO  | AbstractRetryingPeerTask | No peers available, waiting for peers: 6
Jul 07 11:15:36 singapore sh[29612]: org.hyperledger.besu.ethereum.rlp.RLPException: Error applying element decoding function on element 4 of the list
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.RLPInput.readList(RLPInput.java:333)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.wire.PeerInfo.readFrom(PeerInfo.java:64)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.wire.messages.HelloMessage.getPeerInfo(HelloMessage.java:56)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.DeFramer.decode(DeFramer.java:110)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:508)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.AbstractHandshakeHandler.channelRead0(AbstractHandshakeHandler.java:128)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.AbstractHandshakeHandler.channelRead0(AbstractHandshakeHandler.java:43)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Jul 07 11:15:36 singapore sh[29612]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Jul 07 11:15:36 singapore sh[29612]:         at java.base/java.lang.Thread.run(Thread.java:832)
Jul 07 11:15:36 singapore sh[29612]: Caused by: org.hyperledger.besu.ethereum.rlp.RLPException: Cannot read a byte, expecting 1 bytes but current element is 0 bytes long (at bytes 93-94: ...83776974[80]82765fb8...)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.error(AbstractRLPInput.java:202)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.checkElt(AbstractRLPInput.java:255)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.AbstractRLPInput.readByte(AbstractRLPInput.java:340)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.BytesValueRLPInput.readByte(BytesValueRLPInput.java:23)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.RLPInput.readUnsignedByte(RLPInput.java:216)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.p2p.rlpx.wire.Capability.readFrom(Capability.java:62)
Jul 07 11:15:36 singapore sh[29612]:         at org.hyperledger.besu.ethereum.rlp.RLPInput.readList(RLPInput.java:330)
Jul 07 11:15:36 singapore sh[29612]:         ... 28 more

Jul 07 11:14:59 singapore sh[29612]: java.net.SocketException: Connection reset                                                                                                                                              
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)                                 
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)                                         
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)                                                                                                               
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1134)                                                           
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)                                                           
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)                                                                              
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)          
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)                                    
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)                                                                                                                 
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)             
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)            
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 
Jul 07 11:14:59 singapore sh[29612]:         at java.base/java.lang.Thread.run(Thread.java:832)                                                                                                                              
Jul 07 11:14:59 singapore sh[29612]: java.net.SocketException: Connection reset                                                                                                                                              
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)                                                                                      
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)                                                                       
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)                                                                  
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1134)                                                  
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)                             
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)                        
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)                                      
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)                                   
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)                                                                                                 
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)                                                                                                                 
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)                      
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Jul 07 11:14:59 singapore sh[29612]:         at java.base/java.lang.Thread.run(Thread.java:832)                                                                                                                              
Jul 07 11:14:59 singapore sh[29612]: java.net.SocketException: Connection reset                                                                                                                                              
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
Jul 07 11:14:59 singapore sh[29612]:         at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)                     
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)              
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1134)                                                                                                        
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)         
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)                                                                       
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)          
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)                                                                                        
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)                                                                                                 
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)                                                                                                                 
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)          
Jul 07 11:14:59 singapore sh[29612]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Jul 07 11:14:59 singapore sh[29612]:         at java.base/java.lang.Thread.run(Thread.java:832)
meowsbits commented 3 years ago

I just restarted with the --Xsecp256k1-native-enabled false flag recommend at #1464. While my logs are still filled with the above errors, it does seem that progress is much better.

root@singapore:~/besu# curl -s -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "eth_syncing", "params": []}' http://localhost:8545
{
  "jsonrpc" : "2.0",
  "id" : 1,
  "result" : {
    "startingBlock" : "0x11b98",
    "currentBlock" : "0x1cc02",
    "highestBlock" : "0xc79d52",
    "pulledStates" : "0x0",
    "knownStates" : "0x0"
  }
}
root@singapore:~/besu# curl -s -X POST -d '{"jsonrpc": "2.0", "id": 1, "method": "admin_peers", "params": []}' http://localhost:8545 | jq '.result|length'
16

EDIT Well, those peers (16), may have been a fluke... I'm collecting a few minutes of admin.peers logs now...

garyschulte commented 2 years ago

It appears the randomness entropy problem was worked around. Could you confirm whether or not peer discovery on classic is resolved in 21.10.2 by enabling of DNS Discovery? 3033

garyschulte commented 2 years ago

In light of the entropy workaround above, plus all of the dns and peering fixes since this ticket was filed, we will close this. https://github.com/hyperledger/besu/pull/2944 https://github.com/hyperledger/besu/pull/3033 https://github.com/hyperledger/besu/pull/3057 https://github.com/hyperledger/besu/pull/3071 https://github.com/hyperledger/besu/pull/3123

if you are still encountering the issue reported in this ticket, feel free to reopen