## Motivation
Currently, the `time` crate refuses to determine the local timezone
offset on Unix unless the program is single-threaded or the
`unsound_local_offset` feature is enabled. Because `LocalTime`
determines the local timezone offset every time it formats a message,
and `tracing` is frequently used in multi-threaded programs, `LocalTime`
effectively requires `unsound_local_offset`. `unsound_local_offset` is
inconvenient to enable and potentially dangerous.
## Solution
Add an `OffsetTime` formatter that formats time with a fixed offset,
passed in when it is initialized. Make it convenient to initialize this
with the local timezone offset.
The main advantage of this formatter over `LocalTime` is that if it is
initialized early, it will succeed without `unsound_local_offset`. An
additional advantage is that the program can handle errors determining
the local offset, because they now occur in the program's initialization
code rather than in tracing's formatting code.
This is not a drop-in replacement for LocalTime, because it behaves
differently if the program keeps running across a DST change.
`LocalTime` will pick up the new local offset, while `OffsetTime` will
continue to use the offset in effect when the program started.
Fixes#1771
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.
Hopefully this should automatically publish a GitHub release with
each individual crate's changelog when an appropriate tag is pushed,
provided I haven't made a YAML mistake.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Currently, `tracing-appender`'s `RollingFileAppender` does not implement
the `MakeWriter` trait. This means it can only be used by either
wrapping it in `NonBlocking`, or by wrapping it in a `Mutex`. However,
this shouldn't be strictly necessary, as `&File` implements `io::Write`.
It should thus only be necessary to introduce locking when we are in the
process of _rotating_ the log file.
## Solution
This branch adds a `MakeWriter` implementation for
`RollingFileAppender`. This is done by moving the file itself inside of
an `RwLock`, so that a read lock is acquired to write to the file. This
allows multiple threads to write to the file without contention. When
the file needs to be rolled, the rolling thread acquires the write lock
to replace the file. Acquiring the write lock is guarded by an atomic
CAS on the timestamp, so that only a single thread will try to roll the
file. This prevents other threads from immediately rolling the file
_again_ when the write lock is released.
I...should probably write tests for that, though.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Lets journald subscribers survive a journald restart.
Closes#1745
## Motivation
Currently the journald subscriber immediately connects to the journald
socket. As such I understand it'd not survive a full restart of
journald.
## Solution
Do not connect the client socket immediately; instead pass the socket
pathname every time we send a message. This is also what upstream does.
See #1698: Properly write large payloads to journal.
I'd appreciate a very careful review; this cmsg stuff is nasty, and
while it's well documented in `cmsg(3)` I had to fiddle a bit because
the corresponding functions in libc aren't const and thus don't permit a
direct allocation of the buffer as most `cmsg` C code around does.
Closes#1698
## Motivation
Linux limits the maximum amount of data permitted for a single Unix
datagram; sending large payloads directly will fail.
## Solution
Follow systemd.io/JOURNAL_NATIVE_PROTOCOL/ and check for `EMSGSIZE` from
`send()`; in this case write the payload to a memfd, seal it, and pass
it on to journald via a corresponding SCM_RIGHTS control message.
Per discussion in #1698 this adds no dependency on `nix`, and instead
implements fd forwarding directly with some bits of unsafe `libc` code.
See #1710: Do not write strings in Debug representation.
## Motivation
As discussed in #1710 writing strings literally makes tracing-journald
behave like other journal clients, and allows 3rd party journal readers
to extract the original value from the journal without having to
"un"-parse the Debug representation of Rust strings.
Fixes#1710.
* attributes: implement `#[instrument(ret)]`
## Motivation
Currently, users have to explicitly call logging functions at the end of
functions if they wanted to record values being returned. For example,
```rust
fn increment(a: i32) -> i32 {
let succ = a + 1;
tracing::debug!(?succ);
succ
}
```
The code above will be significantly simpler if we provide the
functionality to record returned values.
## Solution
This PR adds the exact feature we're talking here, which enables users
to write the code below instead.
```rust
#[instrument(ret)]
fn increment(a: i32) -> i32 {
a + 1
}
```
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Per discussion with @hawkw in #1698 I'm adding a few simple integration
tests for the journald subscriber, to have some safety net when
implementing the actual issue in #1698.
These tests send messages of various complexity to the journal, and then
use `journalctl`'s JSON output to get them back out, to check whether
the message arrives in the systemd journal as it was intended to.
## Motivation
Increase test coverage for the journald subscriber and codify a known
good state before approaching a fix for #1698.
Depends on #1737
This branch removes all remaining `extern crate` statements. Most of
these are in old code and were not removed when updating to Rust 2018.
Whoops!
Our MSRV no longer requires `extern crate`, so we don't need these. The
exception is `extern crate` statements for `std` and `alloc`, which are
still the way these libraries are included explicitly when building for
`no_std` platforms.
In some cases, the tests had to explicitly import the `span!` and
`event!` macros at every use, because their names conflict with the
`span` and `event` modules in the test support code. Oh well.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Some of the examples still include `#[macro_use] extern crate`
statements for importing macros from `tracing` or `tracing-core`. On a
recent nightly, this results in import conflicts with the implicit
import of the documented crate in doctests:
https://github.com/tokio-rs/tracing/runs/4279736243?check_suite_focus=true
This commit removes all the `extern crate` statements from doctests. Our
MSRV is new enough that `extern crate` is not required on any of the Rust
versions we support.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
The `time` crate must be compiled with `--cfg unsound_local_offset` in
order for local timestamps to be enabled. For users whose first exposure
to the `time` crate's API is via `tracing-subscriber`'s `time` timestamp
formatters, this is potentially _very_ surprising! Therefore, although
this cfg is not part of `tracing`'s API surface, we should probably
document this aspect of `time`'s API in the
`tracing-subscriber::fmt::time` documentation.
## Solution
This branch adds warnings in the `time::LocalTime` type's API docs, in
the struct-level documentation and on the `new` constructor, describing
that `--cfg unsound_local_offset` is necessary to record local
timestamps and referring users to the `time` documentation. I also added
`unsound_local_offset` to the `doc(cfg(...))` attributes for the
`LocalTime` type.
While I was changing `tracing-subscriber`'s docs, I also fixed a couple
formatting issues I noticed.
Fixes#1688
## Motivation
Currently, `tracing_subscriber::fmt` will bail out of formatting the log
line when formatting the timestamp fails. Previously, when timestamps
were formatted using the `chrono` crate, this was the correct behavior,
as getting the timestamp was infallible, and an error would only be
returned if *formatting* the timestamp to the buffer fails. This should
never actually happen, because we are writing the timestamp to a string,
which should never fail; using `?` is just a bit more efficient than
`.expect` because it doesn't require generating unwinding code.
However, this is no longer the case when using the `time` crate. In the
`time` API, actually getting a timestamp is fallible, and in some cases,
will fail. The current code will bail out of formatting the entire log
line if getting the timestamp fails, which is not great --- using the
wrong timestamp formatter will result in silently dropping all log
lines.
## Solution
This branch changes the `format_timestamp` method to print `<unknown
time>` when the timestamp formatting fails, rather than bailing. This
way, we at least print the rest of the log line for the event.
This fixes half of the issue described in #1688 (the other half is
improving documentation).
The line of code that prints the event's fields (including its message)
was accidentally deleted in 0a16972ba4,
while backporting PR #1696 from `master` (where the `Compact` formatter
implementation is significantly different).
This branch puts it back. Also, I've added tests for the `Compact` formatter's
output, to guard against accidentally breaking it in the future. Previously, we
only had tests for the `Full` and `Json` formatters.
Fixes#1741
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
The test-env-log crate has been renamed to test-log to better reflect
its intent of not only catering to env_logger specific initialization
but also tracing (and potentially others in the future).
This change updates the documentation to reference test-log instead of
the now deprecated test-env-log.
## Motivation
Currently, `tracing_subscriber::fmt`'s `FmtContext` type is missing the
`span_scope`, `event_span`, and `event_scope` methods that `Context`
provides. This is a shame; these will make it much easier for users
implementing formatters to iterate over the scope of the event being
formatted correctly. We should expose those methods.
## Solution
This branch adds new methods to `FmtContext`, most of which forward to
the similarly-named `Context` methods. However, because a `FmtContext`
is only constructed when formatting an event, we can also make the event
scope methods a little more ergonomic by storing a ref to the span being
formatted and automatically passing it to `Context::event_scope` and
`Context::event_span`. This means the `FmtContext` can just always return
the current event's scope without the user having to pass it in.
This branch adds some documentation to the `FormatEvent` trait in
`tracing_subscriber::fmt` on how to write user-provided `FormatEvent`
implementations. There's probably room for additional improvement here,
but I just wanted to get something written down for now.
I also fixed a broken link I noticed while I was here.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
This branch adds some documentation to the `FormatEvent` trait in
`tracing_subscriber::fmt` on how to write user-provided `FormatEvent`
implementations. There's probably room for additional improvement here,
but I just wanted to get something written down for now.
I also fixed a broken link I noticed while I was here.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
Depends on #1696
## Motivation
PR #1696 adds a new API for propagating whether or not ANSI formatting
escape codes are enabled to the event formatter and field formatter via
the `Writer` type. This means that it's now quite easy to make field
formatting also include ANSI formatting escape codes when ANSI
formatting is enabled. Currently, `tracing-subscriber`'s default field
formatter does not use ANSI formatting --- ANSI escape codes are
currently only used for parts of the event log line controlled by the
event formatter, not within fields. Adding ANSI colors and formatting in
the fields could make the formatted output nicer looking and easier to
read.
## Solution
This branch adds support for ANSI formatting escapes in the default
field formatter, when ANSI formatting is enabled. Now, field names will
be italicized, and the `=` delimiter is dimmed. This should make it a
little easier to visually scan the field lists, since the names and
values are more clearly separated and should be easier to distinguish.
Additionally, I cleaned up the code for conditionally using ANSI
formatting significantly. Now, the `Writer` type has (crate-private)
methods for returning `Style`s for bold, dimmed, and italicized text,
when ANSI escapes are enabled, or no-op `Style`s when they are not. This
is reused in all the formatter implementations, so it makes sense to
have it in one place. I also added dimmed formatting of delimiters in a
couple other places in the default event format, which I thought
improved readability a bit by bringing the actual *text* to the
forefront.
Example of the default format with ANSI escapes enabled:
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
This backports PR #1696 to v0.1.x.
## Motivation
Currently, whether `tracing-subscriber`'s `fmt` subscriber will ANSI
formatting escape codes use is configured on the `Format` type. This
means that the configuration is honored by the event formatters
implemented in `tracing-subscriber`, but is not easily exposed to those
in other crates. Additionally, it's not currently easy to expose the
configuration to the field formatter, so it's difficult to implement
field formatters that use ANSI escape codes conditionally.
Issue #1651 suggested a new API for this, where the writer that's passed
in to the event and field formatters provides a method for checking if
ANSI escape codes are supported.
## Solution
This branch adds a new method to the `Writer` type added in #1661. The
`FormatEvent` and `FormatFields` implementations can call
`Writer::has_ansi_escapes` to determine whether ANSI escape codes are
supported. This is also propagated to `FormattedFields`, so that it can
be determined when adding new fields to a preexisting set of formatted
fields.
Fixes#1651
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
In `tracing-subscriber` 0.3.x, `MakeWriter` filtering seems to have
stopped working when using the `BoxMakeWriter` wrapper to erase the type
of a `MakeWriter` implementation. It looks like what happened is that
commit 6cc6c47354, which backported the
change to add a lifetime parameter to `MakeWriter` (#781), I
accidentally clobbered the `make_writer_for` method on the inner `Boxed`
type, so that it only has `make_writer`:
6cc6c47354 (diff-c5dc275b15a60c1a2d4694da3797f4247c4f2e1e0978fd210dd14452d6746283L737-L739)
This meant that any filtering performed by the `MakeWriter` inside the
box is now ignored. My bad!
## Solution
This commit puts back the missing `make_writer_for` method. Whoops!
Fixes#1694
Resolves#1669. Namely, I:
- fixed the incorrect docs on `LevelFilter`.
- Removed a stray backtick on `LevelFilter::current`.
- Added a matching backtick in Level's documentation.
I did _not_ add example of comparing a level against a `LevelFilter`; I
instead pointed readers to Level's documentation.
# 0.3.1 (Oct 25, 2021)
This release fixes a few issues related to feature flagging.
### Fixed
- **time**: Compilation error when enabling the "time" feature flag
without also enabling the "local-time" feature flag ([#1685])
- **registry**: Unused method warnings when the "std" feature is enabled
but the "registry" feature is disabled ([#1686])
[#1685]: https://github.com/tokio-rs/tracing/pull/1685
[#1686]: https://github.com/tokio-rs/tracing/pull/1686
## Motivation
Currently, there are some `pub(crate)` methods on the `Extensions`,
`ExtensionsMut`, and `ExtensionsInner` types that are only used when the
"registry" feature is enabled. However, the _types_ exist when the "std"
feature flag is enabled, so those methods produce unused method
warnings.
## Solution
This commit adds `#[cfg(feature = "registry")]` to those methods, fixing
the warning.
## Motivation
Currently, the `pub use` re-export for the `LocalTime` struct is enabled
whenever the "time" feature flag is enabled. However, this type only
_exists_ when the "local-time" feature flag is enabled, so enabling only
the `time` feature results in a compilation error.
## Solution
This commit adds a separate `pub use` for `LocalTime` that's only
enabled when the "local-time" feature is enabled.
Fixes#1683
