chore: set msg_hash logs to notice level

[Ivansete-status]

Description

This is needed to help the Distributed Systems Testing team, DST, to have less logs when analysing thousands of nodes. With that, the DST team will set the log level to NOTICE and that will avoid printing too many logs.

Changes

• set log level to notice when logging msg_hash.
• add error string in case of validation failure in waku/waku_relay/protocol.nim

Issue

closes #2678

[github-actions]

You can find the image built from this PR at

quay.io/wakuorg/nwaku-pr:2737-rln-v1

Built from f2ccdcc

[github-actions]

You can find the image built from this PR at

quay.io/wakuorg/nwaku-pr:2737-rln-v2

Built from f2ccdcc

[NagyZoltanPeter]

Thank you @Ivansete-status, it is great.
If you may consider an enhancement to your work here, I would add something like:

a template, maybe into digest.nim

template logTrackMessage*(
    context: static[string],
    pubsubTopic: PubsubTopic,
    msg: WakuMessage,
    additionalProps: varargs[untyped],
) =
  when defined(logMessageHashes):
    let hash = pubsubTopic.computeMessageHash(msg).to0xHex()
    let recvTime = getNowInNanosecondTime()
    info context,
      pubsubTopic = pubsubTopic,
      contentTopic = msg.contentTopic,
      msg_hash = hash,
      receivedTime = recvTime,
      payloadSizeBytes = msg.payload.len,
      additionalProps

That can be used all around easily, like:

proc registerRelayDefaultHandler(node: WakuNode, topic: PubsubTopic) =
  if node.wakuRelay.isSubscribed(topic):
    return

  proc traceHandler(topic: PubsubTopic, msg: WakuMessage) {.async, gcsafe.} =
    logTrackMessage("waku.relay received", topic, msg, my_peer_id = node.peerId)

    let msgSizeKB = msg.payload.len / 1000

or

  #TODO instead of discard return error when 0 peers received the message
  discard await node.wakuRelay.publish(pubsubTopic, message)

  logTrackMessage("waku.relay published", pubsubTopic, message, peer_id = node.peerId)

  return ok()

WDYT would it apply?

[Ivansete-status]

Thank you @Ivansete-status, it is great. If you may consider an enhancement to your work here, I would add something like:

a template, maybe into digest.nim

template logTrackMessage*(
    context: static[string],
    pubsubTopic: PubsubTopic,
    msg: WakuMessage,
    additionalProps: varargs[untyped],
) =
  when defined(logMessageHashes):
    let hash = pubsubTopic.computeMessageHash(msg).to0xHex()
    let recvTime = getNowInNanosecondTime()
    info context,
      pubsubTopic = pubsubTopic,
      contentTopic = msg.contentTopic,
      msg_hash = hash,
      receivedTime = recvTime,
      payloadSizeBytes = msg.payload.len,
      additionalProps

That can be used all around easily, like:

proc registerRelayDefaultHandler(node: WakuNode, topic: PubsubTopic) =
  if node.wakuRelay.isSubscribed(topic):
    return

  proc traceHandler(topic: PubsubTopic, msg: WakuMessage) {.async, gcsafe.} =
    logTrackMessage("waku.relay received", topic, msg, my_peer_id = node.peerId)

    let msgSizeKB = msg.payload.len / 1000

or

  #TODO instead of discard return error when 0 peers received the message
  discard await node.wakuRelay.publish(pubsubTopic, message)

  logTrackMessage("waku.relay published", pubsubTopic, message, peer_id = node.peerId)

  return ok()

WDYT would it apply?

wow! Thanks! I will consider that once the ci pass xD

[gabrielmer]

We changed the approach and now we will simply use notice log level so DST team can filter easily the relevant logs.

@NagyZoltanPeter do you think creating a template is still relevant with this new approach? I feel that now it's simple enough, but lmk what you think :)

[Ivansete-status]

LGTM your recent changes @gabrielmer !
Much simpler, thanks ;P!

[gabrielmer]

LGTM your recent changes @gabrielmer ! Much simpler, thanks ;P!

approving for @Ivansete-status 😁

[NagyZoltanPeter]

We changed the approach and now we will simply use notice log level so DST team can filter easily the relevant logs.

