Metrics producing duplicate #TYPE definitions

[angusscott]

System information

Erigon version: erigon version erigon version 2.49.1-stable-205eeda0

OS & Version: Linux

Erigon Command (with flags/config):

Chain/Network: Ethereum

Expected behaviour

Expect metrics to not be defined more than once

Actual behaviour

Metric TYPES are still being duplicated, and are breaking against this linter https://o11y.tools/metricslint/

Steps to reproduce the behaviour

Start an instance of Erigon, with --metrics enabled, and make a request.

Following from this issue https://github.com/ledgerwatch/erigon/issues/8053

the metrics endpoint (/debug/metrics/prometheus) still produces invalid metrics. Metrics were tested against this linter https://o11y.tools/metricslint/ and comes back with the following issue.

"text format parsing error in line 150: second TYPE line for metric name "cache_total", or TYPE reported after samples"

I'm verifying the same with Telegraf currently, and will include the output of that once done.

Result

(Metrics can be passed to linter to produce same result)

db_gc_leaf 0
db_gc_overflow 0
db_gc_pages 0
db_pgops{phase="clone"} 0
db_pgops{phase="cow"} 0
db_pgops{phase="merge"} 0
db_pgops{phase="newly"} 0
db_pgops{phase="spill"} 0
db_pgops{phase="split"} 0
db_pgops{phase="unspill"} 0
db_pgops{phase="wops"} 0
db_size 0
domain_block_current 0
domain_collation_hist_size 0
domain_collation_size 0
domain_commitment_keys 0
domain_commitment_updates 0
domain_commitment_updates_applied 0
domain_prune_size 0
domain_pruning_progress 0
domain_running_collations 0
domain_running_commitment 0
domain_running_merges 0
domain_step_current 0
domain_tx_processed 0
exec_repeats 0
exec_steps_in_db 0
exec_triggers 0
exec_txs_done 0
pool_write_to_db_bytes 0
tx_dirty 0
tx_limit 0
tx_spill 0
tx_unspill 0
txpool_basefee 0
txpool_pending 0
txpool_queued 0
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 2.7912e-05
go_gc_duration_seconds{quantile="0.25"} 4.6706e-05
go_gc_duration_seconds{quantile="0.5"} 6.3137e-05
go_gc_duration_seconds{quantile="0.75"} 0.000173571
go_gc_duration_seconds{quantile="1"} 0.000451838
go_gc_duration_seconds_sum 0.002029061
go_gc_duration_seconds_count 17
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 32
# HELP go_info Information about the Go environment.
# TYPE go_info gauge
go_info{version="go1.19.13"} 1
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 1.9882856e+07
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 1.05080232e+08
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.478183e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 623571
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 9.923464e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 1.9882856e+07
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 1.155072e+07
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 2.4559616e+07
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 127530
# HELP go_memstats_heap_released_bytes Number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes gauge
go_memstats_heap_released_bytes 9.289728e+06
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 3.6110336e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.6945115264529555e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 751101
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 28800
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 31200
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 336096
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 423072
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 3.216496e+07
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 4.050137e+06
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 1.6384e+06
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 1.6384e+06
# HELP go_memstats_sys_bytes Number of bytes obtained from system.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 5.3654792e+07
# HELP go_threads Number of OS threads created.
# TYPE go_threads gauge
go_threads 30
# HELP process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE process_cpu_seconds_total counter
process_cpu_seconds_total 0.79
# HELP process_max_fds Maximum number of open file descriptors.
# TYPE process_max_fds gauge
process_max_fds 524288
# HELP process_open_fds Number of open file descriptors.
# TYPE process_open_fds gauge
process_open_fds 18
# HELP process_resident_memory_bytes Resident memory size in bytes.
# TYPE process_resident_memory_bytes gauge
process_resident_memory_bytes 9.8226176e+07
# HELP process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE process_start_time_seconds gauge
process_start_time_seconds 1.69451041236e+09
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 5.500484993024e+12
# HELP process_virtual_memory_max_bytes Maximum amount of virtual memory available in bytes.
# TYPE process_virtual_memory_max_bytes gauge
process_virtual_memory_max_bytes 1.8446744073709552e+19

# TYPE cache_total counter
cache_total{target="acc_read"} 0

