Fix pretty formatter thread id double space #1778

rukai · 2021-12-15T03:19:12Z

Before this PR there was one two many spaces between "on" and "ThreadId" when thread id formatting is enabled but thread name formatting is disabled.
There was no issue when both thread name and thread id were enabled.

Previous output:

  2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table
    at shotover-proxy/src/transforms/redis/cache.rs:366 on  ThreadId(5)
    in shotover_proxy::server::request with id=5 source="CassandraSource"

new output:

  2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table
    at shotover-proxy/src/transforms/redis/cache.rs:366 on ThreadId(5)
    in shotover_proxy::server::request with id=5 source="CassandraSource"

I spent a lot of time working on unittests, I managed to add tests for a lot of related cases but couldnt test the actual case here :/
When I write a test like:

    #[test]
    fn pretty_threads_ids() {
        let make_writer = MockMakeWriter::default();
        let subscriber = crate::fmt::Collector::builder()
            .pretty()
            .with_thread_ids(true)
            .with_writer(make_writer.clone())
            .with_ansi(false)
            .with_timer(MockTime);
        assert_info_hello_ignore_numeric(
            subscriber,
            make_writer,
            r#"  fake time  INFO tracing_subscriber::fmt::format::test: hello
    at tracing-subscriber/src/fmt/format/mod.rs:

"#,
        )
    }

Inexplicably the thread id is not displayed.

Hopefully you can accept the tests I did write as a compromise, the actual fix here is really simple.

rukai · 2021-12-21T00:19:34Z

I believe I have fixed the failure on windows but CI needs to be authorized again.

hawkw · 2021-12-21T00:34:02Z

tracing-subscriber/src/fmt/format/pretty.rs

@@ -174,13 +174,12 @@ where
                if let Some(name) = thread.name() {
                    write!(writer, "{}", name)?;
                    if self.display_thread_id {
-                        write!(writer, " ({:?})", thread.id())?;


hmm, this changes the formatting slightly because we'll no longer have parentheses around thread IDs when thread names are also enabled. i'm not sure if this is particularly important, though.

good point, I didnt notice those extra brackets.
However looking at it I think this is an improvement as the thread id is displayed with the debug display ThreadId(1) so having (ThreadId(1)) is a bit weird.

sure, i don't have a strong opinion on whether the parentheses are good or not, although they seemed more grammatically correct here. not a big deal either way though.

normally, i'd try to reserve formatting changes for a major version bump, but this seems reasonable to me.

hawkw · 2021-12-21T00:34:27Z

tracing-subscriber/src/fmt/format/mod.rs

+        assert_eq!(expected, result)
+    }
+
+    // When numeric characters are used they often form a non-deterministic value.


it would be nice if this comment explained why these values are nondeterministic...

hawkw · 2021-12-21T00:36:26Z

tracing-subscriber/src/fmt/format/mod.rs

+        let result: String = buf
+            .get_string()
+            .chars()
+            .filter(|x| !x.is_numeric())
+            .collect();


i think this could probably be simplified a bit using str::replace from the standard library? not a hard blocker, though.

also, it could be nice if we replaced the numeric characters with a specific character, rather than just removing them? that way, we would be asserting that they were present at that position in the expected string. the current tests will pass even if, for example, no line number was actually printed.

on the other hand, there might be a variable number of numeric characters in the string --- if the code changes significantly, the line number might have another tens place, for example. we could probably work around that using a regex to replace any number of numeric characters with a single one, but i am not sure if this is really worth the effort...

I avoided solutions using regex to avoid adding it as a dev-dep. As you've noted we could make this nicer with regex, so if your happy for me to add the regex dev-dep then I'll rewrite this using regex.

rukai · 2021-12-21T02:01:09Z

It seems PathBuf::from("tracing-subscriber/src/fmt/format/mod.rs").to_str().unwrap() does not output a path with \ so im retrying with replace('/', &std::path::MAIN_SEPARATOR.to_string())

For replacing the digits I just did .replace with an empty string, happy to change this again though.

hawkw · 2021-12-21T21:00:56Z

tracing-subscriber/src/fmt/format/mod.rs

+        let expected = r#"  fake time  INFO tracing_subscriber::fmt::format::test: hello
+    at tracing-subscriber/src/fmt/format/mod.rs:
+
+"#
+        .replace('/', &std::path::MAIN_SEPARATOR.to_string());


what if, instead of using replace to fix the path separator, we just used the file!() macro, like this:

Suggested change

let expected = r#" fake time INFO tracing_subscriber::fmt::format::test: hello

at tracing-subscriber/src/fmt/format/mod.rs:

"#

.replace('/', &std::path::MAIN_SEPARATOR.to_string());

let expected = concat!(

" fake time INFO tracing_subscriber::fmt::format::test: hello\n",

" at ",

file!(),

":\n"

);

this way, we will always get the actual path to the file as understood by Cargo.

oh thats nice! (hopefully it does what we expect on windows)

hawkw · 2021-12-21T21:02:46Z

tracing-subscriber/src/fmt/format/pretty.rs

@@ -174,13 +174,12 @@ where
                if let Some(name) = thread.name() {
                    write!(writer, "{}", name)?;
                    if self.display_thread_id {
-                        write!(writer, " ({:?})", thread.id())?;


sure, i don't have a strong opinion on whether the parentheses are good or not, although they seemed more grammatically correct here. not a big deal either way though.

hawkw · 2021-12-21T21:07:44Z

tracing-subscriber/src/fmt/format/mod.rs

+        let _default = set_default(&subscriber.into());
+        tracing::info!("hello");
+
+        let result = buf.get_string().replace(char::is_numeric, "");


The reason I originally suggested using a regular expression here is that this approach does have the issue that the tests will still pass if the line numbers (and other numeric characters) are totally missing, which is not really ideal.

I don't actually think it's important to avoid adding the regex crate as a dev-dependency, because...tracing-subscriber already has a dev-dependency on regex:

tracing/tracing-subscriber/Cargo.toml

Line 71 in 6dd9d23

regex = { version = "1", default-features = false, features = ["std"] }

:)

So, I think changing this to use a regular expression is probably the best solution.

ahaha I completely missed it was already a dep.
I changed it to use a regex.

hawkw

okay, this looks good to me! thanks for adding the tests, they look great!

hawkw · 2021-12-22T17:21:45Z

tracing-subscriber/src/fmt/format/mod.rs

+        let regex = Regex::new("[0-9]+").unwrap();
+        let result = buf.get_string();
+        let result_cleaned = regex.replace_all(&result, "NUMERIC");


nit, take it or leave it: we may want to put the regex in a lazy_static! to avoid recompiling the regex in every test:

Suggested change

let regex = Regex::new("[0-9]+").unwrap();

let result = buf.get_string();

let result_cleaned = regex.replace_all(&result, "NUMERIC");

lazy_static::lazy_static! {

static ref REGEX: Regex = Regex::new("[0-9]+").unwrap();

}

let result = buf.get_string();

let result_cleaned = regex.replace_all(&REGEX, "NUMERIC");

in theory, this might improve performance somewhat. in practice, I don't think the regex is compiled enough to have a significant impact on how long it takes to run these tests, so this may not really be worth the effort.

tracing-subscriber/src/fmt/format/pretty.rs

davidbarsky

bunch of non-blocking nits that don't need to be addressed.

davidbarsky · 2021-12-22T17:19:53Z

tracing-subscriber/src/fmt/format/pretty.rs

@@ -174,13 +174,12 @@ where
                if let Some(name) = thread.name() {
                    write!(writer, "{}", name)?;
                    if self.display_thread_id {
-                        write!(writer, " ({:?})", thread.id())?;


normally, i'd try to reserve formatting changes for a major version bump, but this seems reasonable to me.

davidbarsky · 2021-12-22T17:22:19Z

tracing-subscriber/src/fmt/format/mod.rs

+    // When numeric characters are used they often form a non-deterministic value as they usually represent things like a thread id or line number.
+    // This assert method should be used when non-deterministic numeric characters are present.
+    fn assert_info_hello_ignore_numeric(
+        subscriber: impl Into<Dispatch>,
+        buf: MockMakeWriter,
+        expected: &str,
+    ) {


this is a non-blocking nit (eliza is extremely welcome to override with an "ignore david, this is fine"), but since this only used in two callsites, i'd rather have the contents of this method be inlined into each test.

davidbarsky · 2021-12-22T17:24:30Z

tracing-subscriber/src/fmt/format/mod.rs

+        assert_info_hello_ignore_numeric(subscriber, make_writer, &expected)
+    }
+
+    fn assert_info_hello(subscriber: impl Into<Dispatch>, buf: MockMakeWriter, expected: &str) {


nit, take it or leave it: the "hello" doesn't really say too much about the test; i'd rather have the previous set of names here.

davidbarsky · 2021-12-22T17:25:15Z

oh, Eliza merged this as I was commented on the PR. feel free to ignore them!

hawkw · 2021-12-22T19:20:42Z

oh, Eliza merged this as I was commented on the PR. feel free to ignore them!

whoops, sorry about that! we can always apply additional test suggestions in a follow-up PR?

…1778) Before this PR there was one two many spaces between "on" and "ThreadId" when thread id formatting is enabled but thread name formatting is disabled. There was no issue when both thread name and thread id were enabled. Previous output: ``` 2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table at shotover-proxy/src/transforms/redis/cache.rs:366 on ThreadId(5) in shotover_proxy::server::request with id=5 source="CassandraSource" ``` new output: ``` 2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table at shotover-proxy/src/transforms/redis/cache.rs:366 on ThreadId(5) in shotover_proxy::server::request with id=5 source="CassandraSource" ``` I spent a lot of time working on unittests, I managed to add tests for a lot of related cases but couldnt test the actual case here :/ When I write a test like: ```rust #[test] fn pretty_threads_ids() { let make_writer = MockMakeWriter::default(); let subscriber = crate::fmt::Collector::builder() .pretty() .with_thread_ids(true) .with_writer(make_writer.clone()) .with_ansi(false) .with_timer(MockTime); assert_info_hello_ignore_numeric( subscriber, make_writer, r#" fake time INFO tracing_subscriber::fmt::format::test: hello at tracing-subscriber/src/fmt/format/mod.rs: "#, ) } ``` Inexplicably the thread id is not displayed. Hopefully you can accept the tests I did write as a compromise, the actual fix here is really simple.

@Swatinem

# 0.3.4 (Dec 23, 2021) This release contains bugfixes for the `fmt` module, as well as documentation improvements. ### Fixed - **fmt**: Fixed `fmt` not emitting log lines when timestamp formatting fails ([#1689]) - **fmt**: Fixed double space before thread IDs with `Pretty` formatter ([#1778]) - Several documentation improvements ([#1608], [#1699], [#1701]) [#1689]: #1689 [#1778]: #1778 [#1608]: #1608 [#1699]: #1699 [#1701]: #1701 Thanks to new contributors @Swatinem and @rukai for contributing to this release!

@Swatinem

# 0.3.4 (Dec 23, 2021) This release contains bugfixes for the `fmt` module, as well as documentation improvements. ### Fixed - **fmt**: Fixed `fmt` not emitting log lines when timestamp formatting fails ([#1689]) - **fmt**: Fixed double space before thread IDs with `Pretty` formatter ([#1778]) - Several documentation improvements ([#1608], [#1699], [#1701]) [#1689]: #1689 [#1778]: #1778 [#1608]: #1608 [#1699]: #1699 [#1701]: #1701 Thanks to new contributors @Swatinem and @rukai for contributing to this release!

…okio-rs#1778) Before this PR there was one two many spaces between "on" and "ThreadId" when thread id formatting is enabled but thread name formatting is disabled. There was no issue when both thread name and thread id were enabled. Previous output: ``` 2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table at shotover-proxy/src/transforms/redis/cache.rs:366 on ThreadId(5) in shotover_proxy::server::request with id=5 source="CassandraSource" ``` new output: ``` 2021-12-15T00:44:05.596510Z ERROR shotover_proxy::transforms::redis::cache: failed to fetch from cache: system.local not a caching table at shotover-proxy/src/transforms/redis/cache.rs:366 on ThreadId(5) in shotover_proxy::server::request with id=5 source="CassandraSource" ``` I spent a lot of time working on unittests, I managed to add tests for a lot of related cases but couldnt test the actual case here :/ When I write a test like: ```rust #[test] fn pretty_threads_ids() { let make_writer = MockMakeWriter::default(); let subscriber = crate::fmt::Collector::builder() .pretty() .with_thread_ids(true) .with_writer(make_writer.clone()) .with_ansi(false) .with_timer(MockTime); assert_info_hello_ignore_numeric( subscriber, make_writer, r#" fake time INFO tracing_subscriber::fmt::format::test: hello at tracing-subscriber/src/fmt/format/mod.rs: "#, ) } ``` Inexplicably the thread id is not displayed. Hopefully you can accept the tests I did write as a compromise, the actual fix here is really simple.

@Swatinem

# 0.3.4 (Dec 23, 2021) This release contains bugfixes for the `fmt` module, as well as documentation improvements. ### Fixed - **fmt**: Fixed `fmt` not emitting log lines when timestamp formatting fails ([tokio-rs#1689]) - **fmt**: Fixed double space before thread IDs with `Pretty` formatter ([tokio-rs#1778]) - Several documentation improvements ([tokio-rs#1608], [tokio-rs#1699], [tokio-rs#1701]) [tokio-rs#1689]: tokio-rs#1689 [tokio-rs#1778]: tokio-rs#1778 [tokio-rs#1608]: tokio-rs#1608 [tokio-rs#1699]: tokio-rs#1699 [tokio-rs#1701]: tokio-rs#1701 Thanks to new contributors @Swatinem and @rukai for contributing to this release!

rukai requested review from davidbarsky, hawkw and a team as code owners December 15, 2021 03:19

rukai force-pushed the fix_thread_id_double_space branch 2 times, most recently from 6041fb6 to b9bea5b Compare December 21, 2021 00:17

hawkw reviewed Dec 21, 2021

View reviewed changes

rukai force-pushed the fix_thread_id_double_space branch from b9bea5b to 2947084 Compare December 21, 2021 01:56

hawkw reviewed Dec 21, 2021

View reviewed changes

Fix pretty formatter thread id double space

d42a261

rukai force-pushed the fix_thread_id_double_space branch from 2947084 to d42a261 Compare December 22, 2021 00:09

hawkw approved these changes Dec 22, 2021

View reviewed changes

Update tracing-subscriber/src/fmt/format/pretty.rs

92d08a8

hawkw merged commit 76825ba into tokio-rs:master Dec 22, 2021

davidbarsky reviewed Dec 22, 2021

View reviewed changes

hawkw mentioned this pull request Dec 23, 2021

subscriber: prepare to release v0.3.4 #1800

Merged

davidbarsky mentioned this pull request Sep 26, 2023

chore: backport roughly a year's worth of changes #2728

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix pretty formatter thread id double space #1778

Fix pretty formatter thread id double space #1778

rukai commented Dec 15, 2021

rukai commented Dec 21, 2021

hawkw Dec 21, 2021

rukai Dec 21, 2021 •

edited

Loading

hawkw Dec 21, 2021

davidbarsky Dec 22, 2021

hawkw Dec 21, 2021

hawkw Dec 21, 2021

hawkw Dec 21, 2021

rukai Dec 21, 2021 •

edited

Loading

rukai commented Dec 21, 2021 •

edited

Loading

hawkw Dec 21, 2021

rukai Dec 22, 2021

hawkw Dec 21, 2021

hawkw Dec 21, 2021

rukai Dec 22, 2021

hawkw left a comment

hawkw Dec 22, 2021

davidbarsky left a comment

davidbarsky Dec 22, 2021

davidbarsky Dec 22, 2021

davidbarsky Dec 22, 2021

davidbarsky commented Dec 22, 2021

hawkw commented Dec 22, 2021

Fix pretty formatter thread id double space #1778

Fix pretty formatter thread id double space #1778

Conversation

rukai commented Dec 15, 2021

rukai commented Dec 21, 2021

Choose a reason for hiding this comment

rukai Dec 21, 2021 • edited Loading

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

rukai Dec 21, 2021 • edited Loading

Choose a reason for hiding this comment

rukai commented Dec 21, 2021 • edited Loading

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

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidbarsky 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

davidbarsky commented Dec 22, 2021

hawkw commented Dec 22, 2021

rukai Dec 21, 2021 •

edited

Loading

rukai Dec 21, 2021 •

edited

Loading

rukai commented Dec 21, 2021 •

edited

Loading