@NagyZoltanPeter do you think creating a template is still relevant with this new approach? I feel that now it's simple enough, but lmk what you think :)

@gabrielmer, @Ivansete-status , cc: @DarshanBPatel
Hey, what is the aim with notice level logging?
Is this mean we do want this message hash tracking in "production" also?
I thought it is just meant for special purpose testing, aka reliability. Do we want it for all releases?

+There are some consideration. As we know (I hope sometime we get there to fix it) if a function call appears in log argument list, that will be called twice. So there is a performance issue with it, although if that is not in scope for msg hash logging we can think of it as acceptable and add all computeMessageHash call right into the log call and not outside, that way if log level is higher it will be never called, just like with the compile option.
Currently we have many places where it is called before the log line.

I think template can help that it is a single place of responsibility and not spread, which is overall a better design I think.
So it is very easy to change.

• One enhancement idea upon message hash calculation (Even more important in case we do want to log it every case, all the time).
  So I would add an optional private message_hash field for WakuMessage + a compute function. That function can decide if we need to calculate it (compile flag, cli flag, etc.) and will calculate only for the first call, if the hash is already calculated for that particular message it can just return the value. That can save precious amount of computation time even at high message rates, also solves the double call issue with logging.

How do you see this applicable? I dont think such an extension to WakuMessage would ruin anything.

[Ivansete-status]

Thank you so much for the comments @NagyZoltanPeter !
I agree that there is room for improvement wrt the CPU usage.
Nevertheless, the current main goal is to achieve message reliability, and I think we can sacrifice CPU usage for now.
My suggestion is, for now, keeping the implementation as simple as possible and we can resume the CPU optimization in the future. WDYT?

On the other hand, notice that msg_hash cannot be part of WakuMessage because it is calculated based on a given pubsub-topic. We may need to have some kind of msg_hashes: Table[pubsub_topic, msg_hash] attribute but as I mentioned, I think it better something to consider in the future ;P

Let me answer your questions more precisely :)

Hey, what is the aim with notice level logging?

Using NTC log level will help the DST-team-reliability-analysis-tool to work faster because it needs to analyze smaller log files. In other words, @AlbertoSoutullo can just set the log level to NOTICE and his tool will perform faster.

Is this mean we do want this message hash tracking in "production" also?

Yes, showing msg_hash is mandatory regardless of the CPU penalties.

I thought it is just meant for special purpose testing, aka reliability. Do we want it for all releases?

Yes, we need to keep these intense logs at least until we fully enhance the reliability

Cheers

[NagyZoltanPeter]

Thank you so much for the comments @NagyZoltanPeter ! I agree that there is room for improvement wrt the CPU usage. Nevertheless, the current main goal is to achieve message reliability, and I think we can sacrifice CPU usage for now. My suggestion is, for now, keeping the implementation as simple as possible and we can resume the CPU optimization in the future. WDYT?

On the other hand, notice that msg_hash cannot be part of WakuMessage because it is calculated based on a given pubsub-topic. We may need to have some kind of msg_hashes: Table[pubsub_topic, msg_hash] attribute but as I mentioned, I think it better something to consider in the future ;P

Let me answer your questions more precisely :)

Hey, what is the aim with notice level logging?

Using NTC log level will help the DST-team-reliability-analysis-tool to work faster because it needs to analyze smaller log files. In other words, @AlbertoSoutullo can just set the log level to NOTICE and his tool will perform faster.

Is this mean we do want this message hash tracking in "production" also?

Yes, showing msg_hash is mandatory regardless of the CPU penalties.

I thought it is just meant for special purpose testing, aka reliability. Do we want it for all releases?

Yes, we need to keep these intense logs at least until we fully enhance the reliability

Cheers

@Ivansete-status : Thank you, I appreciate all the explanation. Most of my quotes were only question due to missed track of this flow.
Yes, we can now live with the performance penalties for now definitely.

Just another question, non-blocking at all!
From message instance point of view, do we know that if one message appears in the system (decoded from network buffer after a call to relay or lightpush). So that particular message instance is tied to exact one pubsub_topic (regardless of what type of sharding). OR! Can we imagine that different calls with same WakuMessage (byte-to-byte equal) can result in one message instance (thus possible to have different topic)?

[NagyZoltanPeter]

All discussed and all good, thank you!!!