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 806 forks source link

Kubernetes Nat Manager do not print exception message (maybe is throwing a exception without message) #3787

Open tomasouza opened 2 years ago

tomasouza commented 2 years ago

Description

As an Developer, I want to know what is the issue when starting nodes on kubernetes nat manager so that I can read what is going on with the exception raised.

Acceptance Criteria

When running besu on kubernetes, the message bring me somenthing useful.

Steps to Reproduce (Bug)

  1. Create a EKS cluster on AWS
  2. Create a Service of type load balancer with the configs in https://besu.hyperledger.org/en/stable/Tutorials/Kubernetes/Nat-Manager-Kubernetes/
  3. The documentation explicits three diferente exceptions and the solutions: Service not found, Forbidden and Ingress not found.

But in my case the message is: 2022-05-04 19:51:57.105+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used 2022-05-04 19:51:57.106+00:00 | main | INFO | NetworkRunner | Starting Network.

There is no exception message following the reason: Expected behavior: I expect when the exception have no message, to send its stacktrace at least. This message is displayed on debug, maybe the stacktrace is ok?

Actual behavior: The message is printed without de exception message, or the exception raised don't have a message 2022-05-04 19:51:57.105+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used 2022-05-04 19:51:57.106+00:00 | main | INFO | NetworkRunner | Starting Network.

Frequency: I still coudn't get peer discovery working

Versions (Add all that apply)

Smart contract information (If you're reporting an issue arising from deploying or calling a smart contract, please supply related information)

Additional Information (Add any of the following or anything else that may be relevant)

joshuafernandes commented 2 years ago

Hi @vjtom Thanks for submitting this. Could you post your service and pod manifest here please for us to reproduce this behaviour

We've got a repo dedicated to k8s available here https://github.com/ConsenSys/quorum-kubernetes as well, the repo has been updated recently and the docs are in the process of being updated https://github.com/hyperledger/besu-docs/pull/1030

Cheers

tomasouza commented 2 years ago

Thank you @joshuafernandes for the reply,

First I have tried with the service exactly like this doc: https://besu.hyperledger.org/en/stable/Tutorials/Kubernetes/Nat-Manager-Kubernetes/

Here is the manifest

apiVersion: v1
kind: Service
metadata:
  labels:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: "1.0.0"
  name: besu
spec:
  ports:
  - name: "json-rpc"
    port: 8545
    targetPort: 8545
  - name: "rlpx"
    port: 30303
    targetPort: 30303
  selector:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: "1.0.0"
  type: LoadBalancer

And a deployment I have tried like this:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: besu
spec:
  selector:
    matchLabels:
      app.kubernetes.io/name: besu
      app.kubernetes.io/release: "1.0.0"        
  replicas: 1
  strategy: {}
  template:
    metadata:
      creationTimestamp: null
      labels:
        app.kubernetes.io/name: besu
        app.kubernetes.io/release: "1.0.0"
    spec:
      containers:
      - name: besu-validator-0
        image: ${IMAGE_TAG}
        imagePullPolicy: Always
        ports:
        - containerPort: 30303
        env:
        - name: BESU_P2P_PORT
          value: "30303"
        - name: BESU_NETWORK_ID
          value: "999666666"
        - name: BESU_IDENTITY
          value: "Validator-0"
        - name: BESU_CONFIG_FILE
          value: "/usr/local/bin/config/bootnode/config.toml"
        - name: BESU_NODE_PRIVATE_KEY_FILE
          value: "/usr/local/bin/config/bootnode/keyPair/key"
        - name: BESU_DISCOVERY_ENABLED
          value: "true" 
        - name: BESU_MINER_COINBASE
          value: "0x79d007ecd184ed3e4dc..."
        resources:
          limits:
            memory: 8Gi
          requests:
            memory: 4Gi`

I have altered the besu_miner_coinbase and filled with ... but there is a actual besu_miner_coinbase in this variable. Thank you so much for your time!

joshuafernandes commented 2 years ago

Hi @vjtom I think some of the selector labels are a bit off?

I've done the following without issue:

--- 
#service.yaml
---
apiVersion: v1
kind: Service
metadata:
  labels:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: "1.0.0"
  name: besu
spec:
  type: NodePort
  ports:
  - name: "json-rpc"
    port: 8545
    targetPort: 8545
    nodePort: 30045
  - name: "rlpx"
    port: 30303
    targetPort: 30303
    nodePort: 30046
  selector:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: "1.0.0"
# deployment
---
apiVersion: v1
kind: ConfigMap
metadata:
  name: besu-config
  labels:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: 1.0.0
data:
  BESU_LOGGING: "INFO"
  BESU_NETWORK: "dev"
  BESU_P2P_ENABLED: "true"
  BESU_RPC_HTTP_ENABLED: "true"
  BESU_RPC_HTTP_APIS: "eth,net,web3,debug,admin"
  KUBE_CONFIG_PATH: "/opt/besu/shared/kube-config"
---
apiVersion: apps/v1
kind: Deployment
metadata:
  name: besu
  labels:
    app.kubernetes.io/name: besu
    app.kubernetes.io/release: "1.0.0"
spec:
  replicas: 1
  selector:
    matchLabels:
      app.kubernetes.io/name: besu
      app.kubernetes.io/release: "1.0.0"
  strategy: {}
  template:
    metadata:
      creationTimestamp: null
      labels:
        app.kubernetes.io/name: besu
        app.kubernetes.io/release: "1.0.0"
    spec:
      containers:
      - name: besu
        image: "hyperledger/besu:latest"
        imagePullPolicy: Always
        ports:
          - containerPort: 8545
          - containerPort: 30303
        envFrom:
        - configMapRef:
            name: besu-config
        env:
        - name: BESU_P2P_PORT
          value: "30303"
        - name: BESU_RPC_HTTP_API
          value: "ETH,NET,WEB3"
      restartPolicy: Always
status: {}

which gave me the logs below:

Setting logging level to INFO
2022-05-09 01:02:54.127+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-05-09 01:02:54.129+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-05-09 01:02:54.132+00:00 | main | INFO  | Besu | Starting Besu version: besu/v22.4.0/linux-x86_64/openjdk-java-11
2022-05-09 01:02:54.379+00:00 | main | INFO  | Besu | Static Nodes file = /opt/besu/static-nodes.json
2022-05-09 01:02:54.381+00:00 | main | INFO  | StaticNodesParser | StaticNodes file /opt/besu/static-nodes.json does not exist, no static connections will be created.
2022-05-09 01:02:54.381+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-05-09 01:02:54.385+00:00 | main | INFO  | Besu | Security Module: localfile
2022-05-09 01:02:54.406+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | No existing database detected at /opt/besu. Using version 1
2022-05-09 01:02:54.871+00:00 | main | INFO  | KeyPairUtil | Generated new secp256k1 public key 0x90c51f84b2d013e1d30c7059b70425046d2562667f17d598a9e97cf733515aa3b32331109479db35dc277a7af01701ee5a10762da5cf38676adfe31ace916ef6 and stored it to /opt/besu/key
2022-05-09 01:02:54.978+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Petersburg: 0]
2022-05-09 01:02:55.063+00:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is not present, creating initial sync phase for PoW
2022-05-09 01:02:55.086+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-05-09 01:02:55.218+00:00 | main | INFO  | Runner | Starting external services ... 
2022-05-09 01:02:55.223+00:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2022-05-09 01:02:55.354+00:00 | vert.x-eventloop-thread-2 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2022-05-09 01:02:55.358+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-05-09 01:02:55.359+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /opt/besu/caches
2022-05-09 01:02:55.366+00:00 | main | INFO  | Runner | Starting Ethereum main loop ... 
2022-05-09 01:02:55.366+00:00 | main | INFO  | KubernetesNatManager | Starting kubernetes NAT manager.
2022-05-09 01:02:55.799+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-05-09 01:02:55.810+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0.0.0.0:30303.
2022-05-09 01:02:55.811+00:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2022-05-09 01:02:55.854+00:00 | vert.x-eventloop-thread-2 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0.0.0.0 and port=30303
tomasouza commented 2 years ago

Thank you so much for the effort to reproduce! If I run it in log level INFO I have the excatly same log as you, could you please post one in level DEBUG please? Im particular, this log that tells me that it did not succeed: 2022-05-04 19:51:57.105+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used

Looking at the code, it has a excpetion in this part: https://github.com/hyperledger/besu/blob/ed1329cf848a9d7858d039a55add810da3c428b5/nat/src/main/java/org/hyperledger/besu/nat/NatService.java

 /** Starts the manager or service. */
  public void start() {
    if (isNatEnvironment()) {
      try {
        getNatManager().orElseThrow().start();
      } catch (Exception e) {
        LOG.debug(
            "Nat manager failed to configure itself automatically due to the following reason : {}. {}",
            e.getMessage(),
            (fallbackEnabled) ? "NONE mode will be used" : "");
        if (fallbackEnabled) {
          disableNatManager();
        } else {
          throw new IllegalStateException(e.getMessage(), e);
        }
      }
    } else {
      LOG.info("No NAT environment detected so no service could be started");
    }
  }

I saw that it has a e.getMassage(), tha's why i created this issue, because it seams that the exception raised had no message to display. And now I don't know what is going on under the hood,

joshuafernandes commented 2 years ago

Hi @vjtom. Here's the logs at debug level.

Setting logging level to DEBUG
2022-05-09 21:53:30.732+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-05-09 21:53:30.735+00:00 | main | DEBUG | Native | Found library resource at jar:file:/opt/besu/lib/jna-5.10.0.jar!/com/sun/jna/linux-x86-64/libjnidispatch.so
2022-05-09 21:53:30.736+00:00 | main | DEBUG | Native | Extracting library to /opt/besu/.cache/JNA/temp/jna12789242962521903366.tmp
2022-05-09 21:53:30.739+00:00 | main | DEBUG | Native | Trying /opt/besu/.cache/JNA/temp/jna12789242962521903366.tmp
2022-05-09 21:53:30.740+00:00 | main | DEBUG | Native | Found jnidispatch at /opt/besu/.cache/JNA/temp/jna12789242962521903366.tmp
2022-05-09 21:53:30.761+00:00 | main | DEBUG | NativeLibrary | Looking for library 'secp256k1'
2022-05-09 21:53:30.761+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-05-09 21:53:30.762+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-05-09 21:53:30.762+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-05-09 21:53:30.762+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-05-09 21:53:30.763+00:00 | main | DEBUG | NativeLibrary | Trying libsecp256k1.so
2022-05-09 21:53:30.763+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libsecp256k1.so: cannot open shared object file: No such file or directory
2022-05-09 21:53:30.763+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-05-09 21:53:30.766+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for secp256k1
2022-05-09 21:53:30.767+00:00 | main | DEBUG | Native | Found library resource at jar:file:/opt/besu/lib/secp256k1-0.4.3.jar!/linux-x86-64/libsecp256k1.so
2022-05-09 21:53:30.768+00:00 | main | DEBUG | Native | Extracting library to /opt/besu/.cache/JNA/temp/jna17373199099199612682.tmp
2022-05-09 21:53:30.773+00:00 | main | DEBUG | NativeLibrary | Found library 'secp256k1' at /opt/besu/.cache/JNA/temp/jna17373199099199612682.tmp
2022-05-09 21:53:30.795+00:00 | main | DEBUG | NativeLibrary | Looking for library 'eth_pairings'
2022-05-09 21:53:30.796+00:00 | main | DEBUG | NativeLibrary | Adding paths from jna.library.path: null
2022-05-09 21:53:30.796+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-05-09 21:53:30.796+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-05-09 21:53:30.797+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-05-09 21:53:30.797+00:00 | main | DEBUG | NativeLibrary | Trying libeth_pairings.so
2022-05-09 21:53:30.797+00:00 | main | DEBUG | NativeLibrary | Loading failed with message: libeth_pairings.so: cannot open shared object file: No such file or directory
2022-05-09 21:53:30.797+00:00 | main | DEBUG | NativeLibrary | Looking for version variants
2022-05-09 21:53:30.799+00:00 | main | DEBUG | Native | Looking in classpath from jdk.internal.loader.ClassLoaders$AppClassLoader@5ffd2b27 for eth_pairings
2022-05-09 21:53:30.799+00:00 | main | DEBUG | Native | Found library resource at jar:file:/opt/besu/lib/bls12-381-0.4.3.jar!/linux-x86-64/libeth_pairings.so
2022-05-09 21:53:30.800+00:00 | main | DEBUG | Native | Extracting library to /opt/besu/.cache/JNA/temp/jna15860162713657879151.tmp
2022-05-09 21:53:30.831+00:00 | main | DEBUG | NativeLibrary | Found library 'eth_pairings' at /opt/besu/.cache/JNA/temp/jna15860162713657879151.tmp
2022-05-09 21:53:30.832+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-05-09 21:53:30.833+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-05-09 21:53:30.837+00:00 | main | INFO  | Besu | Starting Besu version: besu/v22.4.0/linux-x86_64/openjdk-java-11
2022-05-09 21:53:30.853+00:00 | main | DEBUG | LoggerFactory | Using io.vertx.core.logging.Log4j2LogDelegateFactory
2022-05-09 21:53:30.881+00:00 | main | DEBUG | PlatformDependent0 | -Dio.netty.noUnsafe: false
2022-05-09 21:53:30.882+00:00 | main | DEBUG | PlatformDependent0 | Java version: 11
2022-05-09 21:53:30.883+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.theUnsafe: available
2022-05-09 21:53:30.884+00:00 | main | DEBUG | PlatformDependent0 | sun.misc.Unsafe.copyMemory: available
2022-05-09 21:53:30.885+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Buffer.address: available
2022-05-09 21:53:30.885+00:00 | main | DEBUG | PlatformDependent0 | direct buffer constructor: available
2022-05-09 21:53:30.886+00:00 | main | DEBUG | PlatformDependent0 | java.nio.Bits.unaligned: available, true
2022-05-09 21:53:30.887+00:00 | main | DEBUG | PlatformDependent0 | jdk.internal.misc.Unsafe.allocateUninitializedArray(int): available
2022-05-09 21:53:30.888+00:00 | main | DEBUG | PlatformDependent0 | java.nio.DirectByteBuffer.<init>(long, int): available
2022-05-09 21:53:30.888+00:00 | main | DEBUG | PlatformDependent | sun.misc.Unsafe: available
2022-05-09 21:53:30.888+00:00 | main | DEBUG | PlatformDependent | maxDirectMemory: 8350859264 bytes (maybe)
2022-05-09 21:53:30.889+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2022-05-09 21:53:30.889+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.bitMode: 64 (sun.arch.data.model)
2022-05-09 21:53:30.890+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.maxDirectMemory: 8350859264 bytes
2022-05-09 21:53:30.890+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.uninitializedArrayAllocationThreshold: 1024
2022-05-09 21:53:30.891+00:00 | main | DEBUG | CleanerJava9 | java.nio.ByteBuffer.cleaner(): available
2022-05-09 21:53:30.891+00:00 | main | DEBUG | PlatformDependent | -Dio.netty.noPreferDirect: false
2022-05-09 21:53:30.897+00:00 | main | DEBUG | NativeLibraryLoader | -Dio.netty.native.workdir: /tmp (io.netty.tmpdir)
2022-05-09 21:53:30.897+00:00 | main | DEBUG | NativeLibraryLoader | -Dio.netty.native.deleteLibAfterLoading: true
2022-05-09 21:53:30.897+00:00 | main | DEBUG | NativeLibraryLoader | -Dio.netty.native.tryPatchShadedId: true
2022-05-09 21:53:30.897+00:00 | main | DEBUG | NativeLibraryLoader | -Dio.netty.native.detectNativeLibraryDuplicates: true
2022-05-09 21:53:30.905+00:00 | main | DEBUG | NativeLibraryLoader | Successfully loaded the library /tmp/libnetty_transport_native_epoll_x86_6414161487613564289994.so
2022-05-09 21:53:30.908+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv4Stack: false
2022-05-09 21:53:30.908+00:00 | main | DEBUG | NetUtil | -Djava.net.preferIPv6Addresses: false
2022-05-09 21:53:30.910+00:00 | main | DEBUG | NetUtilInitializations | Loopback interface: lo (lo, 127.0.0.1)
2022-05-09 21:53:30.911+00:00 | main | DEBUG | NetUtil | /proc/sys/net/core/somaxconn: 4096
2022-05-09 21:53:30.931+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.level: simple
2022-05-09 21:53:30.932+00:00 | main | DEBUG | ResourceLeakDetector | -Dio.netty.leakDetection.targetRecords: 4
2022-05-09 21:53:30.949+00:00 | main | DEBUG | MultithreadEventLoopGroup | -Dio.netty.eventLoopThreads: 16
2022-05-09 21:53:30.964+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2022-05-09 21:53:30.964+00:00 | main | DEBUG | InternalThreadLocalMap | -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2022-05-09 21:53:30.977+00:00 | main | DEBUG | PlatformDependent | org.jctools-core.MpscChunkedArrayQueue: available
2022-05-09 21:53:31.035+00:00 | main | DEBUG | DefaultDnsServerAddressStreamProvider | Default DNS servers: [/10.96.0.10:53] (sun.net.dns.ResolverConfiguration)
2022-05-09 21:53:31.109+00:00 | main | INFO  | Besu | Static Nodes file = /opt/besu/static-nodes.json
2022-05-09 21:53:31.111+00:00 | main | INFO  | StaticNodesParser | StaticNodes file /opt/besu/static-nodes.json does not exist, no static connections will be created.
2022-05-09 21:53:31.111+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-05-09 21:53:31.115+00:00 | main | INFO  | Besu | Security Module: localfile
2022-05-09 21:53:31.138+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | No existing database detected at /opt/besu. Using version 1
2022-05-09 21:53:31.712+00:00 | main | INFO  | KeyPairUtil | Generated new secp256k1 public key 0xf6fd3cddf389f340e1c323d3b3ff9b40bb9d081520d29e3388625c6ed6135ebbedae6e901e0b8ef1fdbc20ca79d9c30ce0be0af6694d50ac348ab77d337f1b6c and stored it to /opt/besu/key
2022-05-09 21:53:31.851+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Petersburg: 0]
2022-05-09 21:53:31.937+00:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is not present, creating initial sync phase for PoW
2022-05-09 21:53:31.954+00:00 | main | DEBUG | BesuPluginContextImpl | Plugin startup complete.
2022-05-09 21:53:31.960+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-05-09 21:53:31.994+00:00 | main | DEBUG | RlpxAgent | Using default NettyConnectionInitializer
2022-05-09 21:53:31.999+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.noKeySetOptimization: false
2022-05-09 21:53:31.999+00:00 | main | DEBUG | NioEventLoop | -Dio.netty.selectorAutoRebuildThreshold: 512
2022-05-09 21:53:32.093+00:00 | main | INFO  | Runner | Starting external services ... 
2022-05-09 21:53:32.094+00:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2022-05-09 21:53:32.094+00:00 | main | DEBUG | JsonRpcHttpService | max number of active connections 80
2022-05-09 21:53:32.151+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numHeapArenas: 16
2022-05-09 21:53:32.151+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.numDirectArenas: 16
2022-05-09 21:53:32.151+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.pageSize: 8192
2022-05-09 21:53:32.151+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxOrder: 11
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.chunkSize: 16777216
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.smallCacheSize: 256
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.normalCacheSize: 64
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimInterval: 8192
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-05-09 21:53:32.152+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.useCacheForAllThreads: true
2022-05-09 21:53:32.153+00:00 | main | DEBUG | PooledByteBufAllocator | -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-05-09 21:53:32.176+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.processId: 1 (auto-detected)
2022-05-09 21:53:32.177+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.machineId: 02:42:ac:ff:fe:11:00:03 (auto-detected)
2022-05-09 21:53:32.195+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.allocator.type: pooled
2022-05-09 21:53:32.195+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.threadLocalDirectBufferSize: 0
2022-05-09 21:53:32.195+00:00 | main | DEBUG | ByteBufUtil | -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-05-09 21:53:32.207+00:00 | vert.x-eventloop-thread-2 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2022-05-09 21:53:32.212+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-05-09 21:53:32.213+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /opt/besu/caches
2022-05-09 21:53:32.223+00:00 | main | DEBUG | BesuPluginContextImpl | Plugin startup complete.
2022-05-09 21:53:32.223+00:00 | main | INFO  | Runner | Starting Ethereum main loop ... 
2022-05-09 21:53:32.223+00:00 | main | INFO  | KubernetesNatManager | Starting kubernetes NAT manager.
2022-05-09 21:53:32.228+00:00 | main | DEBUG | KubernetesNatManager | Trying to update information using Kubernetes client SDK.
2022-05-09 21:53:32.595+00:00 | main | DEBUG | TaskRunner | Q10006 scheduled after  60 s : OkHttp 10.96.0.1 ping
2022-05-09 21:53:32.600+00:00 | main | DEBUG | Http2 | >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
2022-05-09 21:53:32.601+00:00 | main | DEBUG | Http2 | >> 0x00000000     6 SETTINGS      
2022-05-09 21:53:32.601+00:00 | main | DEBUG | Http2 | >> 0x00000000     4 WINDOW_UPDATE 
2022-05-09 21:53:32.602+00:00 | main | DEBUG | TaskRunner | Q10009 scheduled after   0 ?s: OkHttp 10.96.0.1
2022-05-09 21:53:32.603+00:00 | main | DEBUG | TaskRunner | Q10000 scheduled after   0 ?s: OkHttp ConnectionPool
2022-05-09 21:53:32.603+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10009 starting              : OkHttp 10.96.0.1
2022-05-09 21:53:32.604+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10000 starting              : OkHttp ConnectionPool
2022-05-09 21:53:32.605+00:00 | OkHttp ConnectionPool | DEBUG | TaskRunner | Q10000 run again after 300 s : OkHttp ConnectionPool
2022-05-09 21:53:32.606+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10000 finished run in   2 ms: OkHttp ConnectionPool
2022-05-09 21:53:32.609+00:00 | OkHttp 10.96.0.1 | DEBUG | Http2 | << 0x00000000    24 SETTINGS      
2022-05-09 21:53:32.610+00:00 | OkHttp 10.96.0.1 | DEBUG | TaskRunner | Q10006 scheduled after   0 ?s: OkHttp 10.96.0.1 applyAndAckSettings
2022-05-09 21:53:32.610+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10006 starting              : OkHttp 10.96.0.1 applyAndAckSettings
2022-05-09 21:53:32.610+00:00 | OkHttp 10.96.0.1 | DEBUG | Http2 | << 0x00000000     4 WINDOW_UPDATE 
2022-05-09 21:53:32.615+00:00 | OkHttp 10.96.0.1 | DEBUG | Http2 | << 0x00000000     0 SETTINGS      ACK
2022-05-09 21:53:32.619+00:00 | main | DEBUG | Http2 | >> 0x00000003   916 HEADERS       END_STREAM|END_HEADERS
2022-05-09 21:53:32.621+00:00 | OkHttp 10.96.0.1 applyAndAckSettings | DEBUG | TaskRunner | Q10008 scheduled after   0 ?s: OkHttp 10.96.0.1 onSettings
2022-05-09 21:53:32.622+00:00 | OkHttp 10.96.0.1 applyAndAckSettings | DEBUG | Http2 | >> 0x00000000     0 SETTINGS      ACK
2022-05-09 21:53:32.622+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10008 starting              : OkHttp 10.96.0.1 onSettings
2022-05-09 21:53:32.622+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10008 finished run in 420 ?s: OkHttp 10.96.0.1 onSettings
2022-05-09 21:53:32.622+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10006 finished run in  12 ms: OkHttp 10.96.0.1 applyAndAckSettings
2022-05-09 21:53:32.649+00:00 | OkHttp 10.96.0.1 | DEBUG | Http2 | << 0x00000003   224 HEADERS       END_HEADERS
2022-05-09 21:53:32.650+00:00 | OkHttp 10.96.0.1 | DEBUG | Http2 | << 0x00000003   286 DATA          END_STREAM
2022-05-09 21:53:32.657+00:00 | main | DEBUG | TaskRunner | Q10000 scheduled after   0 ?s: OkHttp ConnectionPool
2022-05-09 21:53:32.657+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10000 starting              : OkHttp ConnectionPool
2022-05-09 21:53:32.657+00:00 | OkHttp ConnectionPool | DEBUG | TaskRunner | Q10000 run again after 300 s : OkHttp ConnectionPool
2022-05-09 21:53:32.657+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10000 finished run in 588 ?s: OkHttp ConnectionPool
2022-05-09 21:53:32.658+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used
2022-05-09 21:53:32.658+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-05-09 21:53:32.671+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0.0.0.0:30303.
2022-05-09 21:53:32.672+00:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2022-05-09 21:53:32.702+00:00 | main | DEBUG | DefaultHostsFileEntriesResolver | -Dio.netty.hostsFileRefreshInterval: 0
2022-05-09 21:53:32.714+00:00 | vert.x-eventloop-thread-2 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0.0.0.0 and port=30303
2022-05-09 21:53:32.719+00:00 | vert.x-eventloop-thread-2 | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0.0.0.0:30303
2022-05-09 21:53:32.775+00:00 | vert.x-eventloop-thread-2 | INFO  | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=1, publicKey=0x02f6fd3cddf389f340e1c323d3b3ff9b40bb9d081520d29e3388625c6ed6135ebb, udpAddress=Optional[/127.0.0.1:30303], tcpAddress=Optional[/127.0.0.1:30303], asBase64=-Je4QGEWC8zxRECX9l99rd6udl7-VLY7EF4Jf2Ikl3uyxvnlfe5bRvq1f2vHfoc4d2RpMy-nKkQlARl-fHYg_TDCfuEBg2V0aMfGhHpznvGAgmlkgnY0gmlwhH8AAAGJc2VjcDI1NmsxoQL2_Tzd84nzQOHDI9Oz_5tAu50IFSDSnjOIYlxu1hNeu4N0Y3CCdl-DdWRwgnZf, nodeId=0x29b7ce913e1de14cc064410fcfe7da895c723ec66217c3eecf778f6b2ea99c89, customFields={tcp=30303, udp=30303, ip=0x7f000001, eth=[[0x7a739ef1, 0x]], id=V4, secp256k1=0x02f6fd3cddf389f340e1c323d3b3ff9b40bb9d081520d29e3388625c6ed6135ebb}}
2022-05-09 21:53:32.800+00:00 | vert.x-eventloop-thread-2 | DEBUG | RecursivePeerRefreshState | Start peer search.
2022-05-09 21:53:32.802+00:00 | vert.x-eventloop-thread-2 | DEBUG | RecursivePeerRefreshState | Skipping bonding round because no candidates are available
2022-05-09 21:53:32.803+00:00 | vert.x-eventloop-thread-2 | DEBUG | RecursivePeerRefreshState | Iterative peer search complete.  0 peers processed over 1 rounds.
2022-05-09 21:53:32.805+00:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://f6fd3cddf389f340e1c323d3b3ff9b40bb9d081520d29e3388625c6ed6135ebbedae6e901e0b8ef1fdbc20ca79d9c30ce0be0af6694d50ac348ab77d337f1b6c@127.0.0.1:30303
2022-05-09 21:53:32.805+00:00 | main | INFO  | DefaultP2PNetwork | Node address 0xcfe7da895c723ec66217c3eecf778f6b2ea99c89
2022-05-09 21:53:32.807+00:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
2022-05-09 21:53:32.809+00:00 | main | INFO  | FullSyncDownloader | Starting full sync.
2022-05-09 21:53:32.810+00:00 | main | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 0
2022-05-09 21:53:32.812+00:00 | main | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2022-05-09 21:53:32.817+00:00 | main | INFO  | Runner | Ethereum main loop is up.

@matkt does the above look right mate?

joshuafernandes commented 2 years ago

@vjtom what happens when you manually set the NAT manager mode? https://besu.hyperledger.org/en/latest/Tutorials/Kubernetes/Nat-Manager-Kubernetes/#automatic-detection-errors

tomasouza commented 2 years ago

Look, your log is like mine, it also printed the part 2022-05-09 21:53:32.658+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used 2022-05-09 21:53:32.658+00:00 | main | INFO | NetworkRunner | Starting Network.

What do you mean setting manually? I have tried just changing the NAT modes, if you may guide me I can try it.

joshuafernandes commented 2 years ago

Set the cli options/env manually as per https://besu.hyperledger.org/en/latest/HowTo/Find-and-Connect/Specifying-NAT/ and see what you get.

tomasouza commented 2 years ago

This I Already done! The same happens in AUTO or KUBERNETES.

joshuafernandes commented 2 years ago

:+1: @matkt could you have a look please - am not sure why this is happening

matkt commented 2 years ago

looking at the log it seems it comes from this line https://github.com/hyperledger/besu/blame/ed1329cf848a9d7858d039a55add810da3c428b5/nat/src/main/java/org/hyperledger/besu/nat/kubernetes/KubernetesNatManager.java#L81 I also saw a modification of this code 4 month ago @joshuafernandes have you already managed to get this version to work recently?

joshuafernandes commented 2 years ago

Hi @matkt not been able to mate. It seems that the message re failing is hidden in debug - might be worth putting that in info too? Our charts in quorum-kubernetes use CNI for networking so we bypass this so to speak. The most recent attempt I did of this was above here where it fails silently. I'll try an older version and see how far I get mate

matkt commented 2 years ago

OK, thanks. because I have serious doubts about the last modification of 4 months ago which precisely affects the library

joshuafernandes commented 2 years ago

Hi @matkt seems like the exception piece broke at 21.10.7

Ran the above files on minikube and upto 21.10.6 I get a reason, from 21.10.7 its a null value

2022-05-17 21:45:13.631+00:00 | OkHttp ConnectionPool | DEBUG | TaskRunner | Q10000 run again after 300 s : OkHttp ConnectionPool
2022-05-17 21:45:13.631+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : . NONE mode will be used
2022-05-17 21:45:13.631+00:00 | OkHttp TaskRunner | DEBUG | TaskRunner | Q10000 finished run in 619 ?s: OkHttp ConnectionPool

21.10.6
2022-05-17 21:53:50.534+00:00 | main | INFO  | KubernetesNatManager | Starting kubernetes NAT manager.
2022-05-17 21:53:50.548+00:00 | main | DEBUG | KubernetesNatManager | Trying to update information using Kubernetes client SDK.
2022-05-17 21:53:50.860+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : Forbidden. NONE mode will be used
2022-05-17 21:53:50.860+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-05-17 21:53:50.879+00:00 | main | DEBUG | DefaultChannelId | -Dio.netty.processId: 1 (auto-detected)

21.10.4
2022-05-17 21:52:31.502+00:00 | main | INFO  | KubernetesNatManager | Starting kubernetes NAT manager.
2022-05-17 21:52:31.516+00:00 | main | DEBUG | KubernetesNatManager | Trying to update information using Kubernetes client SDK.
2022-05-17 21:52:31.825+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : Forbidden. NONE mode will be used
2022-05-17 21:52:31.825+00:00 | main | INFO  | NetworkRunner | Starting Network.

21.10.1
2022-05-17 21:48:15.643+00:00 | main | DEBUG | KubernetesNatManager | Trying to update information using Kubernetes client SDK.
2022-05-17 21:48:15.928+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : Forbidden. NONE mode will be used
2022-05-17 21:48:15.928+00:00 | main | INFO  | NetworkRunner | Starting Network.

21.7.4
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
2022-05-17 21:50:54.590+00:00 | main | DEBUG | KubernetesNatManager | Trying to update information using Kubernetes client SDK.
2022-05-17 21:50:54.853+00:00 | main | DEBUG | NatService | Nat manager failed to configure itself automatically due to the following reason : Forbidden. NONE mode will be used
2022-05-17 21:50:54.854+00:00 | main | INFO  | NetworkRunner | Starting Network.
matkt commented 2 years ago

Hum, ok so it's just an exception issue. I will check why we have this kind of modification on this part