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.

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

Multiple Writers or Subscribers #971

Closed
mankinskin opened this issue Sep 9, 2020 · 4 comments
Closed

Multiple Writers or Subscribers #971

mankinskin opened this issue Sep 9, 2020 · 4 comments

Comments

@mankinskin
Copy link

mankinskin commented Sep 9, 2020

Is it possible to have tracing write logs to multiple writers, such as stdout and a file?
There is tracing_subscriber::fmt::SubscriberBuilder::with_writer(), but this only allows for one writer to be set.
Another option would be to allow for multiple subscribers, however this does not seem to work, as far as I have tried:

fn init_tracing() {
    let file_appender = tracing_appender::rolling::hourly("./logs", "log");
    let (file_writer, _guard) = tracing_appender::non_blocking(file_appender);
    tracing_subscriber::fmt()
        .with_writer(file_writer)
        .init();
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .init();
    tracing::trace!("Tracing initialized.");
}
thread 'main' panicked at 'Unable to install global subscriber: SetLoggerError(())'
@mankinskin mankinskin changed the title Multiple Writers Multiple Writers or Subscribers Sep 9, 2020
@davidbarsky
Copy link
Member

davidbarsky commented Sep 9, 2020

Here's how you can have multiple, distinct writers:

use tracing_subscriber::{fmt, Registry};
use tracing_subscriber::prelude::*;

fn main() {
    let file_appender = tracing_appender::rolling::hourly("./logs", "log");
    let (file_writer, _guard) = tracing_appender::non_blocking(file_appender);

    let subscriber = Registry::default()
        .with(fmt::Layer::default().with(file_writer));
        .with(fmt::Layer::default().with(std::io::stdout));
    
    tracing::subscriber::set_global_default(subscriber).expect("unable to set global subscriber");
}

A note on your provided code example: you should hold onto _guard for as long as you'd like logs to be written to a file—if _guard is dropped at the end of the scope of init_tracing, nothing will be written to a file. Be sure to return the guard and hold onto it in fn main()!

Another option would be to allow for multiple subscribers, however this does not seem to work[..]

We don't support multiple subscribers that are active at the same time. The Layer trait (to be renamed to "Subscriber" soon, see #922) enable functionality similar to what multiple subscribers would enable.

@mankinskin
Copy link
Author

Thank you a lot, this was not really clear from the docs, to be honest. Maybe this would be a good tip for under with_writer? because I was looking for something with writers, but there wasn't anything, and understanding Layer is a huge indirection for some reason. The topic of where the logs are written seems somehow lost in the docs, if you know what I mean. Otherwise I can issue a pull request when I have the time ☺️

@mankinskin
Copy link
Author

mankinskin commented Sep 9, 2020

Note: fmt::Layer only exposes a with_writer method (as of tracing-subscriber v0.2.11), which was probably meant in the above code example.

@mankinskin
Copy link
Author

This is the code now:

use tracing_subscriber::{
    fmt,
    layer::SubscriberExt,
};
use tracing_appender::{
    non_blocking::{
        WorkerGuard,
    },
};

fn init_tracing() -> WorkerGuard {
    let file_appender = tracing_appender::rolling::hourly("./logs", "log");
    let (file_writer, guard) = tracing_appender::non_blocking(file_appender);
    tracing::subscriber::set_global_default(
        fmt::Subscriber::builder()
            // subscriber configuration
            .with_env_filter("server")
            .with_max_level(tracing::Level::DEBUG)
            .finish()
            // add additional writers
            .with(fmt::Layer::default().with_writer(file_writer))
    ).expect("Unable to set global tracing subscriber");
    debug!("Tracing initialized.");
    guard
}
#[tokio::main]
async fn main() -> Result<(), Error> {
    let _guard = init_tracing(); // hold on to WorkerGuard
    MessageStream::init()
        .await?
        .handle_messages()
        .await
}

I only add the file writer Layer explicitly because logging to stdout seems to be enabled by default for fmt::Subscriber.

huitseeker added a commit to MystenLabs/narwhal that referenced this issue Dec 18, 2021
…ubscriber

