Migrate from log to tracing #58

starua · 2023-04-12T13:39:32Z

Close #57

I'm not very familiar with this crate, so if i write some message wrong please tell me.

Finomnis · 2023-04-12T17:36:03Z

src/toplevel.rs

-        for formatted_exit_state in formatted_exit_states {
-            log::debug!("    {}", formatted_exit_state);
-        }
-


Did you remove this out of personal preference? Or did it break some kind of tracing guideline? What's the rationale behind it?

No, actually tracing dose not have an official guideline.

But in my understanding, tracing logs is made of event and span, where every event should be an independent message, and the context for event should be include in it's span, not the event happen beside to it.

I think we can keep this by concat all the format messages in one string and output them out in one event, but i think trigger an event when every subsystem is end will be an better idea.

You don't "trigger when a subsystem ends", though. You do it in perform_shutdown_on_subsystems, after all the results are collected in a Vec first. So I don't see the advantage; printing them in toplevel.rs would at least show toplevel.rs as the source file in tracing. With your change, the source is tokio_graceful_shutdown::subsystem::data, which in its entirety is an internal file not exposed to the user.

It's a debug message only, anyway. I'd prefer concatenating the number of messages in one big status message instead, as you suggested.

starua · 2023-04-18T10:23:53Z

emm, any other suggestions?

Finomnis

I don't have much spare time at the moment, please forgive long response periods.

Finomnis · 2023-04-19T17:33:54Z

src/toplevel.rs

-        for formatted_exit_state in formatted_exit_states {
-            log::debug!("    {}", formatted_exit_state);
-        }
-


You don't "trigger when a subsystem ends", though. You do it in perform_shutdown_on_subsystems, after all the results are collected in a Vec first. So I don't see the advantage; printing them in toplevel.rs would at least show toplevel.rs as the source file in tracing. With your change, the source is tokio_graceful_shutdown::subsystem::data, which in its entirety is an internal file not exposed to the user.

Finomnis · 2023-04-19T17:35:24Z

src/toplevel.rs

-        for formatted_exit_state in formatted_exit_states {
-            log::debug!("    {}", formatted_exit_state);
-        }
-


It's a debug message only, anyway. I'd prefer concatenating the number of messages in one big status message instead, as you suggested.

examples/01_normal_shutdown.rs

Finomnis · 2023-04-19T17:39:52Z

src/toplevel.rs

@@ -236,6 +222,7 @@ impl<ErrType: ErrTypeTraits> Toplevel<ErrType> {
    ///
    /// An error of type [`GracefulShutdownError`] if an error occurred.
    ///
+    #[tracing::instrument(name = "Global System Shutdown", skip_all, level = "debug", fields(timeout = %humantime::format_duration(shutdown_timeout)))]


Would you mind explaining the rationale for this line? Is this best practice to add a name whenever possible? I kind of find it distracting. Either way, Global System Shutdown is kind of incorrect, because people could use nested toplevels and similar. I would prefer to leave the name out, as it will only lead to discussion concerning the correctness of the name. Can't we simply leave out the entire #[tracing::instrument()] line? Why do we have it? What's wrong with the default? Maybe I simply don't know enough about tracing.

After reading a little more, I now kind of understand the concept of spans and grasp what #[tracing::instrument] is for. I don't quite understand what we need the humantime crate for, as Duration is already Debug printable. Further, I don't understand why skip_all, followed by fields if we could simply do skip(self).
Lastly, I kind of don't quite understand why we need this in general; this will never enter user code, so what's the point in using spans here?

Further, why do we need any of this if there is already tracing-log? What's the advantage of switching to tracing in this crate?

tracing-log is just convert every log into event, if we use many layers of subsystems, it's hard to tell which message is from where.

I understand, but the subsystems themselves should then derive #[tracing::instrument], and there is nothing in this crate that prevents this. Setting a span within our code won't do anything for the subsystems themselves, as they are not connected to our code, they get spawned via tokio::spawn.

You're right, sorry, I didn't think well.

I did think about moving over to tracing either way at some point. The reason I didn't so far was compatibility - it's a lot easier to use this crate in tracing if it itself implements log than the other way round. But of course I could be mistaken; if it is equally simple to use this crate in log if itself implements tracing, then I'm actually more inclined to move over to tracing than not :) After playing around with bevy I do think that tracing is the future.

Either way, regardless of whether we move the crate itself over, I definitely would like to move the examples over to tracing to demonstrate how it should work. But if both can happen simultaneously without breaking too much, I think we should continue with this branch. Don't be intimidated by my feedback, I tend to question things. Not to discredit them, but to understand them :)

If you don't want to continue because it no longer is a valid usecase for you, I might take over your branch if that's fine?

If you don't want to continue because it no longer is a valid usecase for you, I might take over your branch if that's fine?

OK

examples/18_error_type_passthrough.rs

    if let Err(e) = &errors {
        match e {
            GracefulShutdownError::SubsystemsFailed(_) => {
-                log::warn!("Subsystems failed.")
+                sum.push_str(format!("Subsystems failed.\n").as_str());


examples/18_error_type_passthrough.rs

            }
            GracefulShutdownError::ShutdownTimeout(_) => {
-                log::warn!("Shutdown timed out.")
+                sum.push_str(format!("Shutdown timed out.\n").as_str());


examples/18_error_type_passthrough.rs

                        }
                        MyError::WithoutData => {
-                            log::warn!("      It failed with MyError::WithoutData")
+                            sum.push_str(
+                                format!("      It failed with MyError::WithoutData\n").as_str(),


examples/01_normal_shutdown.rs

Finomnis · 2023-04-22T07:00:21Z

Why did you close it? I'm absolutely open to this change, I just want to get it right, that's why I'm asking questions :) I want to understand what tracing brings to the table

Finomnis · 2023-04-22T07:00:58Z

I have tracing on my radar for a while already now, I just never got around to it

starua · 2023-04-22T07:17:11Z

Why did you close it? I'm absolutely open to this change, I just want to get it right, that's why I'm asking questions :) I want to understand what tracing brings to the table

No, i really think there is no use for do this if we just use span on subsystems, unless we just do an string replace from log::debug to tracing::debug. I really do think it my bad that ignore this situation. I'm not closing this pr because think you are unfriendly or something.
If you still think we should do the string replacement thing, then i'm willing to help.

Finomnis · 2023-04-22T07:38:40Z

As I will take over, let me close this PR and let me open one with a branch I can edit :)

Migrate from log to tracing

e359baa

Finomnis reviewed Apr 12, 2023

View reviewed changes

Finomnis reviewed Apr 19, 2023

View reviewed changes

github-advanced-security bot found potential problems Apr 19, 2023

View reviewed changes

Finomnis reviewed Apr 19, 2023

View reviewed changes

examples/01_normal_shutdown.rs Outdated Show resolved Hide resolved

starua added 3 commits April 22, 2023 13:59

remove pretty formatter in examples

c5febbf

Set example log level to DEBUG

8f3bf0d

remove humantime

b27ad47

starua force-pushed the main branch from 1a9f0a7 to b27ad47 Compare April 22, 2023 06:19

starua added 2 commits April 22, 2023 14:30

rename handle_shutdown_requests span

0890e37

collect subsystem exit stat logs

979e4c4

starua closed this Apr 22, 2023

starua reopened this Apr 22, 2023

Finomnis closed this Apr 22, 2023

Finomnis mentioned this pull request Apr 22, 2023

Migrate from log to tracing #59

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Migrate from log to tracing #58

Migrate from log to tracing #58

starua commented Apr 12, 2023

Finomnis Apr 12, 2023

starua Apr 13, 2023

Finomnis Apr 19, 2023

Finomnis Apr 19, 2023

starua commented Apr 18, 2023

Finomnis left a comment

Finomnis Apr 19, 2023

Finomnis Apr 19, 2023

Finomnis Apr 19, 2023

Finomnis Apr 19, 2023

Finomnis Apr 19, 2023

starua Apr 22, 2023

Finomnis Apr 22, 2023

starua Apr 22, 2023

Finomnis Apr 22, 2023 •

edited

Finomnis Apr 22, 2023

Finomnis Apr 22, 2023

starua Apr 22, 2023

Finomnis commented Apr 22, 2023

Finomnis commented Apr 22, 2023

starua commented Apr 22, 2023

Finomnis commented Apr 22, 2023

Migrate from log to tracing #58

Migrate from log to tracing #58

Conversation

starua commented Apr 12, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

starua commented Apr 18, 2023

Finomnis left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Finomnis Apr 22, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Finomnis commented Apr 22, 2023

Finomnis commented Apr 22, 2023

starua commented Apr 22, 2023

Finomnis commented Apr 22, 2023

Finomnis Apr 22, 2023 •

edited