# Why are `pallet_*` spans missing for extrinsic execution in the latest versions of block trace rpc?
## Mar 4
**Observation**: The spans and logging show up for pallets that use the old macro format
### Where the missing spans should come from
The missing spans should come from the runtime module macro with dispatch functions. Specifically [it comes from here](https://github.com/paritytech/substrate/blob/fc2d2d36620140da20ff244219a4259b5e59c83a/frame/support/src/dispatch.rs#L1543)
I proved this by forking commit 4f695c73 and adding some random words right there. You [can see that here.](https://github.com/paritytech/substrate/blob/5d9efdec2ca66723f3b00d2d38c838c6bca03965/frame/support/src/dispatch.rs#L1492). In this branch you will see a span for a dispatch with a target like
```json=
"id": "22",
"line": "428",
"name": "transfer_keep_alive, \"zeke\"",
"parent_id": "21",
"target": "pallet_balances",
```
Interestingly, the "on_initialize" and "on_finalize" spans come from a different part of the same macro. They have always surfaced, so not sure why just the dispatch ones don't seem to work. I also modified those to prove that they are where the spans come from. [See here](https://github.com/paritytech/substrate/blob/5d9efdec2ca66723f3b00d2d38c838c6bca03965/frame/support/src/dispatch.rs#L1280-L1298) and [here](https://github.com/paritytech/substrate/blob/5d9efdec2ca66723f3b00d2d38c838c6bca03965/frame/support/src/dispatch.rs#L1402-L1419)
### When the spans go missing
It breaks from
4f695c73e552d6c8370c67d81b4e9d16f420995d --> 2d54a5ba839f22e81e6d4aaf3674b4268dbc4a07
Diff of changes: https://github.com/paritytech/substrate/compare/4f695c73e552d6c8370c67d81b4e9d16f420995d..2d54a5ba839f22e81e6d4aaf3674b4268dbc4a07?diff=split
There are a ton of changes here. The working commit is Feb 3rd and the next commit is feb 16th so there is a bit of ground to cover. I looked through the entire diff.
The only relevant changes I could idnetify that might affect the tracins is converstion to the new pallet macro for balances and timestamp - the two pallets we are looking for traces from.
### TODO
- Investigate if new macro syntax used for balances and timestamp pallet may be affecting the traces
- Play around with the non-working commit - maybe add some logging to within the macro?
- Could the span some be getting overwritten by another span in newer versions? Maybe can check all the macros to see (possibly take out all other spans and see if the ones we want reappear)
## Mar, 3
Below are examples of with and without the spans that are missing from more recent commits.
My hunch is that the spans come from the call being dispatched. As far as [I could tell the traces spans for dispatchables originate here](https://github.com/paritytech/substrate/blob/aa28fe4a35df8a93b3b564dc91778bb57a8852d7/frame/support/src/dispatch.rs#L1542-L1564) - but I am not really sure.
In the newer comitts I have added a span as well with `pallet_testing` just to see if that shows up, but it doesn't.
I played around with the targets a bit, but to no avail.
**list of known non-working commits**
- `a5a674f3113d474bb8c4d9cffec80d2f2e7f5733`
- `8dc7820e40a54d03b47836659006188d8644ea17`
- 371a8d4aab8047f29ecb69be63fe80a6be95b41e
- 2d54a5ba839f22e81e6d4aaf3674b4268dbc4a07
**working commits**
- 921577a9863a51951709bf204c2b055991c776d7
- d9fd09d33cfcffe005c9c82d37a0668e04844891
- ab17e6d9d93f8ce5a014cfe4e8d727e70cc7f6f1
- 4f695c73e552d6c8370c67d81b4e9d16f420995d
### a working commit: `fcab7a2edfcc0b610e0f57e8e33db733d463991a`
This is a fairly old commmit that contains traces in sp_io::storage, which we no longer have
For a block with a `balances.transferKeepAlive` it contains the spans:
```json
{
"entered": [
{
"nanos": "5442313",
"secs": "0"
}
],
"exited": [
{
"nanos": "6383145",
"secs": "0"
}
],
"id": "19",
"line": "363",
"name": "apply_extrinsic",
"parent_id": "1",
"target": "frame_executive",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
},
{
"entered": [
{
"nanos": "5749672",
"secs": "0"
}
],
"exited": [
{
"nanos": "5995527",
"secs": "0"
}
],
"id": "20",
"line": "139",
"name": "set",
"parent_id": "19",
"target": "pallet_timestamp",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
},
{
"entered": [
{
"nanos": "6455237",
"secs": "0"
}
],
"exited": [
{
"nanos": "9451056",
"secs": "0"
}
],
"id": "21",
"line": "363",
"name": "apply_extrinsic",
"parent_id": "1",
"target": "frame_executive",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
},
{
"entered": [
{
"nanos": "7596610",
"secs": "0"
}
],
"exited": [
{
"nanos": "8225002",
"secs": "0"
}
],
"id": "22",
"line": "428",
"name": "transfer_keep_alive",
"parent_id": "21",
"target": "pallet_balances",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
}
```
### a non-working commit: `a5a674f3113d474bb8c4d9cffec80d2f2e7f5733`
Now the equivalent is is missing the pallet specific spans
```json
{
"entered": [
{
"nanos": "6697527",
"secs": "0"
}
],
"exited": [
{
"nanos": "7955866",
"secs": "0"
}
],
"id": "17",
"line": "393",
"name": "apply_extrinsic",
"parent_id": "1",
"target": "frame_executive",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
},
{
"entered": [
{
"nanos": "8052337",
"secs": "0"
}
],
"exited": [
{
"nanos": "12101182",
"secs": "0"
}
],
"id": "18",
"line": "393",
"name": "apply_extrinsic",
"parent_id": "1",
"target": "frame_executive",
"values": {
"bool_values": {},
"i64_values": {},
"string_values": {},
"u64_values": {}
}
}
```
## How this affects balance reconciliations
Both reconcile with a simple balances transfer, but I have not tested beyond that. They both end up with the same amount of operations: 5. So it seems it is ok without the missing spans.
### operations from a non-working commit: `a5a674f3113d474bb8c4d9cffec80d2f2e7f5733`
```json=
[
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "2"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "18"
},
"primarySpanId": {
"id": "18",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "114",
"operationIndex": "0"
},
"address": {
"Id": "5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "-1490319397765",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "2"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "18"
},
"primarySpanId": {
"id": "18",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "119",
"operationIndex": "1"
},
"address": {
"Id": "5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "-100000000000000000",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "2"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "18"
},
"primarySpanId": {
"id": "18",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "121",
"operationIndex": "2"
},
"address": {
"Id": "5CiPPseXPECbkjWCa6MnjNokrgYjMqmKndv2rSnekmSK2DjL"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "100000000000000000",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "2"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "18"
},
"primarySpanId": {
"id": "18",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "130",
"operationIndex": "3"
},
"address": {
"Id": "5EYCAe5ijiYfyeZ2JJCGq56LmPyNRAKzpG4QkoQkkQNB5e6Z"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "1192255518212",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "2"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "18"
},
"primarySpanId": {
"id": "18",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "141",
"operationIndex": "4"
},
"address": {
"Id": "5GNJqTPyNqANBkUVMN1LPPrxXnFouWXoe2wNSmmEoLctxiZY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "298063879553",
"currency": {
"symbol": "Unit"
}
}
}
]
```
operations from working commit: `fcab7a2edfcc0b610e0f57e8e33db733d463991a`
```json=
[
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "1"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "21"
},
"primarySpanId": {
"id": "21",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "108",
"operationIndex": "0"
},
"address": {
"Id": "5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "-1490319384158",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "1"
},
"parentSpanId": {
"name": "transfer_keep_alive",
"target": "pallet_balances",
"id": "22"
},
"primarySpanId": {
"id": "21",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "113",
"operationIndex": "1"
},
"address": {
"Id": "5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "-100000000000000000",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "1"
},
"parentSpanId": {
"name": "transfer_keep_alive",
"target": "pallet_balances",
"id": "22"
},
"primarySpanId": {
"id": "21",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "115",
"operationIndex": "2"
},
"address": {
"Id": "5CiPPseXPECbkjWCa6MnjNokrgYjMqmKndv2rSnekmSK2DjL"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "100000000000000000",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "1"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "21"
},
"primarySpanId": {
"id": "21",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "124",
"operationIndex": "3"
},
"address": {
"Id": "5EYCAe5ijiYfyeZ2JJCGq56LmPyNRAKzpG4QkoQkkQNB5e6Z"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "1192255507326",
"currency": {
"symbol": "Unit"
}
}
},
{
"id": {
"phase": {
"variant": "apply_extrinsic",
"applyExtrinsicIndex": "1"
},
"parentSpanId": {
"name": "apply_extrinsic",
"target": "frame_executive",
"id": "21"
},
"primarySpanId": {
"id": "21",
"name": "apply_extrinsic",
"target": "frame_executive"
},
"eventIndex": "135",
"operationIndex": "4"
},
"address": {
"Id": "5GNJqTPyNqANBkUVMN1LPPrxXnFouWXoe2wNSmmEoLctxiZY"
},
"storage": {
"pallet": "system",
"item": "Account",
"field": "data.free"
},
"amount": {
"value": "298063876832",
"currency": {
"symbol": "Unit"
}
}
}
]
```
Sign in with Wallet
Connect another wallet