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

tomasouza · 2022-05-04T20:42:24Z

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)

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

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?

Frequency: I still coudn't get peer discovery working

Versions (Add all that apply)

Software version: 22.4.0
OS Name & Version: [cat /etc/*release]
NAME="Amazon Linux"
VERSION="2"
ID="amzn"
ID_LIKE="centos rhel fedora"
VERSION_ID="2"
PRETTY_NAME="Amazon Linux 2"
ANSI_COLOR="0;33"
CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2"
HOME_URL="https://amazonlinux.com/"
Amazon Linux release 2 (Karoo)
Kernel Version: [uname -a]
Linux ip-172-24-26-123.sa-east-1.compute.internal 5.4.186-102.354.amzn2.x86_64 Update Jenkins Build for Pantheon → Besu considerations #1 SMP Tue Mar 29 23:49:00 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Docker Version: [docker version]
Client:
Version: 20.10.13
API version: 1.41
Go version: go1.16.15
Git commit: a224086
Built: Thu Mar 31 19:20:32 2022
OS/Arch: linux/amd64
Context: default
Experimental: true
Cloud VM, type, size: [Amazon Web Services t3a-2xlarge]

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

Solidity version [solc --version]
Repo with minimal set of deployable/reproducible contract code - please provide a link
Please include specifics on how you are deploying/calling the contract
Have you reproduced the issue on other eth clients

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

Besu setup info - genesis file, config options
System info - memory, CPU

The text was updated successfully, but these errors were encountered:

joshuafernandes · 2022-05-05T02:42:36Z

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 hyperledger/besu-docs#1030

Cheers

tomasouza · 2022-05-05T15:53:36Z

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 · 2022-05-09T01:06:07Z

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 · 2022-05-09T20:34:06Z

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 · 2022-05-09T22:02:26Z

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 · 2022-05-09T22:07:42Z

@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 · 2022-05-09T22:11:01Z

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

joshuafernandes · 2022-05-09T22:15:53Z

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 · 2022-05-09T22:18:33Z

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

joshuafernandes · 2022-05-09T22:19:55Z

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

matkt · 2022-05-10T08:00:57Z

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 · 2022-05-16T21:19:48Z

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 · 2022-05-17T06:56:06Z

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

joshuafernandes · 2022-05-17T21:56:19Z

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 · 2022-05-23T06:57:05Z

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

hyperledger#3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

#4023) #3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

hyperledger#4023) hyperledger#3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

antonydenyer added a commit to antonydenyer/besu that referenced this issue Jun 28, 2022

Print full exception when NatService fails to configure automaticially

697b86a

hyperledger#3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

antonydenyer mentioned this issue Jun 28, 2022

Print full exception when NatService fails to configure automaticially #4023

Merged

antonydenyer added a commit that referenced this issue Jun 29, 2022

Print full exception when NatService fails to configure automaticially (

5ea8014

#4023) #3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

eum602 pushed a commit to lacchain/besu that referenced this issue Nov 3, 2023

Print full exception when NatService fails to configure automaticially (

8ca9338

hyperledger#4023) hyperledger#3787 Signed-off-by: Antony Denyer <git@antonydenyer.co.uk>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

tomasouza commented May 4, 2022

joshuafernandes commented May 5, 2022

tomasouza commented May 5, 2022 •

edited

Loading

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022 •

edited

Loading

joshuafernandes commented May 9, 2022 •

edited

Loading

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022

joshuafernandes commented May 9, 2022

matkt commented May 10, 2022

joshuafernandes commented May 16, 2022

matkt commented May 17, 2022

joshuafernandes commented May 17, 2022

matkt commented May 23, 2022

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

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

Comments

tomasouza commented May 4, 2022

Description

Acceptance Criteria

Steps to Reproduce (Bug)

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 May 5, 2022

tomasouza commented May 5, 2022 • edited Loading

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022 • edited Loading

joshuafernandes commented May 9, 2022 • edited Loading

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022

joshuafernandes commented May 9, 2022

tomasouza commented May 9, 2022

joshuafernandes commented May 9, 2022

matkt commented May 10, 2022

joshuafernandes commented May 16, 2022

matkt commented May 17, 2022

joshuafernandes commented May 17, 2022

matkt commented May 23, 2022

tomasouza commented May 5, 2022 •

edited

Loading

tomasouza commented May 9, 2022 •

edited

Loading

joshuafernandes commented May 9, 2022 •

edited

Loading