Skip to content

per-transaction trace log specification#447

Merged
julio4 merged 11 commits intoflashbots:mainfrom
yashvardhan-kukreja:main
Mar 26, 2026
Merged

per-transaction trace log specification#447
julio4 merged 11 commits intoflashbots:mainfrom
yashvardhan-kukreja:main

Conversation

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor

📝 Summary

Helps trace a transaction from being included in a mempool to getting publishing it over a flashblock.
Doesn't interfere with the existing log levels of rbuilder.

Needs RUST_LOG=tx_trace=info. Even env vars like RUST_LOG=info,tx_trace=info (info logs for reth, but info logs for the txn trace) or RUST_LOG=debug,tx_trace=info (debug logs for reth, but info logs for the txn trace) work.

For example:
(upon setting RUST_LOG=info,tx_trace=info)

ts=2026-03-17T22:14:06.527634651Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a stage=pool_pending
ts=2026-03-17T22:14:06.750443015Z level=info target=payload_builder message="Building flashblock" block_number=12960088 flashblock_index=3 target_gas=22500000 gas_used=46108 target_da=48750 da_used=0 block_gas_used=60000000
ts=2026-03-17T22:14:06.750621405Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 stage=builder_popped
ts=2026-03-17T22:14:06.750757926Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 gas_used=21000 success=true evm_duration_us=108 stage=evm_executed
ts=2026-03-17T22:14:06.750812977Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 cumulative_gas=67108 stage=builder_committed
ts=2026-03-17T22:14:06.750918657Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 duration_us=18 stage=state_merge
ts=2026-03-17T22:14:06.757009631Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 duration_ms=5 incremental=true cumulative_gas=67108 num_txs=2 stage=state_root_computed
ts=2026-03-17T22:14:06.757295365Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 block_hash=0x7ae139513e2f63efa89fcb85eadfd0c17a054a6fa5b3443a7fde388bcbbab49f seal_duration_us=7 build_block_total_us=6322 cumulative_gas=67108 num_txs=2 stage=block_sealed
ts=2026-03-17T22:14:06.75732475Z level=info target=payload_builder event=flashblock_sent message="Sending flashblock to rollup-boost" id=0x0383f9b3eea14c5b index=3 base=false
ts=2026-03-17T22:14:06.757392877Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 byte_size=1900 total_txs=2 stage=fb_published

With RUST_LOG=warn,tx_trace=info, it would have looked like

ts=2026-03-17T22:14:06.527634651Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a stage=pool_pending
ts=2026-03-17T22:14:06.750621405Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 stage=builder_popped
ts=2026-03-17T22:14:06.750757926Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 gas_used=21000 success=true evm_duration_us=108 stage=evm_executed
ts=2026-03-17T22:14:06.750812977Z level=info target=tx_trace message=[TX_TRACE] tx_hash=0xe57ce8001723cf873c6355387ca81162c6916619312af084ae70a5c7d0f6c85a block_number=12960088 flashblock_index=3 cumulative_gas=67108 stage=builder_committed
ts=2026-03-17T22:14:06.750918657Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 duration_us=18 stage=state_merge
ts=2026-03-17T22:14:06.757009631Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 duration_ms=5 incremental=true cumulative_gas=67108 num_txs=2 stage=state_root_computed
ts=2026-03-17T22:14:06.757295365Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 block_hash=0x7ae139513e2f63efa89fcb85eadfd0c17a054a6fa5b3443a7fde388bcbbab49f seal_duration_us=7 build_block_total_us=6322 cumulative_gas=67108 num_txs=2 stage=block_sealed
ts=2026-03-17T22:14:06.757392877Z level=info target=tx_trace message=[TX_TRACE] block_number=12960088 flashblock_index=3 byte_size=1900 total_txs=2 stage=fb_published

💡 Motivation and Context


✅ I have completed the following steps:

  • Run make lint
  • Run make test
  • Added tests (if applicable)

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
Copy link
Copy Markdown
Member

@julio4 julio4 left a comment

Choose a reason for hiding this comment

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

Thanks this can be useful!

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

@julio4 , note: I shifted the log level from info to debug, because even not provinding tx_trace=info was enough to get them generated causing a lot of noise at info level.

So now at debug level, any of the following options would generate these logs RUST_LOG=debug or RUST_LOG: foo,tx_trace=debug

@julio4
Copy link
Copy Markdown
Member

julio4 commented Mar 19, 2026

@julio4 , note: I shifted the log level from info to debug, because even not provinding tx_trace=info was enough to get them generated causing a lot of noise at info level.

So now at debug level, any of the following options would generate these logs RUST_LOG=debug or RUST_LOG: foo,tx_trace=debug