# TYPE cache_total counter
cache_total{target="st_read"} 0

# TYPE cache_total counter
cache_total{target="write"} 0

# TYPE chain_execution_seconds summary
chain_execution_seconds {quantile="0.5"} 0
chain_execution_seconds {quantile="0.9"} 0
chain_execution_seconds {quantile="0.97"} 0
chain_execution_seconds {quantile="0.99"} 0
chain_execution_seconds {quantile="1"} 0
chain_execution_seconds_time 300.000000
chain_execution_seconds_sum 0.000000
chain_execution_seconds_count 5

# TYPE p2p_dials counter
p2p_dials 0

# TYPE p2p_egress counter
p2p_egress 0

# TYPE p2p_ingress counter
p2p_ingress 0

# TYPE p2p_peers gauge
p2p_peers 0

# TYPE p2p_serves counter
p2p_serves 0

# TYPE rpc_duration_seconds{method="eth_call",success="success"} summary
rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.5"} 0
rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.9"} 0
rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.97"} 0
rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.99"} 0
rpc_duration_seconds{method="eth_call",success="success"} {quantile="1"} 0
rpc_duration_seconds{method="eth_call",success="success"}_time 300.000000
rpc_duration_seconds{method="eth_call",success="success"}_sum 0.000000
rpc_duration_seconds{method="eth_call",success="success"}_count 5

# TYPE rpc_duration_seconds{method="eth_gasPrice",success="success"} summary
rpc_duration_seconds{method="eth_gasPrice",success="success"} {quantile="0.5"} 0
rpc_duration_seconds{method="eth_gasPrice",success="success"} {quantile="0.9"} 0
rpc_duration_seconds{method="eth_gasPrice",success="success"} {quantile="0.97"} 0
rpc_duration_seconds{method="eth_gasPrice",success="success"} {quantile="0.99"} 0
rpc_duration_seconds{method="eth_gasPrice",success="success"} {quantile="1"} 0
rpc_duration_seconds{method="eth_gasPrice",success="success"}_time 300.000000
rpc_duration_seconds{method="eth_gasPrice",success="success"}_sum 0.000000
rpc_duration_seconds{method="eth_gasPrice",success="success"}_count 5

# TYPE rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} summary
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} {quantile="0.5"} 0
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} {quantile="0.9"} 0
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} {quantile="0.97"} 0
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} {quantile="0.99"} 0
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"} {quantile="1"} 0
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"}_time 300.000000
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"}_sum 0.000000
rpc_duration_seconds{method="eth_getBlockByNumber",success="success"}_count 5

# TYPE rpc_duration_seconds{method="eth_getCode",success="success"} summary
rpc_duration_seconds{method="eth_getCode",success="success"} {quantile="0.5"} 0
rpc_duration_seconds{method="eth_getCode",success="success"} {quantile="0.9"} 0
rpc_duration_seconds{method="eth_getCode",success="success"} {quantile="0.97"} 0
rpc_duration_seconds{method="eth_getCode",success="success"} {quantile="0.99"} 0
rpc_duration_seconds{method="eth_getCode",success="success"} {quantile="1"} 0
rpc_duration_seconds{method="eth_getCode",success="success"}_time 300.000000
rpc_duration_seconds{method="eth_getCode",success="success"}_sum 0.000000
rpc_duration_seconds{method="eth_getCode",success="success"}_count 5

# TYPE rpc_failure counter
rpc_failure 0

# TYPE rpc_total counter
rpc_total 345

# TYPE sync counter
sync{stage="account_history_index"} 0

# TYPE sync counter
sync{stage="block_hashes"} 0

# TYPE sync counter
sync{stage="bodies"} 0

# TYPE sync counter
sync{stage="bor_heimdall"} 0

# TYPE sync counter
sync{stage="call_traces"} 0

# TYPE sync counter
sync{stage="execution"} 0

# TYPE sync counter
sync{stage="finish"} 0

# TYPE sync counter
sync{stage="hash_state"} 0

# TYPE sync counter
sync{stage="headers"} 0

# TYPE sync counter
sync{stage="intermediate_hashes"} 0

# TYPE sync counter
sync{stage="log_index"} 0

# TYPE sync counter
sync{stage="senders"} 0

# TYPE sync counter
sync{stage="snapshots"} 0

# TYPE sync counter
sync{stage="storage_history_index"} 0

# TYPE sync counter
sync{stage="translation"} 0

# TYPE sync counter
sync{stage="tx_lookup"} 0

[angusscott]

Just to add the range of issues in these metrics

1. Metrics #TYPE is being duplicated (see this for cache_total and sync metrics)

example:

# TYPE cache_total counter
cache_total{target="acc_read"} 0

# TYPE cache_total counter
cache_total{target="st_read"} 0

# TYPE cache_total counter
cache_total{target="write"} 0

should be

# TYPE cache_total counter
cache_total{target="acc_read"} 0
cache_total{target="st_read"} 0
cache_total{target="write"} 0

2. Metrics #TYPE are malformed, and shouldn't include the label in the definition example:

   # TYPE rpc_duration_seconds{method="eth_call",success="success"} summary

should be

# TYPE rpc_duration_seconds summary

3. Labels aren't correctly grouped (similar to issue above) example:

   # TYPE rpc_duration_seconds{method="eth_call",success="success"} summary
   rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.5"} 0
   rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.9"} 0
   rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.97"} 0
   rpc_duration_seconds{method="eth_call",success="success"} {quantile="0.99"} 0
   rpc_duration_seconds{method="eth_call",success="success"} {quantile="1"} 0
   rpc_duration_seconds{method="eth_call",success="success"}_time 300.000000
   rpc_duration_seconds{method="eth_call",success="success"}_sum 0.000000
   rpc_duration_seconds{method="eth_call",success="success"}_count 5

should be

# TYPE rpc_duration_seconds summary
rpc_duration_seconds{method="eth_call",success="success", quantile="0.5"} 0
rpc_duration_seconds{method="eth_call",success="success", quantile="0.9"} 0
rpc_duration_seconds{method="eth_call",success="success", quantile="0.97"} 0
rpc_duration_seconds{method="eth_call",success="success", quantile="0.99"} 0
rpc_duration_seconds{method="eth_call",success="success", quantile="1"} 0
rpc_duration_seconds_time{method="eth_call",success="success"} 300.000000
rpc_duration_seconds_sum{method="eth_call",success="success"} 0.000000
rpc_duration_seconds_count{method="eth_call",success="success"} 5

[angusscott]

@mh0lt tagging you since you worked on this the other day

[angusscott]

Also looks like some of these are captured by https://github.com/ledgerwatch/erigon/issues/8155

[mh0lt]

I'm currently looking at pushing a fix into devel tomorrow am.

[f0rmatting]

Hi everyone, I've discovered another bug.

Use https://github.com/ledgerwatch/erigon/pull/8186

...
# TYPE rpc_duration_seconds summary
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"} {quantile="0.5"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"} {quantile="0.9"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"} {quantile="0.97"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"} {quantile="0.99"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"} {quantile="1"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"}_time 300.000000
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"}_sum 0.000000
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success"}_count 5
...

Should

...
# TYPE rpc_duration_seconds summary
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success", quantile="0.5"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success", quantile="0.9"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success", quantile="0.97"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success", quantile="0.99"} 0
rpc_duration_seconds{method="engine_exchangeTransitionConfigurationV1",success="success", quantile="1"} 0
# TYPE rpc_duration_seconds gauge
rpc_duration_seconds_time{method="engine_exchangeTransitionConfigurationV1",success="success"}300.000000
# TYPE rpc_duration_seconds_sum counter
rpc_duration_seconds_sum{method="engine_exchangeTransitionConfigurationV1",success="success"}0.000000
# TYPE rpc_duration_seconds_count counter
rpc_duration_seconds_count{method="engine_exchangeTransitionConfigurationV1",success="success"}5
...

I have some confusion here. Why not use github.com/prometheus/client_golang directly instead of manually concatenating strings? Unless there's a specific reason, I'm planning to rewrite this part of the code using github.com/prometheus/client_golang.

[AskAlexSharov]

@f0rmatting no reason, just unfinished migration. see https://github.com/ledgerwatch/erigon/issues/8206

[github-actions[bot]]

This issue is stale because it has been open for 40 days with no activity. Remove stale label or comment, or this will be closed in 7 days.

[github-actions[bot]]

This issue was closed because it has been stalled for 7 days with no activity.