chore: add better e2e trace logging for relay

[jm-clius]

Hopefully an easy fix for #1394

Improves relay trace logging on publishing and receiving a message, to log:

• a hash of the message
• publish/arrival timestamp
• pubsubTopic

@Daimakaimura my understanding is that this will cover your needs? Anything else that would be required/nice to have?

This will result in the following example trace log on the relaying node:

TRC 2023-02-01 14:48:52.270+02:00 waku.relay received                        topics="waku node" tid=22467 file=waku_node.nim:310 pubsubTopic=/waku/2/default-waku/proto hash=0x1220b9cb650d6af10c34d9d882a609d9aa6d506b0831f8f01a8e27be3c665d889974 receivedTime=1675255732000000000

and on the publishing node

TRC 2023-02-01 14:48:52.270+02:00 waku.relay published                        topics="waku node" tid=22467 file=waku_node.nim:310 pubsubTopic=/waku/2/default-waku/proto hash=0x1220b9cb650d6af10c34d9d882a609d9aa6d506b0831f8f01a8e27be3c665d889974 publishTime=1675255732000000000

Note:

• log format and hash selected to be roughly similar to go-waku: waku-org/go-waku@a247e83
• hash computation currently done inside trace log statement (to skip compilation when trace logs not enabled), should probably replaced by the message UID concept being developed

[alrevuelta]

Not sure if you already thought about this but I think its important to highlight that this can't just be run with log-level=TRACE and thats it. We would need to use some chronicles flags (which might require recompiling?) in order to disable all TRACE topics and leaving only the ones related to messages arrival times.

In other words, if we run the node as it is with just level=TRACE this will generate tons of Gbs in logs in very short time, and the impact in performance will most likely be quite relevant. Can't imagine a wakurtosis simulation with dozens of nodes, and ofc parsing the logs can be almost impossible. Most likely will kill every machine.

wdyt? Also, would we need to recompile to enable this chronible logs?

[jm-clius]

@alrevuelta Indeed, I did consider this. We can either separate this logging out completely with a compiler flag, e.g. waku_expensive_logging (and log on INFO) or enable only the waku node topic TRACE logging (which should be clean) with a compiler flag (-d:chronicles_enabled_topics). Both would require changes to the compilation. It is not an option to compile and log all TRACE logs, as you've said.

[LNSD]

From the discord conversation:

There is this chronicles option that could be used to generate a special build that only logs certain topics with TRACE level: https://github.com/status-im/nim-chronicles#chronicles_enabled_topics

[status-im-auto]

Jenkins Builds

❔	Commit	#️⃣	Finished (UTC)	Duration	Platform	Result
❌	da91d14	#1	2023-02-01 22:50:40	~3 min	macos	📄log

[alrevuelta]

Perhaps for another PR, but do we plan to compile and push a new docker image for this variant? I would say it would facilitate things for the DS team, but unsure about starting to push many variants of nwaku, can end up being very convoluted.

@Daimakaimura

[jm-clius]

Of course happy to discuss what is practical with the DS team, but I think it's reasonable to have a different compilation and docker image for this. I see this special logging use case basically as a specialised application of Nwaku. I would avoid compiling this logging into our usual image and then only enable this "application" via some runtime configuration. We can address during next steps. The idea now is to get consensus on adding those logs.

[LNSD]

Nobody said anything about pushing any docker image to docker-hub. The image could be built by docker/kurtosis before running any tests. A docker build argument can be added to the current Dockefile to support a perf-test image variant.

While I understand the concerns, please, let's focus the discussion on the information to be displayed in the log message.

[jm-clius]

From #1394 (comment)

I checked the PR Draft and adding those 2 messages to the logs should be okay for us to calculate delays. Regarding the volume in the logs, indeed that could be also another issue and probably the best option would likely to have a flag to enable only these messages (independently of the log level).

Leaving configuration and compilation TBD, but having gotten the 👍 from DS opening for review and merging.

[LNSD]

LGTM ✅