chore(mempool): add logs to mempool logic

[elintul]

This change is 

[codecov]

Codecov Report

Attention: Patch coverage is 70.96774% with 9 lines in your changes missing coverage. Please review.

Project coverage is 76.05%. Comparing base (b0cfe82) to head (b9eab5c).
Report is 447 commits behind head on main.

Files with missing lines	Patch %	Lines
crates/mempool/src/mempool.rs	68.00%	8 Missing ⚠️
crates/starknet_api/src/transaction.rs	0.00%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1428      +/-   ##
==========================================
+ Coverage   74.18%   76.05%   +1.86%     
==========================================
  Files         359      360       +1     
  Lines       36240    38365    +2125     
  Branches    36240    38365    +2125     
==========================================
+ Hits        26886    29177    +2291     
+ Misses       7220     6980     -240     
- Partials     2134     2208      +74     

Flag	Coverage Δ
	?

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[github-actions]

Benchmark movements:
tree_computation_flow performance improved 😺
tree_computation_flow time: [34.164 ms 34.203 ms 34.245 ms]
change: [-4.0322% -2.5262% -1.2068%] (p = 0.00 < 0.05)
Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
3 (3.00%) high mild
1 (1.00%) high severe

[MohammadNassar1]

Reviewed 4 of 5 files at r1, all commit messages.
Reviewable status: 4 of 5 files reviewed, 2 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool/src/mempool.rs line 73 at r1 (raw file):

        }

        tracing::info!(

Please import info directly.

Code quote:

tracing::info

---

crates/mempool/src/mempool.rs line 92 at r1 (raw file):

    #[tracing::instrument(
        skip(self, args),
        fields( // Log subset of (informative) fields.

I think tip and gas price are also needed, wdyt?

Code quote:

// Log subset of (informative) fields.

[elintul]

Reviewable status: 4 of 5 files reviewed, 2 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 73 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Please import info directly.

I'd rather not, it's not clear where it comes from (ours? an external crate?).

---

crates/mempool/src/mempool.rs line 92 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

I think tip and gas price are also needed, wdyt?

Will add to fee esc. flow, next PR (I don't want to log this for the first transaction of this address and nonce).
I'd rather not to add a TODO, since CI is flaky.

[MohammadNassar1]

Reviewed 1 of 5 files at r1.
Reviewable status: all files reviewed, 6 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool/src/mempool.rs line 132 at r1 (raw file):

            self.align_to_account_state(account_state);
        }
        tracing::info!("Aligned mempool to committed nonces.");

Is it critical information?
Can it be for debug mode?

The same goes for the below info!

Code quote:

 tracing::info!("Aligned mempool to committed nonces.");

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

}

impl std::fmt::Display for AccountState {

please import it instead

Code quote:

std::fmt::Display

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

}

impl std::fmt::Display for AccountState {

Can you please explain why this code is needed? and why deriving Display is not sufficient.

Code quote:

impl std::fmt::Display for AccountState {

---

crates/starknet_api/src/core.rs line 9 at r1 (raw file):

use std::sync::LazyLock;

use derive_more::Display;

Why are there two imports here?
Which one is used for the nonce?

Code quote:

use core::fmt::Display;
use std::fmt::Debug;
use std::sync::LazyLock;

use derive_more::Display;

[MohammadNassar1]

Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

a discussion (no related file):
General question: How do we check that the logs work as expected?

---

[github-actions]

Benchmark movements:
full_committer_flow performance improved 😺
full_committer_flow time: [29.947 ms 30.006 ms 30.066 ms]
change: [-3.8465% -3.4035% -3.0162%] (p = 0.00 < 0.05)
Performance has improved.

[elintul]

Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

a discussion (no related file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

General question: How do we check that the logs work as expected?

I checked manually.
We don't, we trust tracing and our log configuration, which should be separately checked.

---

---

crates/mempool/src/mempool.rs line 132 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Is it critical information?
Can it be for debug mode?

The same goes for the below info!

I want for this long operation to have midway logs; otherwise, debugging is hard.

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

please import it instead

I'd rather not to, same reason for tracing (a general answer for std/short named crates).

---

crates/starknet_api/src/core.rs line 9 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Why are there two imports here?
Which one is used for the nonce?

An excellent example why fully-qualified names should be used. The last one, first one is only a trait, as you can see from my implementation above...

[elintul]

Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Can you please explain why this code is needed? and why deriving Display is not sufficient.

Directly deriving isn't possible, wherever we have it it's actually derive_more::Display, which is only possible for newtypes (struct A(B)).

[MohammadNassar1]

Reviewable status: all files reviewed, 5 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool/src/mempool.rs line 73 at r1 (raw file):

Previously, elintul (Elin) wrote…

I'd rather not, it's not clear where it comes from (ours? an external crate?).

I'm not sure I get it. Do we have two infos?

---

crates/mempool/src/mempool.rs line 132 at r1 (raw file):

Previously, elintul (Elin) wrote…

I want for this long operation to have midway logs; otherwise, debugging is hard.

Can it be for debug mode?

[elintul]

Reviewable status: all files reviewed, 5 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 73 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

I'm not sure I get it. Do we have two infos?

No, it's not only for disambiguation; it's also for generic names - what's "info"? Super unclear. tracing::info is much better.

---

crates/mempool/src/mempool.rs line 132 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Can it be for debug mode?

Will change the level next PR, I want to keep as-is for Nadin to debug this CI.
Note the rest aren't (I'd rather us having logs when bugs happen, and not retrospectively; not always easily reproducible).

[MohammadNassar1]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

Previously, elintul (Elin) wrote…

Directly deriving isn't possible, wherever we have it it's actually derive_more::Display, which is only possible for newtypes (struct A(B)).

Thanks, and can you please explain why you had to add the trait for Nonce struct (below) without the implementation?

[MohammadNassar1]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/starknet_api/src/core.rs line 9 at r1 (raw file):

Previously, elintul (Elin) wrote…

An excellent example why fully-qualified names should be used. The last one, first one is only a trait, as you can see from my implementation above...

Is it not confusing to have two imports with the same name?
(if you agree, it can be changed in a separate PR)

[elintul]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Thanks, and can you please explain why you had to add the trait for Nonce struct (below) without the implementation?

Again, it's not the trait; it's derive_more::Display.
Don't like it (it's longer compilation and linking), but that's the way it is in the rest of the file and I'd rather keep consistent.

[elintul]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/starknet_api/src/core.rs line 9 at r1 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Is it not confusing to have two imports with the same name?
(if you agree, it can be changed in a separate PR)

Yes, but I don't want to fix in this PR.

[elintul]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool_types/src/mempool_types.rs line 17 at r1 (raw file):

Previously, elintul (Elin) wrote…

Again, it's not the trait; it's derive_more::Display.
Don't like it (it's longer compilation and linking), but that's the way it is in the rest of the file and I'd rather keep consistent.

(Did you read my answer below? Note I already answered it.)

[MohammadNassar1]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @ayeletstarkware and @giladchase)

