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.48k stars 809 forks source link

Besu node crash with discovery-enabled=true in config.toml #3343

Closed jorgesanjose closed 2 years ago

jorgesanjose commented 2 years ago

Description

As an user, I want to run up a Besu node with discovery-enabled set to true, but after a few errors, it crashes. But when it is set to false, the errors continues but not crashes.

Steps to Reproduce (Bug)

  1. Set discovery-enabled=true in config.toml.
  2. Set bootnodes array in config.toml.
  3. Start node.

Logs 

2022-01-28 11:38:44.902+00:00 | main | DEBUG | Native | Found library resource at jar:file:/data/alastria-node-besu/versionesBesu/besu-21.10.8/lib/jna-5.8.0.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
2022-01-28 11:38:44.905+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna4822194681370950143.tmp
2022-01-28 11:38:44.908+00:00 | main | DEBUG | Native | Trying /home/x281921/.cache/JNA/temp/jna4822194681370950143.tmp
2022-01-28 11:38:44.909+00:00 | main | DEBUG | Native | Found jnidispatch at /home/x281921/.cache/JNA/temp/jna4822194681370950143.tmp
2022-01-28 11:38:44.953+00:00 | main | DEBUG | NativeLibrary | Looking for library 'secp256k1'
2022-01-28 11:38:44.954+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-01-28 11:38:44.954+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-01-28 11:38:44.955+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:44.956+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /lib64, /usr/lib, /lib, /usr/lib/x86_64-linux-gnu/libfakeroot]
2022-01-28 11:38:44.956+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-01-28 11:38:44.957+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:44.957+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-01-28 11:38:44.961+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for secp256k1
2022-01-28 11:38:44.963+00:00 | main | DEBUG | Native | Found library resource at jar:file:/data/alastria-node-besu/versionesBesu/besu-21.10.8/lib/secp256k1-0.4.2.jar!/linux-x86-64/libsecp256k1.so
2022-01-28 11:38:44.964+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna4489313619374674359.tmp
2022-01-28 11:38:44.973+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /home/x281921/.cache/JNA/temp/jna4489313619374674359.tmp
2022-01-28 11:38:45.009+00:00 | main | DEBUG | NativeLibrary | Looking for library 'eth_pairings'
2022-01-28 11:38:45.011+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-01-28 11:38:45.011+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-01-28 11:38:45.013+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:45.014+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /lib64, /usr/lib, /lib, /usr/lib/x86_64-linux-gnu/libfakeroot]
2022-01-28 11:38:45.015+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-01-28 11:38:45.015+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:45.016+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-01-28 11:38:45.019+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for eth_pairings
2022-01-28 11:38:45.020+00:00 | main | DEBUG | Native | Found library resource at jar:file:/data/alastria-node-besu/versionesBesu/besu-21.10.8/lib/bls12-381-0.3.0.jar!/linux-x86-64/libeth_pairings.so
2022-01-28 11:38:45.022+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna5396103584728477048.tmp
2022-01-28 11:38:45.062+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /home/x281921/.cache/JNA/temp/jna5396103584728477048.tmp
2022-01-28 11:38:45.065+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-01-28 11:38:45.069+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-01-28 11:38:45.076+00:00 | main | INFO  | Besu | Starting Besu version: besu/v21.10.8/linux-x86_64/openjdk-java-11
2022-01-28 11:38:45.125+00:00 | main | DEBUG | LoggerFactory | Using io.vertx.core.logging.Log4j2LogDelegateFactory
2022-01-28 11:38:45.163+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple
2022-01-28 11:38:45.164+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.targetRecords: 4
2022-01-28 11:38:45.188+00:00 | main | DEBUG | PlatformDependent0 | -Dio.netty.noUnsafe: false
2022-01-28 11:38:45.189+00:00 | main | DEBUG | PlatformDependent0 | Java version: 11
2022-01-28 11:38:45.192+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
2022-01-28 11:38:45.193+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
2022-01-28 11:38:45.195+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Buffer.address: available
2022-01-28 11:38:45.196+00:00 | main | DEBUG | PlatformDependent0 | direct buffer constructor: available
2022-01-28 11:38:45.198+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Bits.unaligned: available, true
2022-01-28 11:38:45.201+00:00 | main | DEBUG | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): available
2022-01-28 11:38:45.202+00:00 | main | DEBUG | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
2022-01-28 11:38:45.203+00:00 | main | DEBUG | PlatformDependent | sun.misc.Unsafe: available
2022-01-28 11:38:45.204+00:00 | main | DEBUG | PlatformDependent | maxDirectMemory: 2086666240 bytes (maybe)
2022-01-28 11:38:45.205+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2022-01-28 11:38:45.205+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
2022-01-28 11:38:45.207+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.maxDirectMemory: 2086666240 bytes
2022-01-28 11:38:45.207+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: 1024
2022-01-28 11:38:45.209+00:00 | main | DEBUG | CleanerJava9 | java.nio.ByteBuffer.cleaner(): available
2022-01-28 11:38:45.210+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.noPreferDirect: false
2022-01-28 11:38:45.232+00:00 | main | DEBUG | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 4
2022-01-28 11:38:45.258+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2022-01-28 11:38:45.258+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2022-01-28 11:38:45.268+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.noKeySetOptimization: false
2022-01-28 11:38:45.269+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
2022-01-28 11:38:45.281+00:00 | main | DEBUG | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available
2022-01-28 11:38:45.345+00:00 | main | DEBUG | DefaultDnsServerAddressStreamProvider | Default DNS servers: [/127.0.0.53:53] (sun.net.dns.ResolverConfiguration)
2022-01-28 11:38:45.355+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv4Stack: false
2022-01-28 11:38:45.356+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv6Addresses: false
2022-01-28 11:38:45.362+00:00 | main | DEBUG | NetUtilInitializations | Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
2022-01-28 11:38:45.367+00:00 | main | DEBUG | NetUtil | /proc/sys/net/core/somaxconn: 4096
2022-01-28 11:38:45.442+00:00 | main | INFO  | Besu | Static Nodes file = /data/alastria-node-besu/validator/static-nodes.json
2022-01-28 11:38:45.446+00:00 | main | INFO  | StaticNodesParser | StaticNodes file /data/alastria-node-besu/validator/static-nodes.json does not exist, no static connections will be created.
2022-01-28 11:38:45.449+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-01-28 11:38:45.452+00:00 | main | INFO  | Besu | Security Module: localfile
2022-01-28 11:38:45.485+00:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /data/alastria-node-besu/validator
2022-01-28 11:38:45.546+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /data/alastria-node-besu/validator. Version 1
2022-01-28 11:38:45.925+00:00 | main | INFO  | KeyPairUtil | Loaded public key 0x0f41452bd52d269a9ab9174033ee632c1f17a27259a11003f7550840a5ad3beba07ec1126ff09f5f68649b54afb5de161fa3fc6f7eebdace04ae35f1845961fb from /data/alastria-node-besu/validator/keys/besu/key
2022-01-28 11:38:46.155+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Byzantium: 0]
2022-01-28 11:38:46.340+00:00 | main | DEBUG | BesuPluginContextImpl | Plugin startup complete.
2022-01-28 11:38:46.346+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-01-28 11:38:46.379+00:00 | main | DEBUG | RlpxAgent | Using default NettyConnectionInitializer
2022-01-28 11:38:46.473+00:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2022-01-28 11:38:46.474+00:00 | main | INFO  | MetricsHttpService | Starting metrics http service on 0.0.0.0:9545
2022-01-28 11:38:46.523+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numHeapArenas: 4
2022-01-28 11:38:46.524+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numDirectArenas: 4
2022-01-28 11:38:46.525+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.pageSize: 8192
2022-01-28 11:38:46.525+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxOrder: 11
2022-01-28 11:38:46.525+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.chunkSize: 16777216
2022-01-28 11:38:46.526+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.smallCacheSize: 256
2022-01-28 11:38:46.526+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.normalCacheSize: 64
2022-01-28 11:38:46.526+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-01-28 11:38:46.527+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimInterval: 8192
2022-01-28 11:38:46.527+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-01-28 11:38:46.527+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.useCacheForAllThreads: true
2022-01-28 11:38:46.528+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-01-28 11:38:46.560+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.processId: 20372 (auto-detected)
2022-01-28 11:38:46.562+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.machineId: 00:0d:3a:ff:fe:ab:f3:13 (auto-detected)
2022-01-28 11:38:46.592+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.allocator.type: pooled
2022-01-28 11:38:46.593+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.threadLocalDirectBufferSize: 0
2022-01-28 11:38:46.593+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-01-28 11:38:46.613+00:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2022-01-28 11:38:46.614+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-01-28 11:38:46.613+00:00 | vert.x-eventloop-thread-1 | INFO  | MetricsHttpService | Metrics service started and listening on 9545:9545
2022-01-28 11:38:46.623+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0:0:0:0:0:0:0:0:30303.
2022-01-28 11:38:46.624+00:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2022-01-28 11:38:46.689+00:00 | vert.x-eventloop-thread-1 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0:0:0:0:0:0:0:0 and port=30303
2022-01-28 11:38:46.692+00:00 | main | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0:0:0:0:0:0:0:0:30303
2022-01-28 11:38:46.706+00:00 | main | ERROR | Runner | Startup failed java.lang.NullPointerException
2022-01-28 11:38:46.714+00:00 | Thread-1 | DEBUG | BesuPluginContextImpl | Plugin shutdown complete.
2022-01-28 11:38:46.728+00:00 | Thread-1 | ERROR | Besu | Failed to stop Besu

It shows this errors.

2022-01-28 11:38:45.011+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-01-28 11:38:45.013+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:45.014+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /lib64, /usr/lib, /lib, /usr/lib/x86_64-linux-gnu/libfakeroot]
2022-01-28 11:38:45.015+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-01-28 11:38:45.015+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:44.954+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-01-28 11:38:44.955+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-01-28 11:38:44.956+00:00 | main | DEBUG | NativeLibrary | Adding system paths: [/usr/lib/x86_64-linux-gnu, /lib/x86_64-linux-gnu, /lib64, /usr/lib, /lib, /usr/lib/x86_64-linux-gnu/libfakeroot]
2022-01-28 11:38:44.956+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-01-28 11:38:44.957+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory

Then it crashes.

2022-01-28 11:38:46.706+00:00 | main | ERROR | Runner | Startup failed java.lang.NullPointerException
2022-01-28 11:38:46.714+00:00 | Thread-1 | DEBUG | BesuPluginContextImpl | Plugin shutdown complete.
2022-01-28 11:38:46.728+00:00 | Thread-1 | ERROR | Besu | Failed to stop Besu

Versions (Add all that apply)

macfarla commented 2 years ago

Hi @jorgesanjose - that sounds most annoying! One thing - you can ignore the "loading failed" messages because eventually it finds one - it's just logging where it's searching. 2022-01-28 11:38:45.062+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /home/x281921/.cache/JNA/temp/jna5396103584728477048.tmp

2022-01-28 11:38:44.973+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /home/x281921/.cache/JNA/temp/jna4489313619374674359.tmp

Couple of questions

jorgesjv commented 2 years ago

Hi @macfarla, thanks for the answer.

I've tried with 21.10.9 version and same result.

This is my config.toml. 

# Valid TOML config file
data-path="/mnt/alastria-node-besu/validator"
logging="TRACE"

#Network
bootnodes=["enode://2a9ddbc44eeddc736cf5727ecaefe0372b2b2bae9bb1bc7f2f2f736eee827cacecee3ef7e127b76f68d27415879760905657e572b35d61e9cd35b372932f5ebc@193.125.252.24:30303","enode://e99d27010e07102de26eec8ad44fa84a4c2cb348e037ff91eca1b6134539d5ebf6db9f2c315e2de7ef9caf6297e349c00bda7b8c9028f0c138d910286a63ae9a@159.8.101.3:30303"]
node-private-key-file="/mnt/alastria-node-besu/validator/keys/besu/key"
discovery-enabled=true

# Comment this flag if you are using a lower ver version than 20.10.1
compatibility-eth64-forkid-enabled=true

permissions-accounts-contract-address="0x0000000000000000000000000000000000008888"
permissions-accounts-contract-enabled=false
permissions-nodes-contract-address="0x0000000000000000000000000000000000009999"
permissions-nodes-contract-enabled=false

# Chain
genesis-file="/mnt/alastria-node-besu/validator/config/besu/genesis.json"
min-gas-price=0

rpc-http-api=["ETH","NET","WEB3","ADMIN","IBFT"]
rpc-http-enabled=true
rpc-http-host="0.0.0.0"
host-whitelist=["*"]

# WS
rpc-ws-enabled=true

# Metrics
metrics-enabled=true
metrics-host="0.0.0.0"
metrics-port="9545"

And the full log.

2022-02-01 09:26:33.651+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for /com/sun/jna/linux-x86-64/libjnidispatch.so
2022-02-01 09:26:33.654+00:00 | main | DEBUG | Native | Found library resource at jar:file:/mnt/alastria-node-besu/versionesBesu/besu-21.10.9/lib/jna-5.8.0.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
2022-02-01 09:26:33.655+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna3762955625303343143.tmp
2022-02-01 09:26:33.657+00:00 | main | DEBUG | Native | Trying /home/x281921/.cache/JNA/temp/jna3762955625303343143.tmp
2022-02-01 09:26:33.659+00:00 | main | DEBUG | Native | Found jnidispatch at /home/x281921/.cache/JNA/temp/jna3762955625303343143.tmp
2022-02-01 09:26:33.684+00:00 | main | DEBUG | NativeLibrary | Looking for library 'secp256k1'
2022-02-01 09:26:33.684+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-02-01 09:26:33.684+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-02-01 09:26:33.685+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-02-01 09:26:33.685+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]
2022-02-01 09:26:33.686+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-02-01 09:26:33.686+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-02-01 09:26:33.686+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-02-01 09:26:33.690+00:00 | main | DEBUG | NativeLibrary | Trying /usr/lib/x86_64-linux-gnu/libsecp256k1.so.0
2022-02-01 09:26:33.691+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /usr/lib/x86_64-linux-gnu/libsecp256k1.so.0
2022-02-01 09:26:33.718+00:00 | main | DEBUG | NativeLibrary | Looking for library 'eth_pairings'
2022-02-01 09:26:33.719+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-02-01 09:26:33.719+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-02-01 09:26:33.719+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-02-01 09:26:33.720+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]
2022-02-01 09:26:33.720+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-02-01 09:26:33.720+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-02-01 09:26:33.720+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-02-01 09:26:33.724+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for eth_pairings
2022-02-01 09:26:33.725+00:00 | main | DEBUG | Native | Found library resource at jar:file:/mnt/alastria-node-besu/versionesBesu/besu-21.10.9/lib/bls12-381-0.3.0.jar!/linux-x86-64/libeth_pairings.so
2022-02-01 09:26:33.727+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna4437927128200933330.tmp
2022-02-01 09:26:33.762+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /home/x281921/.cache/JNA/temp/jna4437927128200933330.tmp
2022-02-01 09:26:33.763+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-02-01 09:26:33.763+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-02-01 09:26:33.767+00:00 | main | INFO  | Besu | Starting Besu version: besu/v21.10.9/linux-x86_64/openjdk-java-11
2022-02-01 09:26:33.772+00:00 | main | TRACE | MetricsSystemFactory | Creating a metric system with PROMETHEUS
2022-02-01 09:26:33.796+00:00 | main | DEBUG | LoggerFactory | Using io.vertx.core.logging.Log4j2LogDelegateFactory
2022-02-01 09:26:33.818+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple
2022-02-01 09:26:33.818+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.targetRecords: 4
2022-02-01 09:26:33.845+00:00 | main | DEBUG | PlatformDependent0 | -Dio.netty.noUnsafe: false
2022-02-01 09:26:33.846+00:00 | main | DEBUG | PlatformDependent0 | Java version: 11
2022-02-01 09:26:33.847+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
2022-02-01 09:26:33.848+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
2022-02-01 09:26:33.848+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Buffer.address: available
2022-02-01 09:26:33.849+00:00 | main | DEBUG | PlatformDependent0 | direct buffer constructor: available
2022-02-01 09:26:33.850+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Bits.unaligned: available, true
2022-02-01 09:26:33.851+00:00 | main | DEBUG | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): available
2022-02-01 09:26:33.852+00:00 | main | DEBUG | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
2022-02-01 09:26:33.852+00:00 | main | DEBUG | PlatformDependent | sun.misc.Unsafe: available
2022-02-01 09:26:33.853+00:00 | main | DEBUG | PlatformDependent | maxDirectMemory: 2086666240 bytes (maybe)
2022-02-01 09:26:33.853+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2022-02-01 09:26:33.853+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
2022-02-01 09:26:33.854+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.maxDirectMemory: 2086666240 bytes
2022-02-01 09:26:33.855+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: 1024
2022-02-01 09:26:33.862+00:00 | main | DEBUG | CleanerJava9 | java.nio.ByteBuffer.cleaner(): available
2022-02-01 09:26:33.863+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.noPreferDirect: false
2022-02-01 09:26:33.880+00:00 | main | DEBUG | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 8
2022-02-01 09:26:33.894+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2022-02-01 09:26:33.894+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2022-02-01 09:26:33.901+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.noKeySetOptimization: false
2022-02-01 09:26:33.901+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
2022-02-01 09:26:33.908+00:00 | main | DEBUG | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available
2022-02-01 09:26:33.911+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@6f231ced
2022-02-01 09:26:33.912+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@f5b6e78
2022-02-01 09:26:33.912+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@4b4eced1
2022-02-01 09:26:33.912+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@71926a36
2022-02-01 09:26:33.912+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@216e9ca3
2022-02-01 09:26:33.912+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@75120e58
2022-02-01 09:26:33.913+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@48976e6d
2022-02-01 09:26:33.933+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@2a367e93
2022-02-01 09:26:33.934+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3fba233d
2022-02-01 09:26:33.968+00:00 | main | DEBUG | DefaultDnsServerAddressStreamProvider | Default DNS servers: [/127.0.0.53:53] (sun.net.dns.ResolverConfiguration)
2022-02-01 09:26:33.974+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv4Stack: false
2022-02-01 09:26:33.975+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv6Addresses: false
2022-02-01 09:26:33.976+00:00 | main | DEBUG | NetUtilInitializations | Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
2022-02-01 09:26:33.977+00:00 | main | DEBUG | NetUtil | /proc/sys/net/core/somaxconn: 4096
2022-02-01 09:26:34.022+00:00 | main | INFO  | Besu | Static Nodes file = /mnt/alastria-node-besu/validator/static-nodes.json
2022-02-01 09:26:34.023+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-02-01 09:26:34.023+00:00 | main | TRACE | Besu | Static Nodes = []
2022-02-01 09:26:34.026+00:00 | main | INFO  | Besu | Security Module: localfile
2022-02-01 09:26:34.045+00:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /mnt/alastria-node-besu/validator
2022-02-01 09:26:34.106+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /mnt/alastria-node-besu/validator. Version 1
2022-02-01 09:26:34.390+00:00 | main | INFO  | KeyPairUtil | Loaded public key 0xbfc87e067c71f73f98527126d9a63d215e6efc92f4955656c5f1d5e498fe8d69bb5d096304abc0afcd6ff8dc25155dbece7af33ba74b8604c0574cda30a2376f from /mnt/alastria-node-besu/validator/keys/besu/key
2022-02-01 09:26:34.556+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Byzantium: 0]
2022-02-01 09:26:34.687+00:00 | main | DEBUG | BesuPluginContextImpl | Plugin startup complete.
2022-02-01 09:26:34.690+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-02-01 09:26:34.714+00:00 | main | DEBUG | RlpxAgent | Using default NettyConnectionInitializer
2022-02-01 09:26:34.717+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@66d25ba9
2022-02-01 09:26:34.718+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@5efe47fd
2022-02-01 09:26:34.718+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@739831a4
2022-02-01 09:26:34.718+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@7e3236d
2022-02-01 09:26:34.718+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@38a4e2b0
2022-02-01 09:26:34.719+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@14c99bf6
2022-02-01 09:26:34.719+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@266e9dda
2022-02-01 09:26:34.719+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@38883a31
2022-02-01 09:26:34.719+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@27a6fef2
2022-02-01 09:26:34.720+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@7fe8c7db
2022-02-01 09:26:34.720+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@2dba05b1
2022-02-01 09:26:34.790+00:00 | main | TRACE | MetricsService | Creating metrics service PROMETHEUS
2022-02-01 09:26:34.792+00:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2022-02-01 09:26:34.793+00:00 | main | INFO  | MetricsHttpService | Starting metrics http service on 0.0.0.0:9545
2022-02-01 09:26:34.828+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numHeapArenas: 8
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numDirectArenas: 8
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.pageSize: 8192
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxOrder: 11
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.chunkSize: 16777216
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.smallCacheSize: 256
2022-02-01 09:26:34.829+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.normalCacheSize: 64
2022-02-01 09:26:34.830+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-02-01 09:26:34.830+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimInterval: 8192
2022-02-01 09:26:34.830+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-02-01 09:26:34.830+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.useCacheForAllThreads: true
2022-02-01 09:26:34.830+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-02-01 09:26:34.852+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.processId: 529324 (auto-detected)
2022-02-01 09:26:34.854+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.machineId: 60:45:bd:ff:fe:8c:66:23 (auto-detected)
2022-02-01 09:26:34.872+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.allocator.type: pooled
2022-02-01 09:26:34.872+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.threadLocalDirectBufferSize: 0
2022-02-01 09:26:34.872+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-02-01 09:26:34.884+00:00 | vert.x-acceptor-thread-0 | TRACE | NetServerImpl | Net server listening on 0.0.0.0:/0:0:0:0:0:0:0:0:9545
2022-02-01 09:26:34.885+00:00 | vert.x-eventloop-thread-1 | INFO  | MetricsHttpService | Metrics service started and listening on 9545:9545
2022-02-01 09:26:34.886+00:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2022-02-01 09:26:34.886+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-02-01 09:26:34.893+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0:0:0:0:0:0:0:0:30303.
2022-02-01 09:26:34.894+00:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2022-02-01 09:26:34.931+00:00 | vert.x-eventloop-thread-1 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0:0:0:0:0:0:0:0 and port=30303
2022-02-01 09:26:34.932+00:00 | vert.x-eventloop-thread-1 | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0:0:0:0:0:0:0:0:30303
2022-02-01 09:26:34.941+00:00 | main | ERROR | Runner | Startup failed java.lang.NullPointerException
2022-02-01 09:26:34.954+00:00 | Thread-1 | DEBUG | BesuPluginContextImpl | Plugin shutdown complete.
2022-02-01 09:26:34.964+00:00 | Thread-1 | ERROR | Besu | Failed to stop Besu

And when discovery is set false, it doesn't crash.

2022-02-01 09:42:22.185+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for /com/sun/jna/linux-x86-64/libjnidispatch.so
2022-02-01 09:42:22.188+00:00 | main | DEBUG | Native | Found library resource at jar:file:/mnt/alastria-node-besu/versionesBesu/besu-21.10.9/lib/jna-5.8.0.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
2022-02-01 09:42:22.189+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna4757246696853343800.tmp
2022-02-01 09:42:22.191+00:00 | main | DEBUG | Native | Trying /home/x281921/.cache/JNA/temp/jna4757246696853343800.tmp
2022-02-01 09:42:22.191+00:00 | main | DEBUG | Native | Found jnidispatch at /home/x281921/.cache/JNA/temp/jna4757246696853343800.tmp
2022-02-01 09:42:22.211+00:00 | main | DEBUG | NativeLibrary | Looking for library 'secp256k1'
2022-02-01 09:42:22.212+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-02-01 09:42:22.212+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-02-01 09:42:22.213+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-02-01 09:42:22.213+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]
2022-02-01 09:42:22.214+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-02-01 09:42:22.214+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-02-01 09:42:22.215+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-02-01 09:42:22.218+00:00 | main | DEBUG | NativeLibrary | Trying /usr/lib/x86_64-linux-gnu/libsecp256k1.so.0
2022-02-01 09:42:22.219+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /usr/lib/x86_64-linux-gnu/libsecp256k1.so.0
2022-02-01 09:42:22.238+00:00 | main | DEBUG | NativeLibrary | Looking for library 'eth_pairings'
2022-02-01 09:42:22.239+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-02-01 09:42:22.239+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-02-01 09:42:22.239+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-02-01 09:42:22.239+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]
2022-02-01 09:42:22.240+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-02-01 09:42:22.240+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-02-01 09:42:22.240+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-02-01 09:42:22.243+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for eth_pairings
2022-02-01 09:42:22.244+00:00 | main | DEBUG | Native | Found library resource at jar:file:/mnt/alastria-node-besu/versionesBesu/besu-21.10.9/lib/bls12-381-0.3.0.jar!/linux-x86-64/libeth_pairings.so
2022-02-01 09:42:22.244+00:00 | main | DEBUG | Native | Extracting library to /home/x281921/.cache/JNA/temp/jna5430367098532675878.tmp
2022-02-01 09:42:22.269+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /home/x281921/.cache/JNA/temp/jna5430367098532675878.tmp
2022-02-01 09:42:22.270+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-02-01 09:42:22.270+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-02-01 09:42:22.273+00:00 | main | INFO  | Besu | Starting Besu version: besu/v21.10.9/linux-x86_64/openjdk-java-11
2022-02-01 09:42:22.277+00:00 | main | TRACE | MetricsSystemFactory | Creating a metric system with PROMETHEUS
2022-02-01 09:42:22.297+00:00 | main | DEBUG | LoggerFactory | Using io.vertx.core.logging.Log4j2LogDelegateFactory
2022-02-01 09:42:22.326+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple
2022-02-01 09:42:22.326+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.targetRecords: 4
2022-02-01 09:42:22.341+00:00 | main | DEBUG | PlatformDependent0 | -Dio.netty.noUnsafe: false
2022-02-01 09:42:22.341+00:00 | main | DEBUG | PlatformDependent0 | Java version: 11
2022-02-01 09:42:22.343+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
2022-02-01 09:42:22.344+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
2022-02-01 09:42:22.344+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Buffer.address: available
2022-02-01 09:42:22.345+00:00 | main | DEBUG | PlatformDependent0 | direct buffer constructor: available
2022-02-01 09:42:22.345+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Bits.unaligned: available, true
2022-02-01 09:42:22.347+00:00 | main | DEBUG | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): available
2022-02-01 09:42:22.348+00:00 | main | DEBUG | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
2022-02-01 09:42:22.348+00:00 | main | DEBUG | PlatformDependent | sun.misc.Unsafe: available
2022-02-01 09:42:22.348+00:00 | main | DEBUG | PlatformDependent | maxDirectMemory: 2086666240 bytes (maybe)
2022-02-01 09:42:22.349+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2022-02-01 09:42:22.349+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
2022-02-01 09:42:22.350+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.maxDirectMemory: 2086666240 bytes
2022-02-01 09:42:22.350+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: 1024
2022-02-01 09:42:22.351+00:00 | main | DEBUG | CleanerJava9 | java.nio.ByteBuffer.cleaner(): available
2022-02-01 09:42:22.351+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.noPreferDirect: false
2022-02-01 09:42:22.364+00:00 | main | DEBUG | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 8
2022-02-01 09:42:22.378+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2022-02-01 09:42:22.378+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2022-02-01 09:42:22.398+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.noKeySetOptimization: false
2022-02-01 09:42:22.398+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
2022-02-01 09:42:22.407+00:00 | main | DEBUG | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available
2022-02-01 09:42:22.411+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@6f231ced
2022-02-01 09:42:22.412+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@f5b6e78
2022-02-01 09:42:22.412+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@4b4eced1
2022-02-01 09:42:22.412+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@71926a36
2022-02-01 09:42:22.413+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@216e9ca3
2022-02-01 09:42:22.413+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@75120e58
2022-02-01 09:42:22.413+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@48976e6d
2022-02-01 09:42:22.433+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@2a367e93
2022-02-01 09:42:22.434+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3fba233d
2022-02-01 09:42:22.462+00:00 | main | DEBUG | DefaultDnsServerAddressStreamProvider | Default DNS servers: [/127.0.0.53:53] (sun.net.dns.ResolverConfiguration)
2022-02-01 09:42:22.467+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv4Stack: false
2022-02-01 09:42:22.467+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv6Addresses: false
2022-02-01 09:42:22.469+00:00 | main | DEBUG | NetUtilInitializations | Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
2022-02-01 09:42:22.469+00:00 | main | DEBUG | NetUtil | /proc/sys/net/core/somaxconn: 4096
2022-02-01 09:42:22.499+00:00 | main | WARN  | Besu | Discovery disabled: bootnodes will be ignored.
2022-02-01 09:42:22.503+00:00 | main | INFO  | Besu | Static Nodes file = /mnt/alastria-node-besu/validator/static-nodes.json
2022-02-01 09:42:22.504+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-02-01 09:42:22.504+00:00 | main | TRACE | Besu | Static Nodes = []
2022-02-01 09:42:22.506+00:00 | main | INFO  | Besu | Security Module: localfile
2022-02-01 09:42:22.519+00:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /mnt/alastria-node-besu/validator
2022-02-01 09:42:22.562+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /mnt/alastria-node-besu/validator. Version 1
2022-02-01 09:42:22.776+00:00 | main | WARN  | Besu | Discovery disabled: bootnodes will be ignored.
2022-02-01 09:42:22.796+00:00 | main | INFO  | KeyPairUtil | Loaded public key 0xbfc87e067c71f73f98527126d9a63d215e6efc92f4955656c5f1d5e498fe8d69bb5d096304abc0afcd6ff8dc25155dbece7af33ba74b8604c0574cda30a2376f from /mnt/alastria-node-besu/validator/keys/besu/key
2022-02-01 09:42:22.927+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Byzantium: 0]
2022-02-01 09:42:23.040+00:00 | main | DEBUG | BesuPluginContextImpl | Plugin startup complete.
2022-02-01 09:42:23.044+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-02-01 09:42:23.068+00:00 | main | DEBUG | RlpxAgent | Using default NettyConnectionInitializer
2022-02-01 09:42:23.071+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@25974207
2022-02-01 09:42:23.072+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@195113de
2022-02-01 09:42:23.072+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3ebc955b
2022-02-01 09:42:23.072+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@21a46ff1
2022-02-01 09:42:23.072+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@11b5f4e2
2022-02-01 09:42:23.073+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@6bcae9
2022-02-01 09:42:23.073+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@5aa781f2
2022-02-01 09:42:23.073+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@58feb6b0
2022-02-01 09:42:23.073+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@66d25ba9
2022-02-01 09:42:23.074+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3830f918
2022-02-01 09:42:23.074+00:00 | main | TRACE | NioEventLoop | instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@5efe47fd
2022-02-01 09:42:23.146+00:00 | main | TRACE | MetricsService | Creating metrics service PROMETHEUS
2022-02-01 09:42:23.148+00:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2022-02-01 09:42:23.149+00:00 | main | INFO  | MetricsHttpService | Starting metrics http service on 0.0.0.0:9545
2022-02-01 09:42:23.184+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numHeapArenas: 8
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numDirectArenas: 8
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.pageSize: 8192
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxOrder: 11
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.chunkSize: 16777216
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.smallCacheSize: 256
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.normalCacheSize: 64
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-02-01 09:42:23.185+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimInterval: 8192
2022-02-01 09:42:23.186+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-02-01 09:42:23.186+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.useCacheForAllThreads: true
2022-02-01 09:42:23.186+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-02-01 09:42:23.207+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.processId: 535909 (auto-detected)
2022-02-01 09:42:23.209+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.machineId: 60:45:bd:ff:fe:8c:66:23 (auto-detected)
2022-02-01 09:42:23.225+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.allocator.type: pooled
2022-02-01 09:42:23.226+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.threadLocalDirectBufferSize: 0
2022-02-01 09:42:23.226+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-02-01 09:42:23.238+00:00 | vert.x-acceptor-thread-0 | TRACE | NetServerImpl | Net server listening on 0.0.0.0:/0:0:0:0:0:0:0:0:9545
2022-02-01 09:42:23.240+00:00 | vert.x-eventloop-thread-1 | INFO  | MetricsHttpService | Metrics service started and listening on 9545:9545
2022-02-01 09:42:23.240+00:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2022-02-01 09:42:23.241+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-02-01 09:42:23.247+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0:0:0:0:0:0:0:0:30303.
2022-02-01 09:42:23.248+00:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://bfc87e067c71f73f98527126d9a63d215e6efc92f4955656c5f1d5e498fe8d69bb5d096304abc0afcd6ff8dc25155dbece7af33ba74b8604c0574cda30a2376f@127.0.0.1:30303?discport=0
2022-02-01 09:42:23.249+00:00 | main | INFO  | DefaultP2PNetwork | Node address 0xe00c3fc6a4dd9a29f1cbae093a3b066a1ac318f9
2022-02-01 09:42:23.251+00:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
2022-02-01 09:42:23.252+00:00 | main | INFO  | FullSyncDownloader | Starting full sync.
2022-02-01 09:42:23.253+00:00 | main | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:23.257+00:00 | main | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:23.279+00:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2022-02-01 09:42:23.281+00:00 | main | DEBUG | JsonRpcHttpService | max number of active connections 80
2022-02-01 09:42:23.295+00:00 | vert.x-acceptor-thread-0 | TRACE | NetServerImpl | Net server listening on 0.0.0.0:/0:0:0:0:0:0:0:0:8545
2022-02-01 09:42:23.296+00:00 | vert.x-eventloop-thread-1 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2022-02-01 09:42:23.298+00:00 | main | INFO  | WebSocketService | Starting Websocket service on 127.0.0.1:8546
2022-02-01 09:42:23.301+00:00 | vert.x-acceptor-thread-0 | TRACE | NetServerImpl | Net server listening on 127.0.0.1:/127.0.0.1:8546
2022-02-01 09:42:23.301+00:00 | vert.x-eventloop-thread-1 | INFO  | WebSocketService | Websocket service started and listening on 127.0.0.1:8546
2022-02-01 09:42:23.304+00:00 | main | INFO  | Runner | Ethereum main loop is up.
2022-02-01 09:42:23.307+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-02-01 09:42:23.308+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /mnt/alastria-node-besu/validator/caches
x281921@sanbesu3:/mnt/alastria-node-besu/validator$ tail -f /mnt/alastria-node-besu/validator/logs/besu.log
2022-02-01 09:42:23.298+00:00 | main | INFO  | WebSocketService | Starting Websocket service on 127.0.0.1:8546
2022-02-01 09:42:23.301+00:00 | vert.x-acceptor-thread-0 | TRACE | NetServerImpl | Net server listening on 127.0.0.1:/127.0.0.1:8546
2022-02-01 09:42:23.301+00:00 | vert.x-eventloop-thread-1 | INFO  | WebSocketService | Websocket service started and listening on 127.0.0.1:8546
2022-02-01 09:42:23.304+00:00 | main | INFO  | Runner | Ethereum main loop is up.
2022-02-01 09:42:23.307+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-02-01 09:42:23.308+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /mnt/alastria-node-besu/validator/caches
2022-02-01 09:42:28.265+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:28.265+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:33.266+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:33.267+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:38.267+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:38.268+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:43.268+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:43.269+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:48.270+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:48.270+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:53.251+00:00 | pool-7-thread-1 | TRACE | DefaultP2PNetwork | Initiating connections to discovered peers.
2022-02-01 09:42:53.271+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:53.272+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:42:58.272+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:42:58.273+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:43:03.274+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:43:03.274+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-02-01 09:43:08.275+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers: 0
2022-02-01 09:43:08.275+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.

Thanks in advance

mark-terry commented 2 years ago

Hi @jorgesjv, Which milestone blocks are set in your genesis.json? There's a chance the behaviour you've noted might be triggered by misconfigured milestone blocks.

Cheers.

jorgesjv commented 2 years ago

Hi @mark-terry thanks for the answer.

These are the milestone blocks from my genesis.json.

  "config": {
    "chainId": 2022,
    "homesteadBlock": 0,
    "eip150Block": 0,
    "eip155Block": 0,
    "eip158Block": 0,
    "byzantiumBlock": 0,
    "qbft": {
      "epochlength": 30000,
      "blockperiodseconds": 2,
      "requesttimeoutseconds": 10
    }
  }

Thanks in advance

mark-terry commented 2 years ago

Hi @jorgesjv, I can see what's causing the problem.

Have you got compatibility-eth64-forkid-enabled=true deliberately enabled in your configuration? You mentioned you're using version 21.10.9 - per the documentation this item does not need to be enabled unless this node is on a network with nodes that are running Besu version 1.4 or earlier.

I've identified a bug that will throw an NPE if compatibility-eth64-forkid-enabled=true is set and there are no non-zero milestone blocks specified in the genesis. I'll get a fix out ASAP for it.

In the meantime, could you tell us whether you're able to run your network with compatibility-eth64-forkid-enabled=false and whether that resolves the issue?

jorgesanjose commented 2 years ago

Hi @mark-terry.

I run the Besu node with compatibility-eth64-forkid-enabled=false like you said, and currently, it does not crash. So probably that was the problem. Previously, we had old Besu version, so it was set to true.

Thanks a lot!