Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Strange happenings with manual implementation of Valuable #88

Closed
jaskij opened this issue Mar 1, 2022 · 1 comment · Fixed by #89
Closed

Strange happenings with manual implementation of Valuable #88

jaskij opened this issue Mar 1, 2022 · 1 comment · Fixed by #89
Labels
bug Something isn't working

Comments

@jaskij
Copy link

jaskij commented Mar 1, 2022

For the short term, I wanted to make myself a wrapper for anyhow::Error, to use the unstable support in tracing and log the values as structured.

What happened is that my manual implementation - although seemingly correct, fails to serialize. A different implementation, which stringifies early and uses#[derive(Valuable)] works just fine.

Because the code is a bit bigger than fits into an issue, I have created a reproduction in a separate repository, with both versions.

cc @hawkw
@jaskij jaskij mentioned this issue Mar 1, 2022
Closed
@hawkw
Copy link
Member

hawkw commented Mar 1, 2022

I believe I've figured out what's going wrong here. Your not_working implementation records the error's cause by calling Valuable::as_value on it: https://github.com/jaskij/valuable-serde-bug-reproduction/blob/017613b07dfdf692d869573bbfbd099c73d58398/not_working/src/valuable_anyhow.rs#L31

Since root_cause is an Error, its as_value implementation returns Value::Error. This is correct. However, it's also why this code doesn't work. Note that the difference between the working code and the not_working code is that in working, error.root_cause() is formatted as a String first: https://github.com/jaskij/valuable-serde-bug-reproduction/blob/017613b07dfdf692d869573bbfbd099c73d58398/working/src/main.rs#L26

The problem is due to a bug in valuable-serde when recording the Value::Error variant. When valuable-serde encounters a Value::Error, it returns the error immediately as a serialization error:

valuable/valuable-serde/src/lib.rs

Line 267 in 1fc2ad5

Value::Error(e) => Err(S::Error::custom(e)),

This is not correct. If a serde serializer returns an error, this means something has gone wrong while serializing a value. Returning an error makes the serialization fail. However, this is not what valuable's Value::Error means. Value::Error represents that we are recording a value which happens to be an Error, not that something went wrong while recording the value. This means that valuable-serde will currently return an Error (indicating that serialization failed) any time it attempts to record an Error value.

Instead, it should probably record the string representation of the error using serialize_str or something.

@hawkw hawkw added the bug Something isn't working label Mar 1, 2022
hawkw added a commit that referenced this issue Mar 3, 2022
@hawkw
serde: serialize dyn Error Values using collect_str
290d9c8 
Currently, `valuable-serde` handles `Value::Error` variants incorrectly.
When `valuable-serde` encounters a `Value::Error`, it returns the error
immediately as a serialization error:
https://github.com/tokio-rs/valuable/blob/1fc2ad50fcae7fc0da81dc40a385c235636ba525/valuable-serde/src/lib.rs#L267

This is _not_ correct. If a `serde` serializer returns an error, this
means something has gone wrong while serializing a value. Returning an
error makes the serialization fail. However, this is *not* what
`valuable`'s `Value::Error` means. `Value::Error` represents that we are
_recording a value which happens to be an `Error`_, not that something
went wrong _while_ recording the value. This means that `valuable-serde`
will currently return an `Error` (indicating that serialization failed)
any time it attempts to record an `Error` value, and serialization will
fail.

This commit changes `valuable-serde` to record the error using its
`Display` implementation, using `serde`'s `collect_str` method. Now,
`Error`s will be serialized by recording their messages as a string,
rather than causing the serialization to fail.

Using `collect_str` allows the serializer to write the display
representation to its own internal buffer, rather than having to format
the error to a temporary `String` beforehand.

Fixes #88
hawkw added a commit that referenced this issue Mar 3, 2022
@hawkw
serde: serialize dyn Error Values using collect_str
952adf9 
Currently, `valuable-serde` handles `Value::Error` variants incorrectly.
When `valuable-serde` encounters a `Value::Error`, it returns the error
immediately as a serialization error:
https://github.com/tokio-rs/valuable/blob/1fc2ad50fcae7fc0da81dc40a385c235636ba525/valuable-serde/src/lib.rs#L267

This is _not_ correct. If a `serde` serializer returns an error, this
means something has gone wrong while serializing a value. Returning an
error makes the serialization fail. However, this is *not* what
`valuable`'s `Value::Error` means. `Value::Error` represents that we are
_recording a value which happens to be an `Error`_, not that something
went wrong _while_ recording the value. This means that `valuable-serde`
will currently return an `Error` (indicating that serialization failed)
any time it attempts to record an `Error` value, and serialization will
fail.

This commit changes `valuable-serde` to record the error using its
`Display` implementation, using `serde`'s `collect_str` method. Now,
`Error`s will be serialized by recording their messages as a string,
rather than causing the serialization to fail.

Using `collect_str` allows the serializer to write the display
representation to its own internal buffer, rather than having to format
the error to a temporary `String` beforehand.

