besu Otel take 2

trafficstars

PR description

Fixes the OpenTelemetry configuration so it doesn't initialize the global opentelemetry singleton when getting the tracer.

Documentation

[X] I thought about documentation and added the doc-change-required label to this PR if updates are required.

Changelog

[X] I thought about the changelog and included a changelog update if required.

Jul 08 '22 11:07 atoulme

Ah, I'm still seeing errors in the logs. I need to take another look at it.

Jul 13 '22 02:07 atoulme

@atoulme since this still needs work - I changed to draft for visibility from the main page

Jul 21 '22 22:07 macfarla

Tested locally, no more errors logged

Jul 23 '22 00:07 atoulme

I spun this up on an AWS box (with default config) and still seeing this "Failed to export metrics" error periodically - @atoulme is this expected?


{"@timestamp":"2022-07-26T01:17:24,633","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}
{"@timestamp":"2022-07-26T01:17:30,313","level":"INFO","thread":"EthScheduler-Services-8 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 20601 to 45400 (24800 blocks in 10172ms), Peers: 4","throwable":""}
{"@timestamp":"2022-07-26T01:17:33,303","level":"INFO","thread":"Timer-0","class":"DNSTimerTask","message":"Refreshing DNS records with enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.goerli.ethdisco.net","throwable":""}
{"@timestamp":"2022-07-26T01:17:47,874","level":"INFO","thread":"EthScheduler-Services-8 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 45401 to 67800 (22400 blocks in 10077ms), Peers: 4","throwable":""}
{"@timestamp":"2022-07-26T01:18:03,566","level":"INFO","thread":"EthScheduler-Services-8 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 67801 to 93400 (25600 blocks in 10068ms), Peers: 4","throwable":""}
{"@timestamp":"2022-07-26T01:18:09,812","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export spans. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}
{"@timestamp":"2022-07-26T01:18:23,868","level":"INFO","thread":"EthScheduler-Services-7 (requestCompleteTask)","class":"CompleteTaskStep","message":"Downloaded 1553440 world state nodes. At least 122672 nodes remaining.","throwable":""}
{"@timestamp":"2022-07-26T01:18:24,614","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}

Jul 26 '22 01:07 macfarla

config looks like this

# data
data-path="/data"
logging="INFO"
data-storage-format="BONSAI"

# JWT
# authentication is enabled by default when engine-jwt-disabled=false
engine-jwt-disabled=false





network="goerli"

min-gas-price=1000
sync-mode="FAST"
host-whitelist=["*"]




# rpc
rpc-http-enabled=true
rpc-http-host="0.0.0.0"
rpc-http-port=8545
rpc-http-api=["ADMIN","DEBUG","NET","ETH","MINER","WEB3"]
rpc-http-cors-origins=["all"]


# ws
rpc-ws-enabled=true
rpc-ws-api=["NET","ETH","WEB3"]
rpc-ws-host="0.0.0.0"
rpc-ws-port=8546

# graphql
graphql-http-enabled=true
graphql-http-host="0.0.0.0"
graphql-http-port=8547
graphql-http-cors-origins=["all"]

# p2p
p2p-host="redacted"
p2p-port=30303

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

Jul 26 '22 01:07 macfarla

No it is not. Your config is different than what I used, I'll try it out now.

Jul 26 '22 03:07 atoulme

I'm not reproducing locally :( Are you using Docker by chance?

Jul 26 '22 04:07 atoulme

I'm not reproducing locally :( Are you using Docker by chance?

besu is not running in docker. I will try the same procedure with this PR updated with changes from main

Jul 26 '22 06:07 macfarla

besu --version besu/v22.7.0-dev-cb6925bf/linux-x86_64/openjdk-java-11

Jul 26 '22 08:07 macfarla

Still seeing that error periodically

{"@timestamp":"2022-07-26T08:28:19,916","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}
{"@timestamp":"2022-07-26T08:28:21,778","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4781372 to 4784771 (3400 blocks in 10337ms), Peers: 25","throwable":""}
{"@timestamp":"2022-07-26T08:28:23,989","level":"INFO","thread":"EthScheduler-Services-7 (requestCompleteTask)","class":"CompleteTaskStep","message":"Downloaded 57554972 world state nodes. At least 61514 nodes remaining.","throwable":""}
{"@timestamp":"2022-07-26T08:28:24,570","level":"INFO","thread":"Timer-0","class":"DNSTimerTask","message":"Refreshing DNS records with enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.goerli.ethdisco.net","throwable":""}
{"@timestamp":"2022-07-26T08:28:32,079","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4784772 to 4787771 (3000 blocks in 10295ms), Peers: 25","throwable":""}
{"@timestamp":"2022-07-26T08:28:42,264","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4787772 to 4789171 (1400 blocks in 10176ms), Peers: 24","throwable":""}
{"@timestamp":"2022-07-26T08:28:52,437","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4789172 to 4790771 (1600 blocks in 10169ms), Peers: 24","throwable":""}
{"@timestamp":"2022-07-26T08:29:03,249","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4790772 to 4793371 (2600 blocks in 10804ms), Peers: 24","throwable":""}
{"@timestamp":"2022-07-26T08:29:13,279","level":"INFO","thread":"EthScheduler-Services-9 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 4793372 to 4795571 (2200 blocks in 10024ms), Peers: 24","throwable":""}
{"@timestamp":"2022-07-26T08:29:19,907","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}

Jul 26 '22 08:07 macfarla

I've just rerun this test on a goerli canary - still seeing this ERROR log every minute

besu --version
besu/v22.7.0-dev-b2eb89e8/linux-x86_64/openjdk-java-11

ERROR log:

{"@timestamp":"2022-08-02T05:29:51,761","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}
{"@timestamp":"2022-08-02T05:29:56,340","level":"INFO","thread":"EthScheduler-Services-13 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 73801 to 101200 (27400 blocks in 10152ms), Peers: 6","throwable":""}
{"@timestamp":"2022-08-02T05:29:56,939","level":"INFO","thread":"Timer-0","class":"DNSTimerTask","message":"Refreshing DNS records with enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.goerli.ethdisco.net","throwable":""}
{"@timestamp":"2022-08-02T05:30:10,316","level":"INFO","thread":"EthScheduler-Services-13 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 101201 to 125800 (24600 blocks in 10068ms), Peers: 7","throwable":""}
{"@timestamp":"2022-08-02T05:30:26,249","level":"INFO","thread":"EthScheduler-Services-13 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 125801 to 153600 (27800 blocks in 10043ms), Peers: 7","throwable":""}
{"@timestamp":"2022-08-02T05:30:51,140","level":"INFO","thread":"EthScheduler-Services-7 (requestCompleteTask)","class":"CompleteTaskStep","message":"Downloaded 870135 world state nodes. At least 75316 nodes remaining.","throwable":""}
{"@timestamp":"2022-08-02T05:30:51,685","level":"ERROR","thread":"OkHttp http://localhost:4317/...","class":"OkHttpGrpcExporter","message":"Failed to export metrics. The request could not be executed. Full error message: Failed to connect to localhost/127.0.0.1:4317","throwable":""}
{"@timestamp":"2022-08-02T05:30:53,932","level":"INFO","thread":"EthScheduler-Services-13 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 153601 to 180600 (27000 blocks in 10011ms), Peers: 7","throwable":""}

Aug 02 '22 05:08 macfarla

I have some good news - the sdk folks are working on making it possible to disable the sdk from auto-starting here: https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk-extensions/autoconfigure/README.md#disabling-opentelemetrysdk

Aug 09 '22 15:08 atoulme

I have some good news - the sdk folks are working on making it possible to disable the sdk from auto-starting here: https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk-extensions/autoconfigure/README.md#disabling-opentelemetrysdk

@atoulme are we still waiting on sdk development for this one?

Oct 06 '22 04:10 macfarla

It looks like that finally landed.

Nov 02 '22 05:11 atoulme

ran up a node on AWS with this and logging appears normal


{"@timestamp":"2022-11-14T01:07:05,189","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 707401 to 727600 (20200 blocks in 10022ms), Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T01:07:15,768","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 727601 to 751400 (23800 blocks in 10061ms), Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T01:07:25,847","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 751401 to 770800 (19400 blocks in 10029ms), Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T01:07:39,287","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 770801 to 796200 (25400 blocks in 10083ms), Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T01:07:49,395","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 796201 to 812787 (16587 blocks in 10056ms), Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T01:07:59,559","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 8
12788 to 825187 (12400 blocks in 10126ms), Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T01:08:20,028","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 825188 to 850955 (25768 blocks in 10004ms), Peers: 6","throwable":""}
{"@timestamp":"2022-11-14T01:08:30,642","level":"INFO","thread":"EthScheduler-Services-3 (batchPersistAccountData)","class":"SnapsyncMetricsManager","message":"Worldstate download in progress synced=11.03%, accounts=1736016, slots=24890274, codes=593919, nodes=30614089","throwable":""}
{"@timestamp":"2022-11-14T01:08:36,277","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 850956 to 870156 (19201 blocks in 10118ms), Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T01:08:46,369","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 870157 to 879000 (8844 blocks in 10051ms), Peers: 8","throwable":""}
{"@timestamp":"2022-11-14T01:08:57,339","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 879001 to 890200 (11200 blocks in 10188ms), Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T01:09:07,773","level":"INFO","thread":"EthScheduler-Services-34 (importBlock)","class":"FastImportBlocksStep","message":"Completed importing chain segment 890201 to 904800 (14600 blocks in 10065ms), Peers: 6","throwable":""}

Nov 14 '22 01:11 macfarla

commit 1fa65fb944db18e486145f3a67886679b124bb6c

$ ./besu/ethereum/evmtool/build/install/evmtool/bin/evm --code 6001 
java.lang.IllegalStateException: GlobalOpenTelemetry.set has already been called. GlobalOpenTelemetry.set must be called only once before any calls to GlobalOpenTelemetry.get. If you are using the OpenTelemetrySdk, use OpenTelemetrySdkBuilder.buildAndRegisterGlobal instead. Previous invocation set to cause of this exception.
	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:99)
	at org.hyperledger.besu.metrics.MetricsSystemFactory.disableGlobalOpenTelemetry(MetricsSystemFactory.java:38)
	at org.hyperledger.besu.metrics.MetricsSystemFactory.create(MetricsSystemFactory.java:50)
	at org.hyperledger.besu.evmtool.MetricsSystemModule.getMetricsSystem(MetricsSystemModule.java:32)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.getMetricsSystem(MetricsSystemModule_GetMetricsSystemFactory.java:39)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.get(MetricsSystemModule_GetMetricsSystemFactory.java:31)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.get(MetricsSystemModule_GetMetricsSystemFactory.java:11)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideBlockchainFactory.get(BlockchainModule_ProvideBlockchainFactory.java:46)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideBlockchainFactory.get(BlockchainModule_ProvideBlockchainFactory.java:15)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideStateRootFactory.get(BlockchainModule_ProvideStateRootFactory.java:41)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideStateRootFactory.get(BlockchainModule_ProvideStateRootFactory.java:14)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)
	at org.hyperledger.besu.evmtool.BlockchainModule_GetMutableWorldStateFactory.get(BlockchainModule_GetMutableWorldStateFactory.java:54)
	at org.hyperledger.besu.evmtool.BlockchainModule_GetMutableWorldStateFactory.get(BlockchainModule_GetMutableWorldStateFactory.java:16)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideWorldUpdaterFactory.get(BlockchainModule_ProvideWorldUpdaterFactory.java:37)
	at org.hyperledger.besu.evmtool.BlockchainModule_ProvideWorldUpdaterFactory.get(BlockchainModule_ProvideWorldUpdaterFactory.java:13)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)
	at org.hyperledger.besu.evmtool.DaggerEvmToolComponent$EvmToolComponentImpl.getWorldUpdater(DaggerEvmToolComponent.java:206)
	at org.hyperledger.besu.evmtool.EvmToolCommand.run(EvmToolCommand.java:246)
	at picocli.CommandLine.executeUserObject(CommandLine.java:1939)
	at picocli.CommandLine.access$1300(CommandLine.java:145)
	at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2358)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2352)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2314)
	at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2179)
	at picocli.CommandLine$RunLast.execute(CommandLine.java:2316)
	at picocli.CommandLine.execute(CommandLine.java:2078)
	at org.hyperledger.besu.evmtool.EvmToolCommand.parse(EvmToolCommand.java:164)
	at org.hyperledger.besu.evmtool.EvmTool.main(EvmTool.java:26)