This switches the code base to [tokio/tracing](https://github.com/tokio-rs/tracing).

1. tracing's notion of Spans allows us to instrument logs with context that lets us make sense of the application's state, even in a concurrent of distributed context. The [announcement on the tokio blog](https://tokio.rs/blog/2019-08-tracing) is a pretty compact intro to the notion. Concretely, in the codebase, we have a bunch of log statements that are already emulating spans:
```rust
huitseeker@dapple-2.~/tmp/narwhal( rg --multiline '(?s)fn[^\n]*\n[^\n]*debug'                  [21:31:05]

primary/src/proposer.rs
111:    pub async fn run(&mut self) {
112:        debug!("Dag starting at round {}", self.round);

primary/src/core.rs
152:    async fn process_header(&mut self, header: &Header) -> DagResult<()> {
153:        debug!("Processing {:?}", header);
228:    async fn process_vote(&mut self, vote: Vote) -> DagResult<()> {
229:        debug!("Processing {:?}", vote);
262:    async fn process_certificate(&mut self, certificate: Certificate) -> DagResult<()> {
263:        debug!("Processing {:?}", certificate);

consensus/src/lib.rs
302:    fn order_dag(gc_depth: Round, leader: &Certificate, state: &State) -> Vec<Certificate> {
303:        debug!("Processing sub-dag of {:?}", leader);
```
... except that won't quite work in a distributed context (where those logs itnerleave) or if we use multi-threading.

2. This gives us access to the tracing ecosystem
- translating the logs [to json](https://github.com/LukeMathWalker/tracing-bunyan-formatter), or writing them [simultaneously to file and stdio is trivial](tokio-rs/tracing#971),
- tracing can feed directly into [OpenTelemetry](https://github.com/tokio-rs/tracing/tree/master/tracing-opentelemetry) or [Jaeger](https://github.com/inanna-malick/tracing-honeycomb/tree/master/tracing-jaeger),
- [tracing-timing](https://github.com/jonhoo/tracing-timing) completely subsumes the sort of log parsing that is done in benchmarks/logs,
- [tracing-distributed](https://github.com/inanna-malick/tracing-honeycomb) can feed structured logs into an observability platform.

This PR transforms the "rails" of logging from using log + event_logger to using tracing, and thereby opens the ability to open Spans or use the `#[instrument]` macro.

It keeps full backward-compatibility with the prior logs, and the fabric benchmarking files.

It does (yet) not introduce changes in observable logging behavior, except for:
- switching timestamps from ISO 8601 to RFC3339, simplifying downstream log processing,
- allowing ANSI colors when logging on stderr and NOT in benchmarking mode.

https://www.youtube.com/watch?v=JjItsfqFIdo
mwtian pushed a commit to MystenLabs/sui that referenced this issue Sep 12, 2022
…ubscriber

This switches the code base to [tokio/tracing](https://github.com/tokio-rs/tracing).

1. tracing's notion of Spans allows us to instrument logs with context that lets us make sense of the application's state, even in a concurrent of distributed context. The [announcement on the tokio blog](https://tokio.rs/blog/2019-08-tracing) is a pretty compact intro to the notion. Concretely, in the codebase, we have a bunch of log statements that are already emulating spans:
```rust
huitseeker@dapple-2.~/tmp/narwhal( rg --multiline '(?s)fn[^\n]*\n[^\n]*debug'                  [21:31:05]

primary/src/proposer.rs
111:    pub async fn run(&mut self) {
112:        debug!("Dag starting at round {}", self.round);

primary/src/core.rs
152:    async fn process_header(&mut self, header: &Header) -> DagResult<()> {
153:        debug!("Processing {:?}", header);
228:    async fn process_vote(&mut self, vote: Vote) -> DagResult<()> {
229:        debug!("Processing {:?}", vote);
262:    async fn process_certificate(&mut self, certificate: Certificate) -> DagResult<()> {
263:        debug!("Processing {:?}", certificate);

consensus/src/lib.rs
302:    fn order_dag(gc_depth: Round, leader: &Certificate, state: &State) -> Vec<Certificate> {
303:        debug!("Processing sub-dag of {:?}", leader);
```
... except that won't quite work in a distributed context (where those logs itnerleave) or if we use multi-threading.

2. This gives us access to the tracing ecosystem
- translating the logs [to json](https://github.com/LukeMathWalker/tracing-bunyan-formatter), or writing them [simultaneously to file and stdio is trivial](tokio-rs/tracing#971),
- tracing can feed directly into [OpenTelemetry](https://github.com/tokio-rs/tracing/tree/master/tracing-opentelemetry) or [Jaeger](https://github.com/inanna-malick/tracing-honeycomb/tree/master/tracing-jaeger),
- [tracing-timing](https://github.com/jonhoo/tracing-timing) completely subsumes the sort of log parsing that is done in benchmarks/logs,
- [tracing-distributed](https://github.com/inanna-malick/tracing-honeycomb) can feed structured logs into an observability platform.

This PR transforms the "rails" of logging from using log + event_logger to using tracing, and thereby opens the ability to open Spans or use the `#[instrument]` macro.

It keeps full backward-compatibility with the prior logs, and the fabric benchmarking files.

It does (yet) not introduce changes in observable logging behavior, except for:
- switching timestamps from ISO 8601 to RFC3339, simplifying downstream log processing,
- allowing ANSI colors when logging on stderr and NOT in benchmarking mode.

https://www.youtube.com/watch?v=JjItsfqFIdo
mwtian pushed a commit to mwtian/sui that referenced this issue Sep 29, 2022
…ubscriber

This switches the code base to [tokio/tracing](https://github.com/tokio-rs/tracing).

1. tracing's notion of Spans allows us to instrument logs with context that lets us make sense of the application's state, even in a concurrent of distributed context. The [announcement on the tokio blog](https://tokio.rs/blog/2019-08-tracing) is a pretty compact intro to the notion. Concretely, in the codebase, we have a bunch of log statements that are already emulating spans:
```rust
huitseeker@dapple-2.~/tmp/narwhal( rg --multiline '(?s)fn[^\n]*\n[^\n]*debug'                  [21:31:05]

primary/src/proposer.rs
111:    pub async fn run(&mut self) {
112:        debug!("Dag starting at round {}", self.round);

primary/src/core.rs
152:    async fn process_header(&mut self, header: &Header) -> DagResult<()> {
153:        debug!("Processing {:?}", header);
228:    async fn process_vote(&mut self, vote: Vote) -> DagResult<()> {
229:        debug!("Processing {:?}", vote);
262:    async fn process_certificate(&mut self, certificate: Certificate) -> DagResult<()> {
263:        debug!("Processing {:?}", certificate);

consensus/src/lib.rs
302:    fn order_dag(gc_depth: Round, leader: &Certificate, state: &State) -> Vec<Certificate> {
303:        debug!("Processing sub-dag of {:?}", leader);
```
... except that won't quite work in a distributed context (where those logs itnerleave) or if we use multi-threading.

2. This gives us access to the tracing ecosystem
- translating the logs [to json](https://github.com/LukeMathWalker/tracing-bunyan-formatter), or writing them [simultaneously to file and stdio is trivial](tokio-rs/tracing#971),
- tracing can feed directly into [OpenTelemetry](https://github.com/tokio-rs/tracing/tree/master/tracing-opentelemetry) or [Jaeger](https://github.com/inanna-malick/tracing-honeycomb/tree/master/tracing-jaeger),
- [tracing-timing](https://github.com/jonhoo/tracing-timing) completely subsumes the sort of log parsing that is done in benchmarks/logs,
- [tracing-distributed](https://github.com/inanna-malick/tracing-honeycomb) can feed structured logs into an observability platform.

This PR transforms the "rails" of logging from using log + event_logger to using tracing, and thereby opens the ability to open Spans or use the `#[instrument]` macro.

It keeps full backward-compatibility with the prior logs, and the fabric benchmarking files.

It does (yet) not introduce changes in observable logging behavior, except for:
- switching timestamps from ISO 8601 to RFC3339, simplifying downstream log processing,
- allowing ANSI colors when logging on stderr and NOT in benchmarking mode.

https://www.youtube.com/watch?v=JjItsfqFIdo
mwtian pushed a commit to mwtian/sui that referenced this issue Sep 30, 2022
…ubscriber

This switches the code base to [tokio/tracing](https://github.com/tokio-rs/tracing).

1. tracing's notion of Spans allows us to instrument logs with context that lets us make sense of the application's state, even in a concurrent of distributed context. The [announcement on the tokio blog](https://tokio.rs/blog/2019-08-tracing) is a pretty compact intro to the notion. Concretely, in the codebase, we have a bunch of log statements that are already emulating spans:
```rust
huitseeker@dapple-2.~/tmp/narwhal( rg --multiline '(?s)fn[^\n]*\n[^\n]*debug'                  [21:31:05]

primary/src/proposer.rs
111:    pub async fn run(&mut self) {
112:        debug!("Dag starting at round {}", self.round);

primary/src/core.rs
152:    async fn process_header(&mut self, header: &Header) -> DagResult<()> {
153:        debug!("Processing {:?}", header);
228:    async fn process_vote(&mut self, vote: Vote) -> DagResult<()> {
229:        debug!("Processing {:?}", vote);
262:    async fn process_certificate(&mut self, certificate: Certificate) -> DagResult<()> {
263:        debug!("Processing {:?}", certificate);

consensus/src/lib.rs
302:    fn order_dag(gc_depth: Round, leader: &Certificate, state: &State) -> Vec<Certificate> {
303:        debug!("Processing sub-dag of {:?}", leader);
```
... except that won't quite work in a distributed context (where those logs itnerleave) or if we use multi-threading.

2. This gives us access to the tracing ecosystem
- translating the logs [to json](https://github.com/LukeMathWalker/tracing-bunyan-formatter), or writing them [simultaneously to file and stdio is trivial](tokio-rs/tracing#971),
- tracing can feed directly into [OpenTelemetry](https://github.com/tokio-rs/tracing/tree/master/tracing-opentelemetry) or [Jaeger](https://github.com/inanna-malick/tracing-honeycomb/tree/master/tracing-jaeger),
- [tracing-timing](https://github.com/jonhoo/tracing-timing) completely subsumes the sort of log parsing that is done in benchmarks/logs,
- [tracing-distributed](https://github.com/inanna-malick/tracing-honeycomb) can feed structured logs into an observability platform.

This PR transforms the "rails" of logging from using log + event_logger to using tracing, and thereby opens the ability to open Spans or use the `#[instrument]` macro.

It keeps full backward-compatibility with the prior logs, and the fabric benchmarking files.

It does (yet) not introduce changes in observable logging behavior, except for:
- switching timestamps from ISO 8601 to RFC3339, simplifying downstream log processing,
- allowing ANSI colors when logging on stderr and NOT in benchmarking mode.

https://www.youtube.com/watch?v=JjItsfqFIdo
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants