Add node name to the log lines #7328

cecton · 2020-10-15T10:05:49Z

Related to paritytech/cumulus#149

polkadot companion: paritytech/polkadot#1825

Forked at: d67fc4c Parent branch: origin/master

bkchr · 2020-10-15T12:00:34Z

Can you please explain on what your idea here is? I don't see the connection to the ticket and what we spoke about.

Forked at: d67fc4c Parent branch: origin/master

cecton · 2020-10-15T12:29:27Z

Yes it's more related to paritytech/cumulus#154 actually.

This change already prefixes the logs with the node name. Example here on substrate:

2020-10-15 13:32:49  Substrate Node    
2020-10-15 13:32:49  ✌️  version 2.0.0-a55ccf09b-x86_64-linux-gnu    
2020-10-15 13:32:49  ❤️  by Parity Technologies <admin@parity.io>, 2017-2020    
2020-10-15 13:32:49  📋 Chain specification: Flaming Fir    
2020-10-15 13:32:49  🏷 Node name: wry-wren-1666    
2020-10-15 13:32:49  👤 Role: FULL    
2020-10-15 13:32:49  💾 Database: RocksDb at /tmp/substrateHXzOtQ/chains/flamingfir8/db    
2020-10-15 13:32:49  ⛓  Native runtime: node-259 (substrate-node-1.tx1.au10)    
2020-10-15 13:32:50  🔨 Initializing Genesis block/state (state: 0x89b8…d3e7, header-hash: 0xe40f…ed39)    
2020-10-15 13:32:50  👴 Loading GRANDPA authority set from genesis on what appears to be first startup.    
2020-10-15 13:32:50  ⏱  Loaded block-time = 3000 milliseconds from genesis on first-launch    
2020-10-15 13:32:50  👶 Creating empty BABE epoch changes on what appears to be first startup.    
2020-10-15 13:32:50  🏷 Local node identity is: 12D3KooWSQXLEGL2Ho2Qq8djLTXysTDhoTjFAUYvvEjbfW1kSd4F    
2020-10-15 13:32:50  [wry-wren-1666] substrate-node: 📦 Highest known block at #0    
2020-10-15 13:32:50  [wry-wren-1666] substrate-node: 〽️ Prometheus server started at 127.0.0.1:9615    
2020-10-15 13:32:50  [wry-wren-1666] substrate-node: Listening for new connections on 127.0.0.1:9944.    
2020-10-15 13:32:51  🔍 Discovered new external address for our node: /ip4/91.181.156.13/tcp/30333/p2p/12D3KooWSQXLEGL2Ho2Qq8djLTXysTDhoTjFAUYvvEjbfW1kSd4F    
2020-10-15 13:32:55  [wry-wren-1666] substrate-node: 💤 Idle (0 peers), best: #0 (0xe40f…ed39), finalized #0 (0xe40f…ed39), ⬇ 2.7kiB/s ⬆ 2.4kiB/s    
2020-10-15 13:33:00  [wry-wren-1666] substrate-node: 💤 Idle (0 peers), best: #0 (0xe40f…ed39), finalized #0 (0xe40f…ed39), ⬇ 67 B/s ⬆ 58 B/s    
2020-10-15 13:33:05  [wry-wren-1666] substrate-node: 💤 Idle (0 peers), best: #0 (0xe40f…ed39), finalized #0 (0xe40f…ed39), ⬇ 0 ⬆ 0

On cumulus we will get the node name of the parachain and the relaychain depending on which node is the log. We could also customize this instead of using the node name (it's not done but it's doable easily if you want).

The way this is done is by using a span from tracing which includes the node name.

I still need to figure out for separating the telemetry.

Forked at: d67fc4c Parent branch: origin/master

bkchr · 2020-10-15T12:54:43Z

This should be an optional feature and we actually want to have [Parachain] or [Relaychain] being printed as we already do it in some places.

And why are still some lines without any prefix in your example output?

Regarding telemetry, as I said, we should pass this object around like prometheus.

cecton · 2020-10-15T13:00:23Z

This should be an optional feature and we actually want to have [Parachain] or [Relaychain] being printed as we already do it in some places.

Yes, I don't see any blocker for that. No worry.

