feat(iroh, iroh-gossip): introduce `log-self` feature #1544

divagant-martian · 2023-09-28T20:50:22Z

Description

Aff a feature flag to turn on logging our own peer_id in short form and plug this in in sync, gossip and the downloader. This is enabled by default (not sure if we want this for releases thought. Having it as a feature flag at least gives us the option to chose.

This is what I did to debug #1531 and it was really useful

Notes & open questions

Log sample:

Sync

2023-09-28T20:51:18.908126Z DEBUG sync{me=oywqb57ovmdry243}: iroh::sync_engine::live: sync[dial]: start namespace=NamespaceId(q47zmyim5r6isz22…) peer=PublicKey(2jnygwapdm26wwa2) reason=DirectJoin last_state=None

Gossip

2023-09-28T20:58:42.854730Z DEBUG gossip{me=zooj7iazcl7rsoal}: iroh_gossip::net: handle out_event EmitEvent(TopicId(wno5nwxtkhhtnqsm…), Received(GossipEvent { content: <33b>, delivered_from: PublicKey(7a7kkzndvbt6eulu), scope: Neighbors }))

Downloader

2023-09-28T21:00:11.107411Z DEBUG downloader{me=4vabufwku3wselbl}: iroh::downloader: download completed peer=2jnygwapdm26wwa26tvcprm3m5vqajmhwz7lx5xizwx637ad5sea kind=Blob { hash: Hash(224746ea89d286220e0770f89cda2ab138143b00e384dd795d5a13b77b094822) }

Change checklist

Self-review.
Documentation updates if relevant.
Tests if relevant.

flub

Why not always do this instead of the extra feature and conditional compilation? If it's useful, which it clearly is, then let's just always do it.

flub · 2023-09-29T08:42:37Z

iroh-gossip/src/net.rs

-            if let Err(err) = actor.run().await {
+            let fut = actor.run();
+            #[cfg(feature = "log-self")]
+            let fut = fut.instrument(trace_span!("gossip", %me));


since this is a spawned future I'd strongly recommend to use an info_span. And also to not make it depend on the feature. Every task should have it's own info_span attached as a general rule.

The span should also cover the bit of error handing in the lines below that are still inside this spawned task.

can you explain why info_span? looking throughout the code we still have trace_span once in baomap, debug_span 16 times. Looking at what Frando did in his own branch for his needs he went with trace as well and it seems to work well. What's the difference?

My general guideline is to use info_span for spawned tasks, motivation:

If something is spawned it usually is a "top level task" of some sort (with a serious pinch of salt).

In this case you want to see most log messages with that span attached

and if you set the level to info, debug or trace you will see that attached span by default

(bonus: this matches the "info is for operators" guidance we just discussed)

This does not mean we already do this everywhere consistently. I've done a few PRs in the past making this more consistent but it certainly isn't complete.

Now I understand your reluctance to always having this logging on and that having this as debug or trace makes it even easier to hide. but i do really think this is more useful at info.

ok just to be clear about my question I don't understand what this changes, not sure what the effect of this is.

Is the effect to add the fields only from info and above? if so then don't think this will help in debugging tests
if the effect is to limit to info and below then it's probably better

but then it's confusing that trace still gives me debug logs with peer_ids.

TLDR: I'm confused about what the levels do here

See also https://discord.com/channels/949724860232392765/950683937661935667/1156506832567808060 where @Frando is also asked me this question and I (hopefully!) gave a similar answer.

flub · 2023-09-29T08:49:29Z

iroh/src/downloader.rs

@@ -237,6 +241,12 @@ impl Downloader {

            let service = Service::new(getter, dialer, concurrency_limits, msg_rx);

+            #[cfg(feature = "log-self")]
+            {
+                service.run().instrument(trace_span!("downloader", %me))


same here, it should always attach the span and be info_span as it's run in a task. Again try to do it around the entire spawned future and not just the service.run() method.

flub · 2023-09-29T08:50:11Z

iroh/src/sync_engine/live.rs

-            if let Err(err) = actor.run().instrument(span).await {
+            let fut = actor.run();
+            #[cfg(feature = "log-self")]
+            let fut = fut.instrument(trace_span!("sync", %me));


same note, info_span and cover entire future that's spawned into the task.

Arqu · 2023-09-29T09:52:54Z

This might / will be PII eventually, so having the option to scrub it is nice.

dignifiedquire · 2023-09-29T11:19:21Z

This might / will be PII eventually

unlikely, peerids are sent over the network and shared as identifiers.
if we really need to scrub PII we should do so on themlog storage side, as there is already much more in the logs, like ip addresses

Frando · 2023-10-02T10:03:59Z

Yeah, let's add this. Test logs with multiple nodes are basically unusable without. I did parts of this in #1530 but let's get this in here!

@flub has more experience with tracing then I do so don't have much to add on the implementation front.

In addition to the places where you added the span, I'd recommend to...

also add a similar span to the main node actor loop
change the span in iroh-net to use the same format (%me) with me = peer_id.fmt_short() instead of the magicsock name that is used currently
but those could also be followups

divagant-martian · 2023-10-02T13:27:48Z

can people comment on deciding to make this a compile time flag? @Frando @dignifiedquire @flub (heck we are four here let's just bring @ramfox and @b5 ) my thinking is that logs are already very hard to read. Your own peer id is useful only when you are dealing with multiple nodes in the single run.

This is not the case of users in general, and I would not include this in release builds by default for example. Basically I think it's very nice to be able to have cleaner logs by just removing a feature because this adds "a lot" to already noisy logs

divagant-martian · 2023-10-02T13:46:46Z

agreed feature is not necessary

flub · 2023-10-02T14:53:18Z

agreed feature is not necessary

for completeness: everyone agreed the logging added here is super useful and we should totally have it. but we prefer it always-on, so without the crate-level feature to control it.

i don't mind if you want to re-open this and remove the crate-feature or re-create the PR. though I think it's a reasonable refactor to do to this PR so re-opening might be easier.

## Description second take at #1544 since forced pushed closed prs can't be reopened #### Magicsock ``` 2023-10-02T18:46:34.455601Z DEBUG magicsock{me=2luekswh7o3a5tz4}:derp.actor:recv_detail:client-connect{key=2luekswh7o3a5tz4enymovsoksgnpb2qpmxlvifp6ywwjnacihya}:connect_0: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck] ``` #### Sync ```log 2023-09-28T20:51:18.908126Z DEBUG sync{me=oywqb57ovmdry243}: iroh::sync_engine::live: sync[dial]: start namespace=NamespaceId(q47zmyim5r6isz22…) peer=PublicKey(2jnygwapdm26wwa2) reason=DirectJoin last_state=None ``` #### Gossip ```logs 2023-09-28T20:58:42.854730Z DEBUG gossip{me=zooj7iazcl7rsoal}: iroh_gossip::net: handle out_event EmitEvent(TopicId(wno5nwxtkhhtnqsm…), Received(GossipEvent { content: <33b>, delivered_from: PublicKey(7a7kkzndvbt6eulu), scope: Neighbors })) ``` #### Downloader ``` 2023-09-28T21:00:11.107411Z DEBUG downloader{me=4vabufwku3wselbl}: iroh::downloader: download completed peer=2jnygwapdm26wwa26tvcprm3m5vqajmhwz7lx5xizwx637ad5sea kind=Blob { hash: Hash(224746ea89d286220e0770f89cda2ab138143b00e384dd795d5a13b77b094822) } ``` ## Notes & open questions probably we will add this in other places or change the logging level but would be good to get this in to at least have something over which we can iterate ## Change checklist - [x] Self-review. - [ ] Documentation updates if relevant. - [ ] Tests if relevant.

divagant-martian and others added 7 commits September 28, 2023 14:17

introduce log_self feature

e60dcb0

introduce log_self feature in iroh-gossip

a0b8e39

short fmt

0751c65

couple corrections

11ccf9b

feature flag me

e073d38

more corrections

a4f997a

Merge branch 'main' into log_self

e3d944a

divagant-martian requested review from Frando and flub September 28, 2023 21:14

divagant-martian changed the title ~~feat(iroh, iroh-gossip0: introduce log-self feature~~ feat(iroh, iroh-gossip): introduce log-self feature Sep 28, 2023

flub reviewed Sep 29, 2023

View reviewed changes

b5 added this to the v0.7.0 milestone Sep 29, 2023

b5 assigned divagant-martian Oct 2, 2023

divagant-martian closed this Oct 2, 2023

divagant-martian mentioned this pull request Oct 2, 2023

feat(*): log me #1561

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(iroh, iroh-gossip): introduce `log-self` feature #1544

feat(iroh, iroh-gossip): introduce `log-self` feature #1544

divagant-martian commented Sep 28, 2023 •

edited

Loading

flub left a comment

flub Sep 29, 2023

divagant-martian Oct 2, 2023

flub Oct 2, 2023

divagant-martian Oct 2, 2023 •

edited

Loading

flub Oct 2, 2023

flub Sep 29, 2023

flub Sep 29, 2023

Arqu commented Sep 29, 2023

dignifiedquire commented Sep 29, 2023

Frando commented Oct 2, 2023 •

edited

Loading

divagant-martian commented Oct 2, 2023

divagant-martian commented Oct 2, 2023

flub commented Oct 2, 2023

feat(iroh, iroh-gossip): introduce log-self feature #1544

feat(iroh, iroh-gossip): introduce log-self feature #1544

Conversation

divagant-martian commented Sep 28, 2023 • edited Loading

Description

Notes & open questions

Sync

Gossip

Downloader

Change checklist

flub left a comment

Choose a reason for hiding this comment

flub Sep 29, 2023

Choose a reason for hiding this comment

divagant-martian Oct 2, 2023

Choose a reason for hiding this comment

flub Oct 2, 2023

Choose a reason for hiding this comment

divagant-martian Oct 2, 2023 • edited Loading

Choose a reason for hiding this comment

flub Oct 2, 2023

Choose a reason for hiding this comment

flub Sep 29, 2023

Choose a reason for hiding this comment

flub Sep 29, 2023

Choose a reason for hiding this comment

Arqu commented Sep 29, 2023

dignifiedquire commented Sep 29, 2023

Frando commented Oct 2, 2023 • edited Loading

divagant-martian commented Oct 2, 2023

divagant-martian commented Oct 2, 2023

flub commented Oct 2, 2023

feat(iroh, iroh-gossip): introduce `log-self` feature #1544

feat(iroh, iroh-gossip): introduce `log-self` feature #1544

divagant-martian commented Sep 28, 2023 •

edited

Loading

divagant-martian Oct 2, 2023 •

edited

Loading

Frando commented Oct 2, 2023 •

edited

Loading