DEBUG message `Invalid TraceId` and `Invalid span context`

[macfarla]

I see this debug message in the log. I get it running locally but also in AWS
{"timestamp":"2021-12-16T04:36:33,978","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"B3PropagatorExtractorMultipleHeaders","message":"Invalid TraceId in B3 header: null'. Returning INVALID span context.","throwable":""}

{"timestamp":"2021-12-16T04:36:33,919","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"ApiHandler","message":"Received Wire PING","throwable":""}
{"timestamp":"2021-12-16T04:36:33,978","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"JsonRpcHttpService","message":"Opened connection from 127.0.0.1:48576. Total of active connections
: 1/80","throwable":""}
{"timestamp":"2021-12-16T04:36:33,978","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"B3PropagatorExtractorMultipleHeaders","message":"Invalid TraceId in B3 header: null'. Returning IN
VALID span context.","throwable":""}
{"timestamp":"2021-12-16T04:36:33,978","level":"DEBUG","thread":"vert.x-worker-thread-17","class":"JsonRpcHttpService","message":"JSON-RPC request -> eth_syncing","throwable":""}
{"timestamp":"2021-12-16T04:36:33,979","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"JsonRpcHttpService","message":"Connection closed from 127.0.0.1:48576. Total of active connections
: 0/80","throwable":""}
{"timestamp":"2021-12-16T04:36:34,061","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"AbstractHandshakeHandler","message":"Handshake error:","throwable":" java.io.IOException: Connection r
eset by peer\n\tat java.base/sun.nio.ch.FileDispatcherImpl.read0(Native Method)\n\tat java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)\n\tat java.base/sun.nio.ch.IOUtil.readIntoNa
tiveBuffer(IOUtil.java:276)\n\tat java.base/sun.nio.ch.IOUtil.read(IOUtil.java:233)\n\tat java.base/sun.nio.ch.IOUtil.read(IOUtil.java:223)\n\tat java.base/sun.nio.ch.SocketChannelImpl.read(SocketCha
nnelImpl.java:356)\n\tat io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)\n\tat io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)\n\tat io.netty.channel.socket.nio.N
ioSocketChannel.doReadBytes(NioSocketChannel.java:350)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)\n\tat io.netty.channel.nio.NioEventLoop.pr
ocessSelectedKey(NioEventLoop.java:719)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEven
tLoop.java:581)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)\n\tat io.netty.ut
il.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.
java:829)\n"}
{"timestamp":"2021-12-16T04:36:34,270","level":"DEBUG","thread":"nioEventLoopGroup-3-8","class":"ApiHandler","message":"Received Wire PING","throwable":""}
{"timestamp":"2021-12-16T04:36:34,334","level":"DEBUG","thread":"vert.x-worker-thread-10","class":"PingPacketData","message":"read PING enr as long scalar","throwable":""}
{"timestamp":"2021-12-16T04:36:34,347","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"RlpxAgent","message":"Too many peers. Disconnect incoming connection: NettyPeerConnection{nodeId=0xf61
85b64224d9d971200b234dd9ccc15089dd688c01dbd02ed977d5c492f44ca11c3d793c18b9251b83508efd19f5e0b0267d8b3c98afa17713adbd8f0b74ae5, clientId=Geth/v4.3.0-stable-86215cd4/linux-amd64/go1.17.2, caps=eth/66}"
,"throwable":""}
{"timestamp":"2021-12-16T04:36:34,347","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - Outbound - 0x04 TOO_MANY_PEERS - PeerInfo{version=5, clien
tId='Geth/v4.3.0-stable-86215cd4/linux-amd64/go1.17.2', capabilities=[eth/66, snap/1], port=0, nodeId=0xf6185b64224d9d971200b234dd9ccc15089dd688c01dbd02ed977d5c492f44ca11c3d793c18b9251b83508efd19f5e0
b0267d8b3c98afa17713adbd8f0b74ae5} - 32 peers left","throwable":""}
{"timestamp":"2021-12-16T04:36:34,476","level":"DEBUG","thread":"vert.x-worker-thread-3","class":"PingPacketData","message":"read PING enr as long scalar","throwable":""}
{"timestamp":"2021-12-16T04:36:34,477","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"JsonRpcHttpService","message":"Opened connection from 127.0.0.1:48578. Total of active connections
: 1/80","throwable":""}
{"timestamp":"2021-12-16T04:36:34,477","level":"DEBUG","thread":"vert.x-eventloop-thread-0","class":"B3PropagatorExtractorMultipleHeaders","message":"Invalid TraceId in B3 header: null'. Returning IN
VALID span context.","throwable":""}
{"timestamp":"2021-12-16T04:36:34,478","level":"DEBUG","thread":"vert.x-worker-thread-19","class":"JsonRpcHttpService","message":"JSON-RPC request -> eth_syncing","throwable":""}

Versions (Add all that apply)

• Software version: [besu --version] 21.10.3 but I have seen it before
• Java version: [java -version]
  openjdk 11.0.11 2021-04-20 LTS
  OpenJDK Runtime Environment Corretto-11.0.11.9.1 (build 11.0.11+9-LTS)
  OpenJDK 64-Bit Server VM Corretto-11.0.11.9.1 (build 11.0.11+9-LTS, mixed mode)
• OS Name & Version: [cat /etc/*release]
  [ec2-user@ip-10-0-2-150 besu]$ 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-10-0-2-150.us-east-2.compute.internal 4.14.173-137.229.amzn2.x86_64 Update Jenkins Build for Pantheon → Besu considerations #1 SMP Wed Apr 1 18:06:08 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Additional Information

[jh1995]

Got it too.

• Software version: 21.10.6 (docker container hyperledger/besu:21.10.6 )
• Java version: openjdk version "11.0.13" 2021-10-19
  OpenJDK Runtime Environment (build 11.0.13+8-Ubuntu-0ubuntu1.20.04)
  OpenJDK 64-Bit Server VM (build 11.0.13+8-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)
• Consensus protocol: IBFT2

Private network is composed of Besu clients only.

The error is logged when there is a JSON-RPC request (http).

[macfarla]

This does not affect operation of Besu, it's only noticeable in the DEBUG logs

[macfarla]

it's to do with open telemetry. We're upgrading so maybe it will even be fixed. https://programtalk.com/vs3/?source=java/open-telemetry/opentelemetry-java/extensions/trace-propagators/src/main/java/io/opentelemetry/extension/trace/propagation/B3PropagatorExtractorMultipleHeaders.java

[macfarla]

I no longer see these DEBUG messages.
besu/v22.1.3-dev-7e0d06ac/osx-x86_64/openjdk-java-11

[loziniak]

I see:

Sep 14 15:44:35 SRV-02 run_node.sh[70540]: 2022-09-14 15:44:35.058+02:00 | vert.x-eventloop-thread-1 | DEBUG | JsonRpcHttpService | Opened connection from 0:0:0:0:0:0:0:1%0
:49934. Total of active connections: 1/80
Sep 14 15:44:35 SRV-02 run_node.sh[70540]: 2022-09-14 15:44:35.058+02:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 
header: null'. Returning INVALID span context.

My system:

# uname -a
Linux  5.10.0-16-amd64 #1 SMP Debian 5.10.127-1 (2022-06-30) x86_64 GNU/Linux
# besu --version
besu/v22.4.4/linux-x86_64/openjdk-java-11
# java -version
openjdk version "11.0.16" 2022-07-19
OpenJDK Runtime Environment (build 11.0.16+8-post-Debian-1deb11u1)
OpenJDK 64-Bit Server VM (build 11.0.16+8-post-Debian-1deb11u1, mixed mode, sharing)

[meijiesky]

Seeing this log too when I try to call the following endpoint
https://ethereum.github.io/beacon-APIs/#/Config/getSpec

curl -X 'GET' \
  'http://127.0.0.1:8545/eth/v1/config/spec' \
  -H 'accept: application/json'

2023-12-29 16:05:20.602+08:00 | vert.x-eventloop-thread-1 | DEBUG | JsonRpcHttpService | Opened connection from 127.0.0.1:51734. Total of active connections: 1/80
2023-12-29 16:05:20.602+08:00 | vert.x-eventloop-thread-1 | DEBUG | B3PropagatorExtractorMultipleHeaders | Invalid TraceId in B3 header: null'. Returning INVALID span context.
2023-12-29 16:05:20.604+08:00 | vert.x-eventloop-thread-1 | DEBUG | JsonRpcHttpService | Connection closed from 127.0.0.1:51734. Total of active connections: 0/80