And why are still some lines without any prefix in your example output?

Some are definitely outside the span (the span is created in client/service/src/builder.rs fn spawn_tasks().

Some I'm not sure I'm investigating.

Regarding telemetry, as I said, we should pass this object around like prometheus.

Tbh I'm still not 100% to understand how telemetry works. I'm still investigating.

bkchr · 2020-10-15T13:14:41Z

Tbh I'm still not 100% to understand how telemetry works. I'm still investigating.

We just call a macro that aggregates the data and sends it as json to the server. But that is not important at all. Important is that we replace the singleton with an instance that is passed everywhere and we pass this instance to these macros.

But this is clearly now part of another pr!

Forked at: d67fc4c Parent branch: origin/master

This reverts commit 9055ec2. dtolnay/trybuild#53

Forked at: d67fc4c Parent branch: origin/master

bkchr

Some last changes and than we are ready.

client/basic-authorship/src/basic_authorship.rs

bkchr · 2020-10-21T12:45:42Z

client/cli/proc-macro/src/lib.rs

+use quote::quote;
+use syn::{Error, Expr, Ident, ItemFn};
+
+/// Macro that inserts a tracing span with the node name at the beginning of the function.


This says something different than the body.

I fixed the doc. Should be more consistent

bkchr · 2020-10-21T12:47:04Z

client/cli/proc-macro/src/lib.rs

+///
+/// # Implementation notes
+///
+/// If there are multiple spans with a node name, only the latest will be shown.


Suggested change

/// If there are multiple spans with a node name, only the latest will be shown.

/// If there are multiple spans with a log prefix, only the latest will be shown.

Or similar?

bkchr · 2020-10-21T12:47:16Z

client/cli/proc-macro/src/lib.rs

+///
+/// ```ignore
+/// Builds a new service for a light client.
+/// #[sc_cli::substrate_cli_node_name("light")]


bkchr · 2020-10-21T12:49:33Z

client/cli/proc-macro/src/lib.rs

+	(quote! {
+		#(#attrs)*
+		#vis #sig {
+			let span = #crate_name::tracing::info_span!("substrate-node", name = #name);


Can this span name not be a constant in sc-cli? And it should be renamed to substrate-log-prefix or similar.

hardly because I can't import the const from sc-cli (sc-cli-proc-macro is a dependency of sc-cli). And I'm not too fan to put it in the the proc macro crate... but if you want think it's better I will do it

oh wait, you're right. I see. nevermind!

client/cli/src/logging.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Forked at: d67fc4c Parent branch: origin/master

cecton · 2020-10-21T15:00:18Z

BOT MERGE

ghost · 2020-10-21T15:00:24Z

Checks failed; merge aborted.

cecton · 2020-10-21T15:00:52Z

geezus

cecton · 2020-10-21T15:01:04Z

bot merge --force

cecton · 2020-10-21T15:13:01Z

bot merge force

ghost · 2020-10-21T15:13:06Z

Trying merge.

cecton added 6 commits October 7, 2020 13:14

Initial commit

88c1f42

Forked at: d67fc4c Parent branch: origin/master

WIP

95762f1

Forked at: d67fc4c Parent branch: origin/master

WIP

685c122

Forked at: d67fc4c Parent branch: origin/master

WIP

fea1d0c

Forked at: d67fc4c Parent branch: origin/master

WIP

f0d5964

Forked at: d67fc4c Parent branch: origin/master

WIP

a55ccf0

Forked at: d67fc4c Parent branch: origin/master

github-actions bot added the A3-in_progress Pull request is in progress. No review needed at this stage. label Oct 15, 2020

cecton added 2 commits October 15, 2020 13:44

CLEANUP

ad7dbd5

Forked at: d67fc4c Parent branch: origin/master

Add notes to original source code

c8e0841

CLEANUP

dc2f401

Forked at: d67fc4c Parent branch: origin/master

CLEANUP

34106dd

Forked at: d67fc4c Parent branch: origin/master

cecton added 8 commits October 15, 2020 15:32

WIP

76f2d43

Forked at: d67fc4c Parent branch: origin/master

WIP

0c278a8

Forked at: d67fc4c Parent branch: origin/master

WIP

8257480

Forked at: d67fc4c Parent branch: origin/master

CLEANUP

47f7d3f

Forked at: d67fc4c Parent branch: origin/master

WIP

efb9b82

Forked at: d67fc4c Parent branch: origin/master

Some doc

346eaf1

Test with trybuild

9055ec2

Revert "Test with trybuild" (issue with trybuild atm)

d46d87b

This reverts commit 9055ec2. dtolnay/trybuild#53

cecton marked this pull request as ready for review October 16, 2020 06:34

github-actions bot added A0-please_review Pull request needs code review. and removed A3-in_progress Pull request is in progress. No review needed at this stage. labels Oct 16, 2020

cecton requested review from andresilva, bkchr and sorpaas October 16, 2020 06:35

cecton added 9 commits October 21, 2020 09:42

CLEANUP

a554480

Forked at: d67fc4c Parent branch: origin/master

Improve error message

58a7284

CLEANUP

de4678f

Forked at: d67fc4c Parent branch: origin/master

Fix async issue

c101a09

CLEANUP

35ae152

Forked at: d67fc4c Parent branch: origin/master

CLEANUP

fb4c7bb

Forked at: d67fc4c Parent branch: origin/master

Add test

2238794

fix doc test

c4e0039

Merge commit c2469eb (no conflict)

1a72fc5

bkchr reviewed Oct 21, 2020

View reviewed changes

cecton and others added 6 commits October 21, 2020 15:00

Update client/cli/src/logging.rs

2752062

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Update client/basic-authorship/src/basic_authorship.rs

208bbe2

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Update client/basic-authorship/src/basic_authorship.rs

243dd6c

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Apply suggestions

929bd1e

Suggestions

f12a3f7

Clarify doc

b9d7723

bkchr approved these changes Oct 21, 2020

View reviewed changes

github-actions bot removed the A7-needspolkadotpr label Oct 21, 2020

WIP

f141b73

Forked at: d67fc4c Parent branch: origin/master

github-actions bot added the A7-needspolkadotpr label Oct 21, 2020

ghost merged commit a467358 into master Oct 21, 2020

ghost deleted the cecton-logging-singleton branch October 21, 2020 15:13

tomaka mentioned this pull request Nov 3, 2020

Exclude basic-authorship-proposer from the continuous tasks alert #7484

Merged

dvdplm mentioned this pull request Nov 4, 2020

RPC to allow setting the log filter #7474

Merged

5 tasks

This pull request was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add node name to the log lines #7328

Add node name to the log lines #7328

cecton commented Oct 15, 2020 •

edited

Loading

bkchr commented Oct 15, 2020

cecton commented Oct 15, 2020

bkchr commented Oct 15, 2020

cecton commented Oct 15, 2020

bkchr commented Oct 15, 2020

bkchr left a comment

bkchr Oct 21, 2020

cecton Oct 21, 2020

bkchr Oct 21, 2020

cecton Oct 21, 2020

bkchr Oct 21, 2020

cecton Oct 21, 2020

bkchr Oct 21, 2020

cecton Oct 21, 2020

cecton Oct 21, 2020

cecton Oct 21, 2020

cecton commented Oct 21, 2020

ghost commented Oct 21, 2020

cecton commented Oct 21, 2020

cecton commented Oct 21, 2020

cecton commented Oct 21, 2020

ghost commented Oct 21, 2020

	/// If there are multiple spans with a node name, only the latest will be shown.
	/// If there are multiple spans with a log prefix, only the latest will be shown.

Add node name to the log lines #7328

Add node name to the log lines #7328

Conversation

cecton commented Oct 15, 2020 • edited Loading

bkchr commented Oct 15, 2020

cecton commented Oct 15, 2020

bkchr commented Oct 15, 2020

cecton commented Oct 15, 2020

bkchr commented Oct 15, 2020

bkchr left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cecton commented Oct 21, 2020

ghost commented Oct 21, 2020

cecton commented Oct 21, 2020

cecton commented Oct 21, 2020

cecton commented Oct 21, 2020

ghost commented Oct 21, 2020

cecton commented Oct 15, 2020 •

edited

Loading