Rust: Actix-web Daily Logging – Fix Local Offset, Apply Event Filtering | behai-nguyen software development learnings and documentation

In the last post of our actix-web learning application, we identified two problems. First, there is an issue with calculating the UTC time offset on Ubuntu 22.10, as described in the section 💥 Issue with calculating UTC time offset on Ubuntu 22.10. Secondly, loggings from other crates that match the logging configuration are also written onto log files, as mentioned in the Concluding Remarks section. We should be able to configure what gets logged. We will address both of these issues in this post.

🦀 Index of the Complete Series.


Rust: Actix-web Daily Logging – Fix Local Offset, Apply Event Filtering

🚀 Please note, complete code for this post can be downloaded from GitHub with:

git clone -b v0.12.0 https://github.com/behai-nguyen/rust_web_01.git

The actix-web learning application mentioned above has been discussed in the eleven previous posts. The index of the complete series can be found here.

The code we’re developing in this post is a continuation of the code from the eleventh post. 🚀 To get the code of this eleventh post, please use the following command:

git clone -b v0.11.0 https://github.com/behai-nguyen/rust_web_01.git

– Note the tag v0.11.0.

While this post continues from previous posts in this series, it can be read in conjunction with only the eleventh post.

❶ For this post, no new modules are introduced. Instead, we will update some existing modules and files. The layout chart below shows the updated files and modules, with those marked with ★ indicating the updated ones.

.
├── .env ★
├── Cargo.toml ★
├── ...
├── README.md ★
├── src
│ ├── helper
│ │ ├── app_logger.rs ★
│ │ └── ...
│ ├── main.rs ★
│ └── ...
└── tests
    ├── common.rs ★
    └── ...

🦀 In the context of this post, our focus is solely on the RUST_LOG entry in the .env file, which we will discuss in a later section.

❷ Updates to the Cargo.toml file:

...
[dependencies]
...
time-tz = {version = "2.0", features = ["system"]}
tracing-subscriber = {version = "0.3", features = ["fmt", "std", "local-time", "time", "env-filter"]}

We added the new crate time-tz, and for tracing-subscriber, we added the crate feature env-filter. We will discuss these additions in later sections.

❸ Resolve the issue with calculating the UTC time offset to ensure reliable functionality on both Ubuntu 22.10 and Windows 10.

⓵ As mentioned in the last post:

After extensive searching, I came across this GitHub issue, Document #293 in local-offset feature description #297. It appears that even after three years, this issue remains unresolved.

Document #293 is dated December 19, 2020. Additionally, there are other relevant documents that I did not come across during my previous “extensive searching”:

November 25, 2020 -- Time 0.2.23 fails to determine local offset #296.
November 2, 2021 -- Better solution for getting local offset on unix #380.
Dec 5, 2019 -- tzdb support #193.

<a href=”https://github.com/time-rs/time/issues/193#issuecomment-1037227056” title=”This reply”target=”_blank”>This reply</a> posted on February 13, 2022 mentions the crate time-tz, which resolves the previously mentioned issue.

The parameter utc_offset: time::UtcOffset was removed from the function pub fn init_app_logger() -> WorkerGuard, and the offset calculation is now carried out internally:

    let timer = OffsetTime::new(
        localtime.offset(),
        format_description!("[year]-[month]-[day] [hour]:[minute]:[second]"),
    );

⓶ Offset calculations were accordingly removed from both the function async fn main() -> Result<(), std::io::Error> in the module src/main.rs, and the function pub async fn spawn_app() -> TestApp in the module tests/common.rs.

❸ Configuration to determine what get logged.

We use tracing_subscriber’s filter::EnvFilter struct to filter which events are logged. This functionality requires the crate feature env-filter, as described above.

Event filtering is configured via the environment variable RUST_LOG. Its value can be much more sophisticated than simply trace, debug, info, warn and error. The documentation in the section Enabling logging of the env_logger crate describes the syntax of RUST_LOG with plenty of informative examples.

⓵ Implementing event filtering for the function pub fn init_app_logger() -> WorkerGuard:

    let filter_layer = EnvFilter::try_from_default_env()
        .or_else(|_| EnvFilter::try_new("debug"))
        .unwrap();

    let subscriber = tracing_subscriber::registry()
        .with(
            ...
                .with_filter(filter_layer)
        );

Please note that the code to convert the value of RUST_LOG to tracing::Level has also been removed.

For further documentation, please refer to Filtering Events with Environment Variables. The code above is from the section Composing Layers of the mentioned documentation page. As for the two functions being called, please see:

● pub fn try_from_default_env() -> Result<Self, FromEnvError>.

● pub fn try_new<S: AsRef<str»(dirs: S) -> Result<Self, ParseError>.

And finally, the line:

            ...
                .with_filter(filter_layer)

is from the trait tracing_subscriber::layer::Layer, which is a “a composable handler for tracing events.”

⓶ As for the value of RUST_LOG, there are three cases that do not behave as I initially assumed:

The first two cases are RUST_LOG=xxxx and RUST_LOG=, where nothing gets logged. I had assumed that this error handling would default the logging event to debug:

        .or_else(|_| EnvFilter::try_new("debug"))

I attempted several times to default them to debug, but unfortunately, I was unsuccessful.

The third case is RUST_LOG, where only the RUST_LOG variable name is present in the .env file without any value assigned to it. Based on the above two instances, I expected that nothing would be logged. However, it defaults to debug!

Please note that for the next example discussion, it’s important to keep in mind that the Cargo.toml file contains the following declaration, where learn_actix_web is defined:

[[bin]]
path = "src/main.rs"
name = "learn_actix_web"

Examples of some valid values:

RUST_LOG=off,learn_actix_web=debug -- Only debug logging events from the learn_actix_web crate are logged. All logging events from other crates are ignored.
RUST_LOG=off,learn_actix_web=info -- Only info logging events from the application are logged. If there are no info events in the application, nothing gets logged and the log files remain empty.
RUST_LOG=off,learn_actix_web=debug,actix_server=info -- Only debug events from the application and info events from the actix_server crate are logged.
RUST_LOG=off,learn_actix_web::middleware=debug -- Only debug events from the src/middleware.rs module of the application are logged. This middleware is triggered when accessing the GET route http://0.0.0.0:5000/helloemployee/{partial last name}/{partial first name} from an authenticated session.

A further illustration for example 4 above: Log in and click on the last button as shown in the screenshot below:

https://behainguyen.files.wordpress.com/2024/03/102-01.png

The current log file should contain the following three new lines:

2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: Hi from start. You requested: /helloemployee/%chi/%ak
2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: Middleware. last name: %chi, first name: %ak.
2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: Hi from response -- some employees found.

This finer control demonstrates the power, utility, and helpfulness of tracking an intermittent bug that is not reproducible on staging and development environments. By enabling debug and tracing logging for specific modules, we can effectively troubleshoot such issues.

❹ Logging events should be grouped within the unique ID of the authenticated session.

For each authenticated session, there is a third-party session ID. I have conducted some studies on this cookie, and its value seems to change after each request. For further discussion of this ID under HTTPS, please refer to this discussion.

My initial plan is to group logging for each request under the value of this ID. For example:

** 2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: {value of id} entered.
2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: Hi from start. You requested: /helloemployee/%chi/%ak
...
** 2024-03-18 00:51:15 DEBUG learn_actix_web::middleware: {value of id} exited.

I have not yet determined how to achieve this; further study is required.

❺ We have concluded this post. I’m pleased to have resolved the offset issue and to have implemented logging in a more effective manner.

I hope you find the information useful. Thank you for reading. And stay safe, as always.

✿✿✿

Feature image source: