feat(ivc): add spans for steps

[cyphersnake]

Motivation We have many identical logs associated with different contexts (primary and secondary; multiple steps with the same code), need a way to understand in which context a particular log is in

Overview Just use tracing feature with spans It will look like combination of prefixes for every line log with spans

2024-03-21T16:19:20.285453Z DEBUG creating pp:secondary: sirius::ivc::step_folding_circuit: output instance 0: AssignedCell { value: Value { inner: Some(0x000000000000000000000000000000003ec95afcd94ffc06de8aced00c51329b) }, cell: Cell { region_index: RegionIndex(6), row_offset: 2433, column: Column { index: 6, column_type: Advice } }, _marker: PhantomData<halo2curves::bn256::fq::Fq> }
2024-03-21T16:19:22.733955Z DEBUG creating pp: sirius::ivc::public_params: primary & secondary pp created

[chaosma]

Even with the span log here, it looks confusing to me. I did some search and found another way:

https://docs.rs/env_logger/latest/env_logger

(1) The span enter and span exit is less succinct than this approach. Personally, I like this approach better than tracing and span. (2) env_logger can print out module name as prefix. One thing I am not sure is how to print out the function name in the prefix. WIth this feature added, it will be perfect choice that able to locate the exact log location and very concise.

@cyphersnake @drouyang Let me know your opinion on the choice of logger.

[drouyang]

@Gigatron thoughts?

[cyphersnake]

https://docs.rs/env_logger/latest/env_logger

I don't understand anything. env_logger is just a collector for log. All the described features are supported by all collectors, especially including tracing_subscriber.

(1) The span enter and span exit is less succinct than this approach. Personally, I like this approach better than tracing and span.

Well we can isolate functions and hinge attributes on them, but that would require a lot of refactoring and context passing.

PR presents exactly one approach out of three for possible span zoning. This is the most verbose, but the most suitable for our large functions with our large number of contexts and fuzzy separation between cases

(2) env_logger can print out module name as prefix. One thing I am not sure is how to print out the function name in the prefix. WIth this feature added, it will be perfect choice that able to locate the exact log location and very concise.

We already have the module name written as a prefix, right now. Check above. You can customize the mask however you want.

To add the name of the function and its arguments to the log line, span and attribute are actually used.

https://docs.rs/tracing/latest/tracing/attr.instrument.html

If you need "Exact Location", you can add both the file and the line and all the details about the line using the log settings. This does not require any span

[cyphersnake]

I think you don't really understand the UX of such logs and that's where all the questions come from. We are not looking for a particular string, we are restoring execution traces.

For example, if a synthesis error occurs, we downcast it to a halo2 error, losing all context due to the native trait circuit support. To make up for this, we write an error with more context to the log. But we are not interested in location and line and not in the call function, but in the specific trace up to this error. In which scenario it occurred. And scenarios can be described either by ourselves (as in this PR) or, for example, trace call-stack functions (or their part) with inputs to understand in what case it occurred. The second option is more general, but with our huge data it is very redundant. That's why I chose the first one.

[cyphersnake]

On Monday I will make a full-fledged introduction on types of logs, on what possibilities rust gives and what are alternatives to span for tracing (spoiler their growth is not). Also on how you can work with log output and what approaches are available

[drouyang]

When introducing a new framework, we got to train the engineers to learn to use it as well.

Chao may have some particular needs. Probably some example or tutorial would be helpful. We just cannot assume people can read the doc and figuring out by themselves. Prior experience with the tools matters.

[cyphersnake]

When introducing a new framework, we got to train the engineers to learn to use it as well.

Well it's a pretty basic logging toolset, in Rust it's very easy, because of the fact that almost everything is tacitly standardized.

I.e. if it were 'slog' (log extension) or 'tracing' as it is now, there is very little difference in usage. Moreover, my experience from other languages is about the same.

But in general scientific fields rarely use full-fledged logs, it's more about industrial development, so you need an introduction to the topic in general.

[Gigatron]

Tracing is a superset of logging and it provides better tool for observability. With that said, I think @cyphersnake can make the necessary global configuration so that when Chao wants to add some logs with tracing::info/debug it will output the file and line number.

[cyphersnake]

Logging in Rust

Levels

In Rust, we have an established way of writing logging that is the same for all libraries. These are macros that immediately indicate the level:

• ERROR - errors that should not occur within a properly working system.
• WARNING - warnings that are not critical in themselves, but may help debug other situations that have arisen or require attention in the medium term (classic example is low disk space left).
• INFO - basic level describing high-level logic. Thanks to these logs it should be possible to reconstruct what the system was doing without extensive details. There should not be a lot of them.
• TRACE - logs that allow tracing requests. They are usually included not on the production environment, but on dev loops for debugging errors. Most often include detailed information about inputs and outputs of functions, which is too much for INFO.
• DEBUG - level exists for debugging locally or on some environment. Most often as much information as possible is configured on one or two modules to avoid redundancy through RUST_LOG.

Mask

The default log string mask consists of the following components:

• Time
• Level
• Module
• Message string

Any information that can be pulled from the syntax tree of the macro call file can be added to it:

