[BUG] - KES metrics are not being reported on tag 1.19.0

[MarcelKlammer]

Exernal

Summary
KES reporting not available on v1.19.0

Steps to reproduce
Update your block producer to v1.19.0. See metrics. No KES

Expected behavior
KES should be reported.

System info (please complete the following information):

• OS: Ubuntu
• Version 20.04

cardano-node 1.19.0 - linux-x86_64 - ghc-8.6
git rev 4814003
cardano-cli 1.19.0 - linux-x86_64 - ghc-8.6
git rev 4814003

[MarcelKlammer]

Alongside my 1.19.0 test I rotated the KES keys using a local Docker Ubuntu container running the same v1.19.0.

Those newly created KES keys seem to be wrong, as they result in KES not reporting.

Uploading the old KES keys to a v1.19.0 block producer results in KES reporting normally.

So something is fishy with KES creation in v1.19.0

[MarcelKlammer]

Old KES keys produce this trace:

Aug 20 20:22:59 ip-172-31-33-176 cardano-node[88751]: [ip-172-3:cardano.node.Forge:Debug:52] [2020-08-20 20:22:59.71 UTC] OptSkip (OptCons (WrapForgeStateInfo {unwrapForgeStateInfo = KESInfo {kesStartPeriod = KESPeriod 40, kesEndPeriod = KESPeriod 102, kesEvolution = 9}}) OptNil)

New KES keys don't produce a cardano.node.Forge:Debug trace.

[disassembler]

That debug log was there for testing a specific problem with KES rotation. Debug logs are not expected to be stable and are expected to be added/removed at any point. I can confirm the KES metrics that we monitor show correctly after redeploying with a new KES key:

cardano_node_Forge_metrics_operationalCertificateStartKESPeriod_int 0 0
cardano_node_Forge_metrics_operationalCertificateExpiryKESPeriod_int 62
cardano_node_Forge_metrics_currentKESPeriod_int 2
cardano_node_Forge_metrics_remainingKESPeriods_int 60

[disassembler]

I also regenerated KES keys and deployed them before checking this (they were initially deployed at KES period 0)

[kevinhammond]

I will close the issue. There appears to be no problem.

[mrBliss]

Old KES keys produce this trace:

Aug 20 20:22:59 ip-172-31-33-176 cardano-node[88751]: [ip-172-3:cardano.node.Forge:Debug:52] [2020-08-20 20:22:59.71 UTC] OptSkip (OptCons (WrapForgeStateInfo {unwrapForgeStateInfo = KESInfo {kesStartPeriod = KESPeriod 40, kesEndPeriod = KESPeriod 102, kesEvolution = 9}}) OptNil)

New KES keys don't produce a cardano.node.Forge:Debug trace.

The key evolution code was refactored in 1.19.0. Now, such a debug message is only traced when the key actually evolved instead of once at the start of each slot (if the node is configured to produce blocks). As @disassembler said, debug logs are not expected to be stable.

[MarcelKlammer]

I don't care about the debug logs. It was an attempt to give you some insight.

The metrics are not present. Plain and simple. I uploaded new KES and opcert with the start KES period being the present KES period. And the KES metrics don't show up.

[mrBliss]

I don't care about the debug logs. It was an attempt to give you some insight.

The metrics are not present. Plain and simple. I uploaded new KES and opcert with the start KES period being the present KES period. And the KES metrics don't show up.

Ah, reading your messages, I had the impression that you were talking about the missing trace messages. Is #1748 what you mean?

[MarcelKlammer]

No,

EKG > Prometheus > Grafana.

cardano_node_Forge_metrics_remainingKESPeriods_int is not present.

Could it be, that this trace is actually necessary to get a KES metric at all.
Could it be, that since I regenerated the KES keys with the current KES period, that it didn't evolve yet, and so no trace is printed and thus nothing shows up?

[MarcelKlammer]

I'm still testing and I'm getting closer. I will keep you updated.

[mrBliss]

No,

EKG > Prometheus > Grafana.

cardano_node_Forge_metrics_remainingKESPeriods_int is not present.

Ah

Could it be, that this trace is actually necessary to get a KES metric at all.
Could it be, that since I regenerated the KES keys with the current KES period, that it didn't evolve yet, and so no trace is printed and thus nothing shows up?

Yeah, I'm now thinking that that's indeed the reason. That's also the cause of #1748. Thanks for the info! I'll see what I can do about it (e.g., trace it once on startup, even when the key didn't have to evolve).

[MarcelKlammer]

Yeah, I'm now thinking that that's indeed the reason. That's also the cause of #1748. Thanks for the info! I'll see what I can do about it (e.g., trace it once on startup, even when the key didn't have to evolve).

@kevinhammond Closing a bug report without proper investigation shouldn't be the norm, just saying.

[matiwinnetou]

I agree with @MarcelKlammer , I was also a bit shocked how quickly it was closed without looking into details.

[MarcelKlammer]

@mrBliss I can confirm the behavior now.

Just regenerated KES with --kes-period 48 instead of 49 (current) and node v1.19.0 now has KES metrics EKG/Prometheus/Grafana showing up.

[mrBliss]

A fix for this: IntersectMBO/ouroboros-network#2529.

[kevinhammond]

Hi Marcel. We did do the investigation (we were concerned that there might be a KES key acceptance problem, which would have needed urgent attention). I was told it was expected behaviour, but of course the issue was with logging rather than generation, as you have noted. We've seen quite a few things coming up with LiveView, unfortunately.