@yashvardhan-kukreja Did you test on dev or release build? In release builds trace are not compiled.
I would be more in favor of not including these in info/debug level and only trace level, but I am not sure your use case and if you need this enabled in release builds

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

yashvardhan-kukreja commented Mar 19, 2026

@julio4 , note: I shifted the log level from info to debug, because even not provinding tx_trace=info was enough to get them generated causing a lot of noise at info level.

So now at debug level, any of the following options would generate these logs RUST_LOG=debug or RUST_LOG: foo,tx_trace=debug

@yashvardhan-kukreja Did you test on dev or release build? In release builds trace are not compiled.

I would be more in favor of not including these in info/debug level and only trace level, but I am not sure your use case and if you need this enabled in release builds

Yep @julio4, as per my knowledge this is a release build (given I am building it directly from the dockerfile with no flag/arg overrides).

  • And we would like this feature to be usable in release build

Semantically speaking, I agree and kinda want to include these logs at trace level and have the user really opt-in into them via tx_trace=trace RUST_LOG setting.

  • But yeah, failing to achieve so, I fell back to debug level especially considering other per-tx debug logs like "Transaction event received" (though this change could create more debug noise)

Pardon my lack of production rust knowledge, is there a way and a negative consequence of enabling this specific trace log? Otherwise, we can just have a dedicated env var (ENABLE_TXN_TRACE_DEBUG_LOG) which when set to true will cause these logs to generate (at debug level) keeping backwards compatibility the max.

Wdyt of these ideas?

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
match event {
FullTransactionEvent::Pending(hash) => {
debug!(
target: "tx_trace",
Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

this is a redundant log with the log below, if you like to filter by target = tx_trace, could consider updating all the target=monitoring tx logs to target=tx_trace? discarded tx logs would also be helpful here I think, and reduces redundant logs

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

yeah I thought of that but didn't want my changes to be intrusive. Happy to make that change if you re ok with that

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Just got done. Note: I got rid of kind tag in favor of stage

@avalonche
Copy link
Copy Markdown
Collaborator

Wondering if adding these to a trace span would be better here

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

yashvardhan-kukreja commented Mar 19, 2026

Wondering if adding these to a trace span would be better here

Hmm yeah but wouldn't that require a tracing setup?

  • Not wrong but yeah I was looking towards having it as a log

Although yeah even trace spans can be logged though they don't look very pretty

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@julio4
Copy link
Copy Markdown
Member

julio4 commented Mar 20, 2026

Wondering if adding these to a trace span would be better here

Hmm yeah but wouldn't that require a tracing setup?

  • Not wrong but yeah I was looking towards having it as a log

Although yeah even trace spans can be logged though they don't look very pretty

We have tracing setup for span under the telemetry flag, but I can understand why you prefer logs for these which are fine as well.

It should be possible to enable trace with a feature like tx-trace-logs = ["tracing/release_max_level_trace"] or changing reth features to use min-trace-logs instead of min-debug-logs (but this would requires to opt-out of reth default-features). With a env filter like RUST_LOG=debug,tx_trace=trace, the runtime overhead should be negligible.

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

With a env filter like RUST_LOG=debug,tx_trace=trace, the runtime overhead should be negligible.

Thanks @julio4 . So just to confirm, with min-trace-logs feature + RUST_LOG=tx_trace=trace, the runtime overhead is going to be negligible as you said right?

  • PS: I don't plan to enable this in normal production use-cases but would be nice to have in some situation where we wanna diagnose a deeper problem. So I am not stressing much about this

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

yashvardhan-kukreja commented Mar 20, 2026

@julio4 unfortunately, the min_trace_logs approach didn't work out.

After building with

 docker build --build-arg FEATURES=min-trace-logs -t yashvardhankukreja/op-rbuilder:log-trace-txns-feature-enabled .

And running it with RUST_LOG=info,tx_trace=trace, I got the following logs

~/OPLabs/Projects/infra/op-conductor-ops main*                                                   09:19:22
❯ k logs -f -n eris-0-opn-geth-f-sequencer-0 op-rbuilder-0
Defaulted container "op-rbuilder" out of: op-rbuilder, download-genesis (init)
warning: some trace filter directives would enable traces that are disabled statically
 | `tx_trace=trace` would enable the TRACE level for the `tx_trace` target
 = note: the static max level is `debug`
 = help: to enable TRACE logging, remove the `max_level_debug` feature from the `tracing` crate
warning: some trace filter directives would enable traces that are disabled statically
 | `tx_trace=trace` would enable the TRACE level for the `tx_trace` target
 = note: the static max level is `debug`
 = help: to enable TRACE logging, remove the `max_level_debug` feature from the `tracing` crate

Here's the suspected analysis by Claude

The min-trace-logs feature on op-rbuilder doesn't work because reth v1.11.3 includes min-debug-logs in its default features, which enables tracing/release_max_level_debug. Since Cargo features are additive and unioned across the dependency graph, both release_max_level_debug (from reth) and release_max_level_trace (from our feature flag) end up active simultaneously — and tracing picks the most restrictive one, so debug wins. To fix this, we need to declare reth with default-features = false and re-enable the defaults we need minus min-debug-logs, so our own min-*-logs features have sole control over the tracing level.

(I confirmed from reth's cargo.toml, it does seem that it has min-debug-logs as its default features)

If this issue is true, then it can be a problem to manage this. The whole approach of overriding defaults of reth crate in rbuilder cargo.toml minus min-debug-logs makes it an additional overhead of keeping these defaults (mins min-debug-logs) in sync with reth crate's present version.


But I am still surprised how is this true (if it's true)? Like any crate in the dependency tree can impose restrictions on its dependent like this?

Would you mind validating this?

@julio4
Copy link
Copy Markdown
Member

julio4 commented Mar 23, 2026

@julio4 unfortunately, the min_trace_logs approach didn't work out.

After building with


 docker build --build-arg FEATURES=min-trace-logs -t yashvardhankukreja/op-rbuilder:log-trace-txns-feature-enabled .

And running it with RUST_LOG=info,tx_trace=trace, I got the following logs


~/OPLabs/Projects/infra/op-conductor-ops main*                                                   09:19:22

❯ k logs -f -n eris-0-opn-geth-f-sequencer-0 op-rbuilder-0

Defaulted container "op-rbuilder" out of: op-rbuilder, download-genesis (init)

warning: some trace filter directives would enable traces that are disabled statically

 | `tx_trace=trace` would enable the TRACE level for the `tx_trace` target

 = note: the static max level is `debug`

 = help: to enable TRACE logging, remove the `max_level_debug` feature from the `tracing` crate

warning: some trace filter directives would enable traces that are disabled statically

 | `tx_trace=trace` would enable the TRACE level for the `tx_trace` target

 = note: the static max level is `debug`

 = help: to enable TRACE logging, remove the `max_level_debug` feature from the `tracing` crate

Here's the suspected analysis by Claude

The min-trace-logs feature on op-rbuilder doesn't work because reth v1.11.3 includes min-debug-logs in its default features, which enables tracing/release_max_level_debug. Since Cargo features are additive and unioned across the dependency graph, both release_max_level_debug (from reth) and release_max_level_trace (from our feature flag) end up active simultaneously — and tracing picks the most restrictive one, so debug wins. To fix this, we need to declare reth with default-features = false and re-enable the defaults we need minus min-debug-logs, so our own min-*-logs features have sole control over the tracing level.

(I confirmed from reth's cargo.toml, it does seem that it has min-debug-logs as its default features)

If this issue is true, then it can be a problem to manage this. The whole approach of overriding defaults of reth crate in rbuilder cargo.toml minus min-debug-logs makes it an additional overhead of keeping these defaults (mins min-debug-logs) in sync with reth crate's present version.


But I am still surprised how is this true (if it's true)? Like any crate in the dependency tree can impose restrictions on its dependent like this?

Would you mind validating this?

I thought it would be additive in choosing the less restrictive level, not the most (so trace and not debug). But because feature is defined by dependency it might be different.

We can move ahead and keep it at debug level and I'll look into this, so you're not blocked on this.

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

Thanks @julio4 , I appreciate it. I'll just double-check with you if you really want to go ahead with debug level or also gate it behind an env var like ENABLE_TX_HASH_DEBUG_LOGGING? That'll at least ensure that by default, debug logs won't depict these new log statements.

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@julio4
Copy link
Copy Markdown
Member

julio4 commented Mar 25, 2026

Thanks @julio4 , I appreciate it. I'll just double-check with you if you really want to go ahead with debug level or also gate it behind an env var like ENABLE_TX_HASH_DEBUG_LOGGING? That'll at least ensure that by default, debug logs won't depict these new log statements.

Yes I think env gated would be best as a temporary solution if possible!

@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

Awesome, thanks! Will proceed with it

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@yashvardhan-kukreja
Copy link
Copy Markdown
Contributor Author

Hi @julio4 , just committed an env-level gate and tested it in a live-devnet. It's working as expected.

Signed-off-by: Yashvardhan Kukreja <yashvardhan@oplabs.co>
@julio4 julio4 enabled auto-merge (squash) March 26, 2026 17:00
@julio4 julio4 merged commit c2d0700 into flashbots:main Mar 26, 2026
4 checks passed
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.

3 participants