Caused by: java.lang.Throwable
	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:107)
	at org.hyperledger.besu.metrics.MetricsSystemFactory.disableGlobalOpenTelemetry(MetricsSystemFactory.java:38)
	at org.hyperledger.besu.metrics.MetricsSystemFactory.create(MetricsSystemFactory.java:50)
	at org.hyperledger.besu.evmtool.MetricsSystemModule.getMetricsSystem(MetricsSystemModule.java:32)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.getMetricsSystem(MetricsSystemModule_GetMetricsSystemFactory.java:39)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.get(MetricsSystemModule_GetMetricsSystemFactory.java:31)
	at org.hyperledger.besu.evmtool.MetricsSystemModule_GetMetricsSystemFactory.get(MetricsSystemModule_GetMetricsSystemFactory.java:11)
	at org.hyperledger.besu.evmtool.DataStoreModule_ProvideBlockchainKeyValueStorageFactory.get(DataStoreModule_ProvideBlockchainKeyValueStorageFactory.java:46)
	at org.hyperledger.besu.evmtool.DataStoreModule_ProvideBlockchainKeyValueStorageFactory.get(DataStoreModule_ProvideBlockchainKeyValueStorageFactory.java:14)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)
	at org.hyperledger.besu.evmtool.DataStoreModule_ProvideBlockchainStorageFactory.get(DataStoreModule_ProvideBlockchainStorageFactory.java:39)
	at org.hyperledger.besu.evmtool.DataStoreModule_ProvideBlockchainStorageFactory.get(DataStoreModule_ProvideBlockchainStorageFactory.java:14)
	at dagger.internal.DoubleCheck.get(DoubleCheck.java:47)

Nov 21 '22 08:11 holiman

@holiman please open an issue and assign to me thanks!

Nov 21 '22 14:11 atoulme

Way ahead of you :)

https://github.com/hyperledger/besu/issues/4714

Don't have rights to assign on this repo though.

Nov 21 '22 14:11 holiman

besu besu copied to clipboard

Otel take 2

PR description

Documentation

Changelog

besu
besu copied to clipboard