[MohammadNassar1]

Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @ayeletstarkware and @giladchase)

[MohammadNassar1]

Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @ayeletstarkware and @giladchase)

[github-actions]

Benchmark movements:
tree_computation_flow performance improved 😺
tree_computation_flow time: [34.543 ms 34.594 ms 34.647 ms]
change: [-6.2510% -4.3541% -2.5495%] (p = 0.00 < 0.05)
Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
3 (3.00%) high mild
1 (1.00%) high severe

[github-actions]

Benchmark movements:
tree_computation_flow performance improved 😺
tree_computation_flow time: [34.061 ms 34.113 ms 34.176 ms]
change: [-7.0723% -4.9462% -3.0413%] (p = 0.00 < 0.05)
Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
2 (2.00%) high mild
4 (4.00%) high severe

[giladchase]

Reviewed 5 of 6 files at r2, all commit messages.
Reviewable status: 5 of 6 files reviewed, 1 unresolved discussion (waiting on @ayeletstarkware, @elintul, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 14 at r2 (raw file):

    MempoolResult,
};
use tracing;

Can remove, crates are always in the namespace

Code quote:

use tracing;

---

crates/mempool/src/mempool.rs line 97 at r2 (raw file):

            account_state = %args.account_state
        ),
        ret,

Just to be sure i understand, this returns () in case of success, that is the intended behavior? Note that this also prints the instrument fields