• File
• String and Line

This is done using a crate that collects logs. It is possible to customize either through environment variables or through direct customization in code. The second option is preferable if you don't have a DevOps engineer in your team responsible for environment configuration.

During such a macro call you cannot get information about:

• The function within which the call is made
• Callstack at the time of the function output

This is due to the very limitations of macros, which simply see the code and cannot rely on syntax tree information.

Example

The last two points are needed to keep track of complex compound scenarios. For example in our case, synthesizing StepFoldingCircuit for a single-step IVC is called:

1. In PublicParams::new for 'primary' to form primary_S.
2. In PublicParams::new for 'secondary' to form secondary_S.
3. In PublicParams::new for 'secondary' to form z_output
4. In PublicParams::new for 'secondary' to form secondary_initial_plonk_trace
5. In IVC::new for primary to form z_output
6. In IVC::new for primary to check inside MockProver (if debug mode is enabled). Inside is called twice.
7. In IVC::new for primary to actually perform step 0
8. In IVC::new for 'secondary' to generate z_output.
9. In IVC::new for 'secondary' to check inside MockProver (if debug mode is enabled). Inside is called twice.
10. In IVC::new for secondary to actually perform step 0
11. In IVC::fold_step for primary to generate z_output
12. In IVC::fold_step for 'primary' to check inside MockProver (if debug mode is enabled). Inside is called twice.
13. In IVC::fold_step for primary to actually perform step 1
14. In IVC::fold_step for 'secondary' to generate z_output.
15. In IVC::fold_step for 'secondary' to check inside MockProver (if debug mode is enabled). Inside is called twice.
16. In IVC::fold_step for 'secondary' to actually perform step 1

Thus without debug-mode the synthesis circuit is called 12 times, and with debug-mode 20 times for single-step IVC. Any log line inside StepFoldingCircuit will be duplicated many times, which will not make it easy to understand the context of the call. We can give some cutoffs in the code and track the window within those cutoffs in the code, however, this is labor intensive as we not only need to look for the right line each time, but also track the window within the frame of which the call is made.

It should also be noted that in a real loop IVC will not be single-step, and the number of steps can be large.

Context

Thus, we are faced with the task of tracking the context of the call for each line. There are two approaches:

1. generalized, where we track the callstack with all variables supplied as input. This is a good and easy option when we have small functions with a small number of variables.
2. We introduce some high-level contexts that are added to the logs and allow us to trace the code usage scenario.

Outputting even a simple PlonkStructure is no longer acceptable due to the volume, so we choose the second option.Within this framework it is possible to manually pass a context or a label (often UUID is used) within the code as a variable and manually pass it to functions. There are also automatic tools that add a stack of scopes called span to the logging system. Within the second option, there are two main approaches.

Attribute

https://docs.rs/tracing/latest/tracing/attr.instrument.html

// The generated span's name will be "my_span" rather than "my_function".
#[instrument(name = "my_span")]]
pub fn my_function() {
    // ...do something incredibly interesting and important ...
}

Span

use tracing::{span, Level};
let span = span!(Level::TRACE, "my_span");
// `enter` returns a RAII guard which, when dropped, exits the span. this
// indicates that we are in the span for the current lexical scope.
let _enter = span.enter();
// perform some work in the context of `my_span`...

or

use tracing::{span, Level};
let span = span!(Level::TRACE, "my_span").entered();
// ``entered` returns a RAII guard which, when dropped, exits the span. this
// indicates that we are in the span for the current lexical scope.

Span with manual drop

use tracing::{span, Level};
let span = span!(Level::TRACE, "my_span").entered();
// some code
spain.exit()
// some code

Output

Span is also part of the mask and we can output it as we wish.Thus, we just need to define a target mask where all the necessary nuances are displayed.

Customize logs

There is a default syntax for the RUST_LOG variable, which includes level, module by module details

RUST_LOG="warn,test::foo=info,test::foo::bar=debug" ./test

Enable WARN in general, and enable INFO for the test::foo module, and enable DEBUG for the test::foor::bar module.

Parsing logs

If your logs are not structured (e.g. in json), the easiest way to parse logs is to use ripgrep and search for file strings by some syntactic contructs or span | module.Regular expressions you or chatgpt can also help.

You can also redirect ripgrep output to a separate file for analysis, including only the logs you need. For example, for a particular span (rg "pp:secondary" > log_of_secondary_in_pp)

[cyphersnake]

We can use this PR as a place to discuss this issue, after I redirect my post to our knowledge base.

This is just that, a note, do not take it as the truth in the last instance, I have just described the problem and how to solve it.

@chaosma this is written primarily for you, you can give your feedback here. I'm not pushing new logs-PR yet, however, I've also added a lot of other spans for debugging so I can accurately understand the call scenarios.

The nature of working with logs is now R&D in nature, after that we will need to reflect on how we want to trace real production, however, for now focus on making it easy to debug. That's why almost all of our logs are DEBUG level, however, span makes us look a bit ahead.

[chaosma]

@cyphersnake Thanks for the documentation. It is very helpful. Fully understand the purpose here. Let's go with the high level call chain approach.