Fixes #88
@hawkw hawkw mentioned this issue Mar 3, 2022
Merged
hawkw added a commit that referenced this issue Mar 7, 2022
@hawkw
serde: serialize dyn Error Values using collect_str
461c3d7 
Currently, `valuable-serde` handles `Value::Error` variants incorrectly.
When `valuable-serde` encounters a `Value::Error`, it returns the error
immediately as a serialization error:
https://github.com/tokio-rs/valuable/blob/1fc2ad50fcae7fc0da81dc40a385c235636ba525/valuable-serde/src/lib.rs#L267

This is _not_ correct. If a `serde` serializer returns an error, this
means something has gone wrong while serializing a value. Returning an
error makes the serialization fail. However, this is *not* what
`valuable`'s `Value::Error` means. `Value::Error` represents that we are
_recording a value which happens to be an `Error`_, not that something
went wrong _while_ recording the value. This means that `valuable-serde`
will currently return an `Error` (indicating that serialization failed)
any time it attempts to record an `Error` value, and serialization will
fail.

This commit changes `valuable-serde` to record the error using its
`Display` implementation, using `serde`'s `collect_str` method. Now,
`Error`s will be serialized by recording their messages as a string,
rather than causing the serialization to fail.

Using `collect_str` allows the serializer to write the display
representation to its own internal buffer, rather than having to format
the error to a temporary `String` beforehand.

Fixes #88
@hawkw hawkw closed this as completed in #89 Mar 8, 2022
hawkw added a commit that referenced this issue Mar 8, 2022
@hawkw
serde: serialize dyn Error Values using collect_str (#89)
01a4d6a 
Currently, `valuable-serde` handles `Value::Error` variants incorrectly.
When `valuable-serde` encounters a `Value::Error`, it returns the error
immediately as a serialization error:
https://github.com/tokio-rs/valuable/blob/1fc2ad50fcae7fc0da81dc40a385c235636ba525/valuable-serde/src/lib.rs#L267

This is _not_ correct. If a `serde` serializer returns an error, this
means something has gone wrong while serializing a value. Returning an
error makes the serialization fail. However, this is *not* what
`valuable`'s `Value::Error` means. `Value::Error` represents that we are
_recording a value which happens to be an `Error`_, not that something
went wrong _while_ recording the value. This means that `valuable-serde`
will currently return an `Error` (indicating that serialization failed)
any time it attempts to record an `Error` value, and serialization will
fail.

This commit changes `valuable-serde` to record the error using its
`Display` implementation, using `serde`'s `collect_str` method. Now,
`Error`s will be serialized by recording their messages as a string,
rather than causing the serialization to fail.

Using `collect_str` allows the serializer to write the display
representation to its own internal buffer, rather than having to format
the error to a temporary `String` beforehand.

Fixes #88
bryangarza added a commit to bryangarza/tracing that referenced this issue Apr 29, 2022
@bryangarza
subscriber: if error occurs when formatting event, print to stderr
22b5873 
When `Format_event::format_event(...)` returns an errror, we are
currently silently dropping that
Span/Event. tokio-rs/valuable#88 explains
one such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever a Span/Event is dropped.

This patch adds a single `eprintln` line to let the user know that we
were unable to format a specific event. We are not emitting an actual
tracing Event, to avoid the risk of a cycle (the new Event could
trigger the same formatting error again).

Resolves tokio-rs#1965.
@bryangarza bryangarza mentioned this issue Apr 29, 2022
Merged
bryangarza added a commit to bryangarza/tracing that referenced this issue Apr 29, 2022
@bryangarza
subscriber: if error occurs when formatting event, print to stderr
c725c8a 
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

This patch adds a single `eprintln` line to let the user know that we
were unable to format a specific event. We are not emitting an actual
tracing Event, to avoid the risk of a cycle (the new Event could
trigger the same formatting error again).

Resolves tokio-rs#1965.
bryangarza added a commit to tokio-rs/tracing that referenced this issue Jul 25, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
e4a6b57 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
4e7903c 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
fd712ac 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
45b5aac 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
bdee4e0 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
2ff8467 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
561903e 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
davidbarsky added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
ca3c05b 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
hawkw added a commit to tokio-rs/tracing that referenced this issue Aug 24, 2022
@bryangarza @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
370a7c1 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
liuhaozhan added a commit to liuhaozhan/tracing that referenced this issue Nov 17, 2022
@liuhaozhan @hawkw @davidbarsky
subscriber: if error occurs when formatting event, write error to Wri…
bf5e801 
…ter (#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves #1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
kaffarell pushed a commit to kaffarell/tracing that referenced this issue May 22, 2024
@bryangarza @hawkw
@davidbarsky @kaffarell
subscriber: if error occurs when formatting event, write error to Wri…
f02819f 
…ter (tokio-rs#2102)

Motivation:
When `Format_event::format_event(...)` returns an error, we are
currently silently dropping that
Event. tokio-rs/valuable#88 explains one
such case in which this was encountered (due to a bug in
valuable-serde). We want to be made aware whenever an Event is dropped.

Solution:
Write to the Writer with an error message to let the user know that
we were unable to format a specific event. If writing to the Writer fails,
we fall back to writing to stderr. We are not emitting an actual tracing
Event, to avoid the risk of a cycle (the new Event could trigger the
same formatting error again).

Resolves tokio-rs#1965.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

serde: serialize dyn Error Values using collect_str tokio-rs/valuable
2 participants
@jaskij @hawkw