Code quote:

        ret,

---

crates/mempool/src/mempool.rs line 255 at r2 (raw file):

        }

        tracing::info!("{existing_tx_ref} will be replaced by {incoming_tx_ref}.");

Do we want to instrument this function?
Without it prints look like:

2024-10-20T07:08:27.780747Z  INFO add_tx: TransactionReference {...} will be replaced by ...

And with it:

2024-10-20T07:08:27.780747Z  INFO add_tx::handle_fee_escalation TransactionReference {...} will be replaced by ...

Code quote:

    fn handle_fee_escalation(&mut self, incoming_tx: &Transaction) -> MempoolResult<()> {
        let incoming_tx_ref = TransactionReference::new(incoming_tx);
        let TransactionReference { address, nonce, .. } = incoming_tx_ref;
        let Some(existing_tx_ref) = self.tx_pool.get_by_address_and_nonce(address, nonce) else {
            // Replacement irrelevant: no existing transaction with the same nonce for address.
            return Ok(());
        };

        if !self.should_replace_tx(existing_tx_ref, &incoming_tx_ref) {
            tracing::info!(
                "{existing_tx_ref} was not replaced by {incoming_tx_ref} due to insufficient
                fee escalation."
            );
            // TODO(Elin): consider adding a more specific error type / message.
            return Err(MempoolError::DuplicateNonce { address, nonce });
        }

        tracing::info!("{existing_tx_ref} will be replaced by {incoming_tx_ref}.");

[giladchase]

Reviewable status: 5 of 6 files reviewed, 1 unresolved discussion (waiting on @ayeletstarkware, @elintul, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 317 at r2 (raw file):

        )
    }
}

Plz move to after the impl of the struct

Code quote:

impl std::fmt::Display for TransactionReference {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        let TransactionReference { address, nonce, tx_hash, tip, max_l2_gas_price } = self;
        write!(
            f,
            "TransactionReference {{ address: {address}, nonce: {nonce}, tx_hash: {tx_hash},
            tip: {tip}, max_l2_gas_price: {max_l2_gas_price} }}"
        )
    }
}

[elintul]

Reviewable status: 5 of 6 files reviewed, 1 unresolved discussion (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 14 at r2 (raw file):

Previously, giladchase wrote…

Can remove, crates are always in the namespace

Cool!!

---

crates/mempool/src/mempool.rs line 97 at r2 (raw file):

Previously, giladchase wrote…

Just to be sure i understand, this returns () in case of success, that is the intended behavior? Note that this also prints the instrument fields

Removed; I'll configure the node tracing subscriber to log exit (and enter) to the span, instead.

---

crates/mempool/src/mempool.rs line 255 at r2 (raw file):

Previously, giladchase wrote…

Do we want to instrument this function?
Without it prints look like:

2024-10-20T07:08:27.780747Z  INFO add_tx: TransactionReference {...} will be replaced by ...

And with it:

2024-10-20T07:08:27.780747Z  INFO add_tx::handle_fee_escalation TransactionReference {...} will be replaced by ...

Good idea, done!
(Converted all those to debug, so we don't spam logs.)

[elintul]

Reviewable status: 5 of 7 files reviewed, 1 unresolved discussion (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 255 at r2 (raw file):

Previously, elintul (Elin) wrote…

Good idea, done!
(Converted all those to debug, so we don't spam logs.)

Also, added tip and max_l2_gas_price logging to add_tx under info, so they always appear.

[github-actions]

Benchmark movements:
tree_computation_flow performance regressed!
tree_computation_flow time: [35.303 ms 35.772 ms 36.335 ms]
change: [+1.5335% +2.8555% +4.7230%] (p = 0.00 < 0.05)
Performance has regressed.
Found 8 outliers among 100 measurements (8.00%)
1 (1.00%) high mild
7 (7.00%) high severe

[MohammadNassar1]

Reviewed 1 of 2 files at r3, 4 of 4 files at r4, all commit messages.
Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool/src/mempool.rs line 124 at r4 (raw file):

    pub fn commit_block(&mut self, args: CommitBlockArgs) -> MempoolResult<()> {
        let CommitBlockArgs { nonces, tx_hashes } = args;
        tracing::debug!("Committing block with {} transactions to mempool.", tx_hashes.len());

Please elaborate on why this one is debug and not info level?
I see for get_txs and add_tx you've used info

Code quote:

debug!

---

crates/mempool/src/mempool.rs line 167 at r4 (raw file):

    // TODO(Mohammad): Rename this method once consensus API is added.
    fn _update_gas_price_threshold(&mut self, threshold: GasPrice) {

Do you need to add this API as well?

Code quote:

 fn _update_gas_price_threshold(

---

crates/mempool/src/mempool.rs line 298 at r4 (raw file):

// TODO(Elin): move to a shared location with other next-gen node crates.
fn tip(tx: &Transaction) -> Tip {
    tx.tip().expect("Expected a valid tip value.")

I don't think the error message adds any additional information.
You can add unwrap here.

Code quote:

"Expected a valid tip value."

[elintul]

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 124 at r4 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Please elaborate on why this one is debug and not info level?
I see for get_txs and add_tx you've used info

WDYM? Default level of instrument spans is info.
handle_fee_escalation is an inner function, so I think it should log in debug level, so we don't get spammed on every add_tx call.

---

crates/mempool/src/mempool.rs line 167 at r4 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

Do you need to add this API as well?

Maybe later, as we integrate it to our flow.

---

crates/mempool/src/mempool.rs line 298 at r4 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

I don't think the error message adds any additional information.
You can add unwrap here.

I'd rather production code to not use unwraps.
This is temporary code anyways. What's the status of moving to a >=V3 enum? Please answer offline.

[MohammadNassar1]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @ayeletstarkware, @elintul, and @giladchase)

---

crates/mempool/src/mempool.rs line 124 at r4 (raw file):

Previously, elintul (Elin) wrote…

WDYM? Default level of instrument spans is info.
handle_fee_escalation is an inner function, so I think it should log in debug level, so we don't get spammed on every add_tx call.

exactly, I see that get_txs and add_tx use info while commit_block uses debug. Is there a reason for that?

btw, I agree regarding handle_fee_escalation, but I'm asking about commit_block.

---

crates/mempool/src/mempool.rs line 298 at r4 (raw file):

Previously, elintul (Elin) wrote…

I'd rather production code to not use unwraps.
This is temporary code anyways. What's the status of moving to a >=V3 enum? Please answer offline.

Answered offline

[elintul]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @ayeletstarkware, @giladchase, and @MohammadNassar1)

---

crates/mempool/src/mempool.rs line 124 at r4 (raw file):

Previously, MohammadNassar1 (mohammad-starkware) wrote…

exactly, I see that get_txs and add_tx use info while commit_block uses debug. Is there a reason for that?

btw, I agree regarding handle_fee_escalation, but I'm asking about commit_block.

Note only inside logs in commit are debug...

[github-actions]

Benchmark movements:
tree_computation_flow performance improved 😺
tree_computation_flow time: [34.999 ms 35.020 ms 35.045 ms]
change: [-5.9769% -3.8023% -1.8311%] (p = 0.00 < 0.05)
Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
2 (2.00%) high mild
2 (2.00%) high severe

[github-actions]

Benchmark movements:
tree_computation_flow performance improved 😺
tree_computation_flow time: [35.260 ms 35.323 ms 35.389 ms]
change: [-5.7438% -4.1756% -2.7058%] (p = 0.00 < 0.05)
Performance has improved.
Found 5 outliers among 100 measurements (5.00%)
5 (5.00%) high mild

[giladchase]

Reviewed 1 of 2 files at r3, 4 of 4 files at r4, all commit messages.
Reviewable status: complete! all files reviewed, all discussions resolved (waiting on @ayeletstarkware)