#620: Add structured logging to basic transaction flow (Authority/Client) #706

velvia · 2022-03-08T17:44:53Z

Initial PR for #620
The doc explains the goals - using structured logging so we can have proper context for entire transaction flows and be able to easily trace a transaction across processes, components, and async threads. Plus using proper key-value tagging to be able to easily filter logs.

Example of logging showing tracing a single TX across authority_aggregator on gateway/client side and authority:

7ab7774d1f7bd40848}: sui_core::authority_aggregator: Broadcasting transaction request to authorities quorum_threshold=3 validity_threshold=2 timeout_after_quorum=60s
2022-03-05T01:35:03.383791Z TRACE test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority_aggregator: Transaction data: TransactionData { kind: Call(MoveCall { package: (0000000000000000000000000000000000000002, SequenceNumber(1), o#3104eb8786a94f58d88564c38e22f13d79e3868c5cf81c9c9228fe91465eccad), module: Identifier("ObjectBasics"), function: Identifier("transfer"), type_arguments: [], object_arguments: [(DA40C299F382CBC3C1EBEEA97351F5F185BAD359, SequenceNumber(1), o#d299113b3b52fd1b9dc01e3ba9cf70345faed592af04a56e287057f166ed2783)], shared_object_arguments: [], pure_arguments: [[145, 123, 205, 38, 175, 158, 193, 63, 122, 56, 238, 127, 139, 117, 186, 164, 89, 46, 222, 252]], gas_budget: 1000 }), sender: k#37ebb9c16574a57bcc7b52a6312a35991748be55, gas_payment: (3EE0283D2D12D5C49D0E4E2F509D07227A64ADF2, SequenceNumber(1), o#3ad1a71ee65e8e6675e6a0fb1e893e48c1820b274d3055d75f4abb850c9663e5) }
2022-03-05T01:35:03.385294Z DEBUG test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Checked locks and found mutable objects num_mutable_objects=2
2022-03-05T01:35:03.386500Z DEBUG test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Checked locks and found mutable objects num_mutable_objects=2
2022-03-05T01:35:03.387681Z DEBUG test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Checked locks and found mutable objects num_mutable_objects=2
2022-03-05T01:35:03.388835Z DEBUG test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Checked locks and found mutable objects num_mutable_objects=2
2022-03-05T01:35:03.391841Z DEBUG test_move_call_args_linter_command:process_tx{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority_aggregator: Received signatures response from authorities for transaction req broadcast num_errors=0 good_stake=3 bad_stake=0 num_signatures=3 has_certificate=true
2022-03-05T01:35:03.391891Z DEBUG test_move_call_args_linter_command:process_cert{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority_aggregator: Broadcasting certificate to authorities quorum_threshold=3 validity_threshold=2 timeout_after_quorum=60s
2022-03-05T01:35:03.394529Z DEBUG test_move_call_args_linter_command:process_cert{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Read inputs for transaction from DB num_inputs=3
2022-03-05T01:35:03.395917Z DEBUG test_move_call_args_linter_command:process_cert{tx_digest=t#7e5f08ab09ec80e3372c101c5858c96965a25326c21af27ab7774d1f7bd40848}: sui_core::authority: Finished execution of transaction with status Success { gas_used: 7 } gas_used=7

Log initialization is fixed to take in log levels from the environment RUST_LOG variable.

This is just a start - much more to come, but I think it gives everyone the basic idea and template to do more. TODOs (either this PR or subsequent ones):

Logging of spans, one should be able to see the time spans took
Automatic logging of expects and unwraps with context
more detailed logging everywhere

…n authority_aggregator

… var

Clay-Mysten

The docs look great, Evan! I left some optional suggestions. Otherwise, LGTM!

doc/observability.md

huitseeker

This looks great, but the doc part is meant to be internal developer doc, i.e. it's for people developing Sui itself rather than on Sui. Is docs the right place?

/cc @Clay-Mysten

Clay-Mysten · 2022-03-08T23:13:37Z

Hi Francois,

I ran this past Sam, and he thought it appropriate for the Contribute section of the site aimed at folks looking to augment Sui. I updated our Dev Portal sitemap outline to reflect this:
https://docs.google.com/document/d/1izze8way6Z6-NiTabJADowoUECnMIl4c8KKNoCyL1fA/edit#

Let me know if that doesn't make sense to you.

velvia · 2022-03-08T23:39:51Z

Thanks for the feedback @Clay-Mysten !
As for where docs go, will leave suggestions in your good hands.

Also just added ability to dump span events (start, end, duration) as JSON. Sample output:

{"v":0,"name":"sui","msg":"[PROCESS_CERT - START]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.241421Z","target":"sui_core::authority_server","line":67,"file":"sui_core/src/authority_server.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - EVENT] Read inputs for transaction from DB","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.246688Z","target":"sui_core::authority","line":393,"file":"sui_core/src/authority.rs","num_inputs":2,"tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - EVENT] Finished execution of transaction with status Success { gas_used: 18 }","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.246759Z","target":"sui_core::authority","line":409,"file":"sui_core/src/authority.rs","gas_used":18,"tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[DB_UPDATE_STATE - START]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.247888Z","target":"sui_core::authority","line":430,"file":"sui_core/src/authority.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493"}
{"v":0,"name":"sui","msg":"[DB_UPDATE_STATE - END]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.248114Z","target":"sui_core::authority","line":430,"file":"sui_core/src/authority.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493","elapsed_milliseconds":0}
{"v":0,"name":"sui","msg":"[PROCESS_CERT - END]","level":20,"hostname":"Evan-MLbook.lan","pid":51425,"time":"2022-03-08T22:48:11.248688Z","target":"sui_core::authority_server","line":67,"file":"sui_core/src/authority_server.rs","tx_digest":"t#d1385064287c2ad67e4019dd118d487a39ca91a40e0fd8e678dbc32e112a1493","elapsed_milliseconds":2}

sblackshear · 2022-03-09T05:14:35Z

This looks great, but the doc part is meant to be internal developer doc, i.e. it's for people developing Sui itself rather than on Sui. Is docs the right place?

/cc @Clay-Mysten

I agree with not co-mingling these with external developer docs. Maybe a dev-docs or contributor-docs folder would make sense?

gdanezis

I love this! Probably worth also adding a note on how practically one can run an authority and observe its logs (or are they just printing on stderr by default?)

doc/observability.md

huitseeker

This is super dope! I would pay good money to sit down and watch a demo of this.

Here's the main missing things to me:

I think the doc section on ## Ways to View Logs, Traces, Metrics should be expanded.
I don't think the markdown should live in our dev portal, except perhaps in a "for Sui core developers" section (/cc @Clay-Mysten ).

doc/observability.md

sui/src/sui.rs

velvia · 2022-03-09T21:06:47Z

@Clay-Mysten I've moved the doc to a new dev-docs folder.

Thanks everyone for the feedback. I'm planning to restructure the "ways to view logs, traces, etc." section and write some stuff on the basic architecture of it, but leave the actual implementation of subscriber/viewing options to a later PR, in favour of getting this in faster.

sui_core/src/authority_server.rs

patrickkuo · 2022-03-11T13:35:22Z

Just noticed ./sui genesis and ./sui start no longer prints logs after this change.... @velvia can you take a look?

patrickkuo · 2022-03-11T14:31:56Z

Just noticed ./sui genesis and ./sui start no longer prints logs after this change.... @velvia can you take a look?

Ok I just saw this in the doc

NOTE: For logs, set RUST_LOG=debug before invoking ./sui start.

most of the output of sui start and genesis are informative and are info level logging, do you think we should print INFO logs by default?

velvia · 2022-03-11T18:36:01Z

@patrickkuo Let me fix it in an upcoming PR, am looking into it

Context: The `BatchLoader` is establishing a primary->worker communication using a public address, which is adding latency and competing with outbound traffic. The proper fix us to use the `BlockWaiter`. The issue: We would like a mitigation to be deployed and effective sooner. The fix: We inspect the worker addresses used by the `BatchLoader`, and rewrite their hostname to localhost when it matches the local primary.

) We operate an executor with a bound on the concurrent number of messages (see #463, #559, #706). PR #472 added logging for the bound being hit. We expect the executors to operate for a long time at this limit (e.g. in recovery situation). The spammy logging is not usfeful This removes the logging of the concurrency bound being hit. Fixes #759

Context: The `BatchLoader` is establishing a primary->worker communication using a public address, which is adding latency and competing with outbound traffic. The proper fix us to use the `BlockWaiter`. The issue: We would like a mitigation to be deployed and effective sooner. The fix: We inspect the worker addresses used by the `BatchLoader`, and rewrite their hostname to localhost when it matches the local primary.

…ystenLabs#763) We operate an executor with a bound on the concurrent number of messages (see MystenLabs#463, MystenLabs#559, MystenLabs#706). PR MystenLabs#472 added logging for the bound being hit. We expect the executors to operate for a long time at this limit (e.g. in recovery situation). The spammy logging is not usfeful This removes the logging of the concurrency bound being hit. Fixes MystenLabs#759

velvia added 5 commits March 3, 2022 10:56

Initial observability doc and example of context/structured logging i…

dbb3ef3

…n authority_aggregator

Start logging tx / cert processing in authority.rs

6495bc6

Merge branch 'main' into ec/initial-logging-pr

e9aebc6

Fix tracing_subscriber initialization to respect RUST_LOG environment…

9d07e33

… var

Add note about enabling logs

a25d633

velvia requested review from huitseeker, lxfind, oxade and Clay-Mysten March 8, 2022 17:45

Clay-Mysten approved these changes Mar 8, 2022

View reviewed changes

huitseeker reviewed Mar 8, 2022

View reviewed changes

velvia added 2 commits March 8, 2022 15:18

Add JSON span logging output by setting SUI_JSON_SPAN_LOGS=1

63e63ef

Merge from main

88b2555

gdanezis approved these changes Mar 9, 2022

View reviewed changes

doc/observability.md Outdated Show resolved Hide resolved

doc/observability.md Outdated Show resolved Hide resolved

huitseeker reviewed Mar 9, 2022

View reviewed changes

doc/observability.md Outdated Show resolved Hide resolved

doc/observability.md Outdated Show resolved Hide resolved

sui/src/sui.rs Show resolved Hide resolved

velvia added 3 commits March 9, 2022 11:42

Add tx_kind to both gateway side and authority side transaction tags

2bf190b

Cargo clippy

afc32fb

CR feedback esp on docs

52c5795

velvia added 2 commits March 9, 2022 14:06

Change authors in build files

f01d23c

Add to observability doc

6784274

velvia merged commit 18568c9 into MystenLabs:main Mar 9, 2022

velvia deleted the ec/initial-logging-pr branch March 9, 2022 23:35

huitseeker mentioned this pull request Mar 10, 2022

refactor: replace strum with name_variant #728

Merged

lanvidr reviewed Mar 10, 2022

View reviewed changes

sui_core/src/authority_server.rs Show resolved Hide resolved

huitseeker mentioned this pull request Apr 15, 2022

Fix broken release #1392

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

#620: Add structured logging to basic transaction flow (Authority/Client) #706

#620: Add structured logging to basic transaction flow (Authority/Client) #706

velvia commented Mar 8, 2022 •

edited

Loading

Clay-Mysten left a comment

huitseeker left a comment

Clay-Mysten commented Mar 8, 2022

velvia commented Mar 8, 2022

sblackshear commented Mar 9, 2022

gdanezis left a comment

huitseeker left a comment

velvia commented Mar 9, 2022

patrickkuo commented Mar 11, 2022

patrickkuo commented Mar 11, 2022

velvia commented Mar 11, 2022

#620: Add structured logging to basic transaction flow (Authority/Client) #706

#620: Add structured logging to basic transaction flow (Authority/Client) #706

Conversation

velvia commented Mar 8, 2022 • edited Loading

Clay-Mysten left a comment

Choose a reason for hiding this comment

huitseeker left a comment

Choose a reason for hiding this comment

Clay-Mysten commented Mar 8, 2022

velvia commented Mar 8, 2022

sblackshear commented Mar 9, 2022

gdanezis left a comment

Choose a reason for hiding this comment

huitseeker left a comment

Choose a reason for hiding this comment

velvia commented Mar 9, 2022

patrickkuo commented Mar 11, 2022

patrickkuo commented Mar 11, 2022

velvia commented Mar 11, 2022

velvia commented Mar 8, 2022 •

edited

Loading