Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore: adding observers for message logging #2800

Merged
merged 11 commits into from
Jun 13, 2024

Conversation

gabrielmer
Copy link
Contributor

@gabrielmer gabrielmer commented Jun 11, 2024

Description

Adding observers so the hash and origin/destination of every message sent and received is logged. This will help with our reliability simulation efforts.

This adds lots of logs, so there's always the option to have it under a compilation flag. Let me know if that's preferable or if it's ok for now and we'll make them optional at a later stage.

Note

We're finally adding observers only for messages received, as no additional valuable information is currently added by logging sent messages. If necessary at any point, they can be easily activated.

Changes

  • added nim-libp2p observers for incoming and outgoing messages to log message data

Example output:

image

Copy link

github-actions bot commented Jun 11, 2024

You can find the image built from this PR at

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

Built from e29af21

Copy link

github-actions bot commented Jun 11, 2024

You can find the image built from this PR at

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

Built from e29af21

@gabrielmer gabrielmer marked this pull request as ready for review June 13, 2024 10:12
Copy link
Collaborator

@Ivansete-status Ivansete-status left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM! Thanks! A very clean PR 🥳
I just added some comments that I hope you find useful.
On the other hand, we might need to review the following snippet because I have the feeling that we will duplicate some logs when a message is rx.

I think we could potentially move that logic to the new one, when a message is received.

proc traceHandler(topic: PubsubTopic, msg: WakuMessage) {.async, gcsafe.} =
notice "waku.relay received",
my_peer_id = node.peerId,
pubsubTopic = topic,
msg_hash = topic.computeMessageHash(msg).to0xHex(),
receivedTime = getNowInNanosecondTime(),
payloadSizeBytes = msg.payload.len
let msgSizeKB = msg.payload.len / 1000
waku_node_messages.inc(labelValues = ["relay"])
waku_histogram_message_size.observe(msgSizeKB)

waku/node/waku_node.nim Outdated Show resolved Hide resolved
waku/node/waku_node.nim Outdated Show resolved Hide resolved
waku/node/waku_node.nim Outdated Show resolved Hide resolved
waku/node/waku_node.nim Outdated Show resolved Hide resolved
waku/node/waku_node.nim Outdated Show resolved Hide resolved
waku/node/waku_node.nim Outdated Show resolved Hide resolved
@AlbertoSoutullo
Copy link

Allow me to jump here and give some personal point of view c:

I did some analysis on v0.28.0-rc.0. One of the problems that I faced with that version is for relay, this is an example of a received message log line:

DBG 2024-06-11 17:18:51.085+00:00 waku.relay received                        topics="waku node" tid=7 file=waku_node.nim:229 my_peer_id=16U*TnatWR pubsubTopic=/waku/2/rs/2/0 msg_hash=0x15e25e4a98318a664762d29efadc0b47451a7bf92aa01ec3071858a68d6ace6b receivedTime=1718126331085366272 payloadSizeBytes=1000

I think a mix between something like the previous line and what you did would be perfect. Because the only thing that I was missing from the previous line was something like from_peer field that you added. With this, it is very easy to build a trace of the message. But also, I have in the same line my_peer_id, which helps to build this without too much headache, and is something that is missing in this PR I think.
If it doesn't add too much trouble, I would be happy to have that information on that log line.

On the other hand, I don't know your motivation regarding logging received and sent. But from my perspective, this is redundant information. You can either trace the logs searching for received information to analyze the messages in the mesh, or look for the sent information. So here, you are logging twice the amount of information.
One example that I can give you is that from my side, and just searching for received log lines, I can build a Dataframe with indexed columns as timestamp and msg_hash, and then have normal columns with from_peer and to_peer. This allows me to create a trace of a message, check for a specific message how much time it took to reach all nodes, and many other things.
I am trying to think what additional information could I extract by reading the sent log lines, but right now I cannot think about any.

So if you are concerned about the amount of logging, and if you don't think about any benefit of this, I would recommend just stick to received information.

Copy link
Contributor

@NagyZoltanPeter NagyZoltanPeter left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is super cool!
About the compilation flag question. I'm on the side not to have such logs when out to production as it is not just overwhelming amount of logs but reveals way toooo much information about the network and messages.

@Ivansete-status
Copy link
Collaborator

It is super cool! About the compilation flag question. I'm on the side not to have such logs when out to production as it is not just overwhelming amount of logs but reveals way toooo much information about the network and messages.

I see your point. Nevertheless, I think for now it is interesting to have it in that way because it is much simpler than having a compilation flag and we are just disclosing a bit of information about the neighbors but doesn't bring a picture of the whole network.

We can revisit that in the future if needed but for now is fine IMHO.
( cc @gabrielmer )

@gabrielmer
Copy link
Contributor Author

I think I'll merge it as it is now, and if needed we can add the compilation flag anytime :)

@gabrielmer gabrielmer merged commit b522865 into master Jun 13, 2024
16 of 19 checks passed
@gabrielmer gabrielmer deleted the chore-add-logger-observers branch June 13, 2024 16:35
gabrielmer added a commit that referenced this pull request Jun 17, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants