Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

(Logs) Submit proven transaction logs #172

Merged
merged 29 commits into from
Jan 26, 2024

Conversation

polydez
Copy link
Contributor

@polydez polydez commented Jan 23, 2024

Sample output:

2024-01-26T04:59:45.932429Z  INFO rpc::submit_proven_transaction: miden-rpc: rpc/src/server/api.rs:82: new
2024-01-26T04:59:45.933068Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:38: new
2024-01-26T04:59:45.933525Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:54: Deserialized transaction, tx_id: 0x38f624118526133c6754d95676a857dc0b19ebd31bd0f3a81dcb1ede0370e143, account_id: 0x9be6a85b380f7fcc, initial_account_hash: 0x34d8f2e5c8bd3ed9710e8be6f47c292c48f52bce1960399b1e59b16496641b78, final_account_hash: 0x66959f9a05ebcfeced216685ef7a694a849a3dfc3c31bbcddd416ec06b093daa, input_notes: None, output_notes: [{ note_id: 0x6965901ed2777856183cf1a8a786d982d75ad78bc2c34c89af6ee5cce7cd7c11, note_metadata: {sender: 0x9be6a85b380f7fcc, tag: 18781 }}], tx_script_root: 0x8637b1dc79e85e3edcb59223092796824c4ccdb5372cf7dec2104dafe74151fe, block_ref: 0x0ef1e1e748b33e7bf66ced296a4fdf75a867f4345277eb4ba1ba4d7c4cdc96b8
2024-01-26T04:59:45.933563Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:187: new
2024-01-26T04:59:45.933631Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:192: tx_id: 0x38f624118526133c6754d95676a857dc0b19ebd31bd0f3a81dcb1ede0370e143, account_id: 0x9be6a85b380f7fcc
2024-01-26T04:59:45.933652Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx: miden_node_block_producer::state_view: block-producer/src/state_view/mod.rs:50: new
2024-01-26T04:59:45.933675Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: new
2024-01-26T04:59:45.934015Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: close, time.busy: 4.67µs, time.idle: 334µs
2024-01-26T04:59:45.934055Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:116: new
2024-01-26T04:59:45.934090Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:130: tx_id: 0x38f624118526133c6754d95676a857dc0b19ebd31bd0f3a81dcb1ede0370e143
2024-01-26T04:59:45.934864Z  INFO store::get_transaction_inputs: miden-store: store/src/server/api.rs:162: new
2024-01-26T04:59:45.934892Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: new
2024-01-26T04:59:45.934907Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:460: account_id: 0x9be6a85b380f7fcc, nullifiers: None
2024-01-26T04:59:45.934955Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: return: ({ account_id: 0x9be6a85b380f7fcc, account_hash: 0x34d8f2e5c8bd3ed9710e8be6f47c292c48f52bce1960399b1e59b16496641b78 }, [])
2024-01-26T04:59:45.934988Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: close, time.busy: 81.2µs, time.idle: 14.5µs
2024-01-26T04:59:45.935124Z  INFO store::get_transaction_inputs: miden-store: store/src/server/api.rs:162: close, time.busy: 243µs, time.idle: 18.1µs
2024-01-26T04:59:45.935414Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:116: close, time.busy: 549µs, time.idle: 809µs
2024-01-26T04:59:45.935439Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_tx_inputs_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:172: new
2024-01-26T04:59:45.935622Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_tx_inputs_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:172: close, time.busy: 4.88µs, time.idle: 178µs
2024-01-26T04:59:45.935643Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: new
2024-01-26T04:59:45.935658Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: close, time.busy: 1.79µs, time.idle: 13.7µs
2024-01-26T04:59:45.936180Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx: miden_node_block_producer::state_view: block-producer/src/state_view/mod.rs:50: close, time.busy: 1.71ms, time.idle: 815µs
2024-01-26T04:59:45.936199Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:205: Transaction added to tx queue, queue_len: 1
2024-01-26T04:59:45.936215Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:187: close, time.busy: 1.79ms, time.idle: 859µs
2024-01-26T04:59:45.936232Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:38: close, time.busy: 2.35ms, time.idle: 813µs
2024-01-26T04:59:45.936976Z  INFO rpc::submit_proven_transaction: miden-rpc: rpc/src/server/api.rs:82: close, time.busy: 84.6µs, time.idle: 4.47ms

Sample output (error):

2024-01-26T04:57:05.299837Z  INFO rpc::submit_proven_transaction: miden-rpc: rpc/src/server/api.rs:82: new
2024-01-26T04:57:05.300438Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:38: new
2024-01-26T04:57:05.300958Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:54: Deserialized transaction, tx_id: 0xdcab26794408ce01b30ccc7032337d53af85b9de5deea5029723bb329547a3b2, account_id: 0x9be6a85b380f7fcc, initial_account_hash: 0x34d8f2e5c8bd3ed9710e8be6f47c292c48f52bce1960399b1e59b16496641b78, final_account_hash: 0x66959f9a05ebcfeced216685ef7a694a849a3dfc3c31bbcddd416ec06b093daa, input_notes: None, output_notes: [{ note_id: 0xd549ca7d1948002dd045b17f26cd29ba594b9a2a1ccab0bf6e5e116ce649f121, note_metadata: {sender: 0x9be6a85b380f7fcc, tag: 18781 }}], tx_script_root: 0x5e9f56f0dee24decfb763f325228496867e582b5ad49a4aba90a1f8a562bf8a1, block_ref: 0x2e9185366113d9ccffed7677007f108e7dafabba6b0511d952669d683a174e6e
2024-01-26T04:57:05.300994Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:187: new
2024-01-26T04:57:05.301098Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:192: tx_id: 0xdcab26794408ce01b30ccc7032337d53af85b9de5deea5029723bb329547a3b2, account_id: 0x9be6a85b380f7fcc
2024-01-26T04:57:05.301147Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx: miden_node_block_producer::state_view: block-producer/src/state_view/mod.rs:50: new
2024-01-26T04:57:05.301173Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: new
2024-01-26T04:57:05.301608Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_in_flight_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:138: close, time.busy: 9.29µs, time.idle: 425µs
2024-01-26T04:57:05.301650Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:116: new
2024-01-26T04:57:05.301689Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:130: tx_id: 0xdcab26794408ce01b30ccc7032337d53af85b9de5deea5029723bb329547a3b2
2024-01-26T04:57:05.302590Z  INFO store::get_transaction_inputs: miden-store: store/src/server/api.rs:162: new
2024-01-26T04:57:05.302621Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: new
2024-01-26T04:57:05.302636Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:460: account_id: 0x9be6a85b380f7fcc, nullifiers: None
2024-01-26T04:57:05.302685Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: return: ({ account_id: 0x9be6a85b380f7fcc, account_hash: 0x66959f9a05ebcfeced216685ef7a694a849a3dfc3c31bbcddd416ec06b093daa }, [])
2024-01-26T04:57:05.302707Z  INFO store::get_transaction_inputs:get_transaction_inputs: miden-store: store/src/state.rs:454: close, time.busy: 71.8µs, time.idle: 15.0µs
2024-01-26T04:57:05.302899Z  INFO store::get_transaction_inputs: miden-store: store/src/server/api.rs:162: close, time.busy: 290µs, time.idle: 19.5µs
2024-01-26T04:57:05.303264Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:get_tx_inputs: miden-block-producer: block-producer/src/store/mod.rs:116: close, time.busy: 657µs, time.idle: 957µs
2024-01-26T04:57:05.303289Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_tx_inputs_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:172: new
2024-01-26T04:57:05.303526Z ERROR block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_tx_inputs_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:172: error: IncorrectAccountInitialHash { tx_initial_account_hash: RpoDigest([15654158025335429172, 3182212002995703409, 11185076813500773704, 8654621706019756318]), store_account_hash: Some(RpoDigest([17064115922431612262, 5361952000515121645, 14824496736419814020, 12266971318421701085])) }
2024-01-26T04:57:05.303547Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx:ensure_tx_inputs_constraints: miden-block-producer: block-producer/src/state_view/mod.rs:172: close, time.busy: 26.9µs, time.idle: 231µs
2024-01-26T04:57:05.304147Z ERROR block_producer::submit_proven_transaction:add_transaction:verify_tx: miden_node_block_producer::state_view: block-producer/src/state_view/mod.rs:50: error: IncorrectAccountInitialHash { tx_initial_account_hash: RpoDigest([15654158025335429172, 3182212002995703409, 11185076813500773704, 8654621706019756318]), store_account_hash: Some(RpoDigest([17064115922431612262, 5361952000515121645, 14824496736419814020, 12266971318421701085])) }
2024-01-26T04:57:05.304169Z  INFO block_producer::submit_proven_transaction:add_transaction:verify_tx: miden_node_block_producer::state_view: block-producer/src/state_view/mod.rs:50: close, time.busy: 2.06ms, time.idle: 967µs
2024-01-26T04:57:05.304189Z ERROR block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:187: error: VerificationFailed(IncorrectAccountInitialHash { tx_initial_account_hash: RpoDigest([15654158025335429172, 3182212002995703409, 11185076813500773704, 8654621706019756318]), store_account_hash: Some(RpoDigest([17064115922431612262, 5361952000515121645, 14824496736419814020, 12266971318421701085])) })
2024-01-26T04:57:05.318207Z  INFO block_producer::submit_proven_transaction:add_transaction: miden-block-producer: block-producer/src/txqueue/mod.rs:187: close, time.busy: 16.2ms, time.idle: 1.03ms
2024-01-26T04:57:05.318275Z ERROR block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:38: error: status: InvalidArgument, message: "VerificationFailed(IncorrectAccountInitialHash { tx_initial_account_hash: RpoDigest([15654158025335429172, 3182212002995703409, 11185076813500773704, 8654621706019756318]), store_account_hash: Some(RpoDigest([17064115922431612262, 5361952000515121645, 14824496736419814020, 12266971318421701085])) })", details: [], metadata: MetadataMap { headers: {} }
2024-01-26T04:57:05.318695Z  INFO block_producer::submit_proven_transaction: miden-block-producer: block-producer/src/server/api.rs:38: close, time.busy: 17.3ms, time.idle: 957µs
2024-01-26T04:57:05.319759Z  INFO rpc::submit_proven_transaction: miden-rpc: rpc/src/server/api.rs:82: close, time.busy: 115µs, time.idle: 19.8ms

@polydez polydez requested a review from bobbinth January 23, 2024 15:54
@polydez polydez marked this pull request as draft January 23, 2024 16:08
@polydez polydez force-pushed the polydez-logs-submit-proven-transaction branch from a7a3e3a to 9bb8583 Compare January 23, 2024 17:33
Copy link
Contributor

@bobbinth bobbinth left a comment

Choose a reason for hiding this comment

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

Thank you! Looks good! I left some comments inline, but also a few general comments:

  • Looks like we are missing the RPC part of the flow.
  • It seems like child spans inherit fields of parent spans. If this is correct, then we don't need to add things like COMPONENT to every log message. Same goes for transaction ID which we should be able to set once and then it would be associated with subsequent logs.
  • For things which may result in kilobytes of data being logged (e.g., full requests/responses), let's use DEBUG level.
  • Let's make sure that data gets serialized in a usable format. This may require introducing wrapper structs and implementing Display traits on them.

block-producer/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/txqueue/mod.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/store/mod.rs Outdated Show resolved Hide resolved
block-producer/src/txqueue/mod.rs Outdated Show resolved Hide resolved
store/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/store/mod.rs Outdated Show resolved Hide resolved
utils/src/logging.rs Outdated Show resolved Hide resolved
utils/src/logging.rs Outdated Show resolved Hide resolved
Copy link
Contributor

@bobbinth bobbinth left a comment

Choose a reason for hiding this comment

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

Thank you! Looks good! Not a full review - but I did leave a few comments inline.

block-producer/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/txqueue/mod.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/store/mod.rs Outdated Show resolved Hide resolved
block-producer/src/store/mod.rs Outdated Show resolved Hide resolved
@polydez polydez marked this pull request as ready for review January 25, 2024 12:22
@polydez
Copy link
Contributor Author

polydez commented Jan 25, 2024

@bobbinth, I've addressed all comments. If you have a chance, please, take a look!

Copy link
Contributor

@bobbinth bobbinth left a comment

Choose a reason for hiding this comment

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

Thank you! Looks good! I left some comments inline - but they are all pretty small.

store/src/lib.rs Outdated Show resolved Hide resolved
rpc/src/server/mod.rs Outdated Show resolved Hide resolved
rpc/src/server/mod.rs Outdated Show resolved Hide resolved
utils/src/logging.rs Show resolved Hide resolved
block-producer/src/server/api.rs Outdated Show resolved Hide resolved
block-producer/src/state_view/mod.rs Outdated Show resolved Hide resolved
block-producer/src/store/mod.rs Outdated Show resolved Hide resolved
store/src/db/mod.rs Outdated Show resolved Hide resolved
store/src/main.rs Outdated Show resolved Hide resolved
store/src/server/mod.rs Outdated Show resolved Hide resolved
Copy link
Contributor

@bobbinth bobbinth left a comment

Choose a reason for hiding this comment

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

Looks good! Thank you! I left some more small comments inline. After these are addressed, we can merge.

let metadata = envelope.metadata();
format!(
"{{ note_id: {}, note_metadata: {{sender: {}, tag: {} }}}}",
envelope.note_id().inner(),
Copy link
Contributor

Choose a reason for hiding this comment

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

For note ID, let's use to_hex() here.

Comment on lines 43 to 44
#[instrument(target = "miden-store", skip_all)]
async fn query(
Copy link
Contributor

Choose a reason for hiding this comment

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

Why do we need to instrument this? As I mentioned previously, this command will be run from the CLI - so, not sure we need to collect any logs here.

pub async fn serve(
config: StoreConfig,
db: Db,
) -> Result<()> {
info!(target: COMPONENT, %config);
Copy link
Contributor

Choose a reason for hiding this comment

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

Any reason not to add a message here? e.g., so that it looks like so:

info!(target: COMPONENT, %config, "Initializing server");

Then, line 28 could be something like this:

info!(target: COMPONENT, "Server initialized");

(i.e., I'm not sure we need to log config twice).

pub async fn setup(config: StoreConfig) -> Result<Self, anyhow::Error> {
info!(target: COMPONENT, %config);
Copy link
Contributor

Choose a reason for hiding this comment

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

Similar comment as above: any reason not to make it:

info!(target: COMPONENT, %config, "Connecting to the database");

Also, I'd change "DB" on line 87 below to "database".

pub async fn serve(config: RpcConfig) -> Result<()> {
info!(target: COMPONENT, %config);
Copy link
Contributor

Choose a reason for hiding this comment

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

Similar comment to above: any reason not to change this to:

info!(target: COMPONENT, %config, "Initializing server");

Then, we can probably change line 24 to something like this:

info!(target: COMPONENT, "Server initialized");

pub async fn serve(config: BlockProducerConfig) -> Result<()> {
info!(target: COMPONENT, %config);
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's change this to:

info!(target: COMPONENT, %config, "Initializing server");

And line 72 below to:

info!(target: COMPONENT, "Server initialized");

…roven-transaction

# Conflicts:
#	block-producer/src/server/mod.rs
#	rpc/src/server/mod.rs
#	store/src/server/mod.rs
#	utils/src/config.rs
@bobbinth bobbinth merged commit cf36148 into main Jan 26, 2024
4 checks passed
@bobbinth bobbinth deleted the polydez-logs-submit-proven-transaction branch January 26, 2024 06:33
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.

2 participants