Add tracing logic in pallet macro for hooks and dispatchables

[gui1117]

Fix #8303

decl_module add some tracing logic. This tracing is now also expanded in pallet macro.

Note that the tracing slightly differ between dispatchables from decl_module as the logic of the dispatchable function is not changed in the pallet macro.
Instead the trace is entered in the UnfilteredDispatch implementation (which is the implementation called when dispatching an extrinsic)

[emostov]

Does it make sense to add some tests to show how the traces in the new macro compare with the old macro?

[kianenigma]

Test would be nice, but since I think we can and should drop support for decl_ in the next release, fine without it as well.

[dvdplm]

cc @insipx

[bkchr]

Test would be nice, but since I think we can and should drop support for decl_ in the next release, fine without it as well.

If someone is relying on this stuff, we need a test for this.

[gui1117]

I can't find any test for now, I think I can do something similar to https://github.com/paritytech/substrate/blob/master/primitives/api/test/tests/runtime_calls.rs#L220
Is there a more simple way to check the trace in tests ? like by initializing tracing_subscriber in some way which writes to some local vec instead of stderr ?

[gui1117]

I agree that test should be better but considering decl_module doesn't test them either, I think it can be move to another PR/issue: paritytech/polkadot-sdk#333

[bkchr]

like by initializing tracing_subscriber in some way which writes to some local vec instead of stderr ?

Yeah that also works.

But the issue is okay for now.

[emostov]

Just wanted to document here a difference with the spans from old vs new macro I noticed:

2021-03-11 11:30:24.833  TRACE tokio-runtime-worker sc_tracing: pallet_timestamp::pallet: on_initialize, time: 7194, id: 38281146588463105, parent_id: None    
2021-03-11 11:30:24.833  TRACE tokio-runtime-worker sc_tracing: pallet_babe: on_initialize, time: 43113, id: 40532946402148353, parent_id: None

new macro targets: pallet_{{pallet name}}::pallet
old macro targets: pallet_{{pallet name}}

Guillaume mentioned offline using something like

<T::PalletInfo as frame_support::traits::PalletInfo>::name::<#pallet_ident<#type_use_gen>>()

to see if that gets the correct target name. I am going to give that a go.

[gui1117]

if need the pallet name better to trace it explicitly instead of just tracing: on_initialize.
the new macro define the function in the module pallet that's why it is written in the tracing.

[shawntabrizi]

I am out of the loop on who is relying on these traces and why we need tests?

I mean tests are great, but are people taking a dependency on trace information to trigger some workflows?

[emostov]

I am out of the loop on who is relying on these traces and why we need tests?

@shawntabrizi As of now, the current designs for balance reconciliation (and general state change auditing) rely on tracking DB read/writes via traces. A fragile approach, but it is the current approach.

Also to follow up on my earlier comments, I am happy with this PR as is. Tests are nice but given the current status quo I don't think they should be a blocker.
As discussed offline with @dvdplm, @insipix - there may be merit in adding the instantiated pallets name (i.e. how it is named in the runtime) to the spans as values in order to correctly attribute events; however that is beyond the scope of this PR.

[dvdplm]

lgtm

[gui1117]

bot merge

[ghost]

Waiting for commit status.

[ghost]

Checks failed; merge aborted.

[gui1117]

bot merge

[ghost]

Checks failed; merge aborted.