[Bug] chain_execution_count, chain_id value extraction results in unexpected behavior.

[rpl-ffl]

After upgrading to Sonic develop = 02b387, Norma has reported 2 newly-encountered unexpected behavior during testing:

1. chain_execution_count appears to no longer be extractable. Norma tests if the sonic client's runtime behavior can be extracted or not using chain_execution_count:

Norma/driver/monitoring/node/prom_log_source_test.go

Lines 89 to 147 in 4b529a0

	func TestLogsIntegrationGetRealMetric(t *testing.T) {
	t.Parallel()
	ctrl := gomock.NewController(t)
	net := driver.NewMockNetwork(ctrl)
	client, err := docker.NewClient()
	if err != nil {
	t.Fatalf("failed to create a docker client: %v", err)
	}
	t.Cleanup(func() {
	_ = client.Close()
	})
	node, err := opera.StartOperaDockerNode(client, nil, &opera.OperaNodeConfig{
	Label: "test",
	NetworkConfig: &driver.NetworkConfig{NumberOfValidators: 1},
	})
	if err != nil {
	t.Fatalf("failed to create an Opera node on Docker: %v", err)
	}
	t.Cleanup(func() {
	_ = node.Cleanup()
	})
	// simulate existing nodes
	net.EXPECT().RegisterListener(gomock.Any()).AnyTimes()
	net.EXPECT().GetActiveNodes().AnyTimes().Return([]driver.Node{node})
	outDir := t.TempDir()
	monitor, err := monitoring.NewMonitor(net, monitoring.MonitorConfig{OutputDir: outDir})
	if err != nil {
	t.Fatalf("failed to create monitor instance: %v", err)
	}
	t.Cleanup(func() {
	_ = monitor.Shutdown()
	})
	for _, metricKeys := range []monitoring.PrometheusLogKey{
	monitoring.NewPrometheusKey("chain_execution", monitoring.Quantile05),
	monitoring.NewPrometheusNameKey("chain_execution_count")} {
	// wait for the metric to arrive for some time
	source := NewPromLogSource(monitor, metricKeys)
	var found bool
	for i := 0; i < 100; i++ {
	series, exists := source.GetData("test")
	if exists {
	datapoint := series.GetLatest()
	if datapoint != nil {
	found = datapoint.Position > 0
	break
	}
	}
	time.Sleep(100 * time.Millisecond)
	}
	if !found {
	t.Errorf("Metric data not arrived within give time for: %s", metricKeys.Name)
	}
	}

prom_log_source_test.go:145: Metric data not arrived within give time for: chain_execution_count

chain_execution and chain_execution_count seems to only appear in the testing section. (In other words, actual run looks for txpool_received, system_memory_used, etc.) Thus it could be that the string label changed or if we can check for other values instead of chain_execution to confirm value extraction.

Question

• Has chain_execution or chain_execution_count behavior been changed recently?
• If chain_execution or chain_execution_count has been deprecated, can we use anything other value to perform this check instead?

2. chain_info starts to appear with the following value chain_info {} 1 where a float is expected in place of {}.

monitoring: failed to parse log: cannot parse value from: {}; [chain_info {} 1]; strconv.ParseFloat: parsing "{}": invalid syntax

We can suppress this behavior on Norma front, but it would be nice to understand where the changes are coming from.

Question:

• Has chain_info behavior been changed recently?

[thaarok]

There is a change of chain_execution/chain_execution_count introduced by go-ethereum dependency upgrade:
The metric is visible in the /debug/metrics/prometheus output only when the samples count is not zero - it use ResettingTimer instead of Timer which was used in the older go-ethereum:
https://github.com/Fantom-foundation/go-ethereum-sonic/blob/main/metrics/prometheus/collector.go#L125-L127
You need to handle missing chain_execution_count as a zero count.

I may try to fix the chain_info, however it seems it (or "chain_id") does not exist even in the main branch - I don't even see it in the Norma sources - how are you using it right now? Do you need it?

[rpl-ffl]

I may try to fix the chain_info, however it seems it (or "chain_id") does not exist even in the main branch - I don't even see it in the Norma sources - how are you using it right now? Do you need it?

Sorry, there was a typo before. It's always been chain_info, never chain_id.
Norma does not use it. I have not seen it before and suppressing it by ignoring chain_info seems to result in a normal run.

[thaarok]

@rpl-ffl I have prepared fix here - please check attached example output if it matches your expectations:
Fantom-foundation/Sonic#219

[rpl-ffl]

@thaarok Thank you for the quick fix.
Proceeding by ignoring chain_info for now.