Currently, the LostWaker warning seems to often display false positives. These seem to occur when a task has a single waker clone, is woken by value (dropping the waker), and yields after having been woken. This seems to occur the most frequently when a task self-wakes (and that may be the only instance where this occurs?).

It would be nice to fix this --- the warning should only be shown when a task definitely won't be woken again. However, I'm not immediately sure how we would determine this.

One potential solution is that the false-positives seem to be pretty transient. They flicker in and out of existence rapidly. We could potentially just only display the lint if the task has remained in the 0-waker state for a long time.

What problem are you trying to solve?

Compiling console-subscriber into a package that already has some protos and tonic compiled in.

If these protos are using tonic's compression feature, they will enable a couple of fields (accept_compression_encodings, send_compression_encodings) that appear in console-api's generated protobufs that currently expect a unit.

How should the problem be solved?

Regenerate console-api's protos with tonic's compression turned on (it ought to be backward compatible if it's on)

Any alternatives you've considered?

Allow a feature, either through console-subscriber through to console-api to optionally enable the compression feature

How would users interact with this feature?

No response

Would you like to work on this feature?

maybe

   Compiling h2 v0.3.3
error: failed to run custom build command for `console-api v0.1.0 (/Users/joelr/Work/Rust/console/console-api)`

Caused by:
  process didn't exit successfully: `/Users/joelr/Work/Rust/console/target/debug/build/console-api-509b6171e0106590/build-script-build` (exit status: 1)
  --- stderr
  Error: Custom { kind: Other, error: "failed to invoke protoc (hint: https://docs.rs/prost-build/#sourcing-protoc): Bad CPU type in executable (os error 86)" }
warning: build failed, waiting for other jobs to finish...
error: build failed

Motivation

Currently, when constructing an update message to send over the wire, a timestamp is taken first, and then the protobuf data is constructed. This can lead to issues where the "now" timestamp is actually before timestamps present in the stats sent in that update, since the stats for a particular task/resource/async op might be updated on another thread after taking the update's "now" timestamp. This results in issues like #266.

Solution

There's no actual reason to take those timestamps before we assemble the update. This branch changes the aggregator to build all the various data updates in an update message, and then record the update's "now" timestamp. Any timestamps for tasks/resources/async ops that are recorded after the update's "now" timestamp will now be included in the next update.

Fixes #266 Depends on #290

Platform

x86_64 GNU/Linux

Description

Spawning multiple instrumented futures along with the console_subscriber consistently results in the program hanging, with 0% CPU usage – looks like a deadlock. It could of course be that I'm doing something completely wrong!

We're spawning multiple tasks in the same location, with the following snippet:

#[track_caller]
fn spawn<W, G, F>(&mut self, g: G)
where
    W: Worker<Self>,
    G: FnOnce(oneshot::Receiver<()>) -> F,
    F: Future<Output = ()> + Send + 'static,
{
    let (tx, rx) = oneshot::channel();
    let future = g(rx);

    let caller = Location::caller();
    let span = tracing::info_span!(
        target: "tokio::task", 
        "task", 
        file = caller.file(), 
        line = caller.line(),
    );

    let task = tokio::spawn(future.instrument(span))

    self.tasks
        .entry(TypeId::of::<W>())
        .or_default()
        .push((tx, Box::new(task)));
}

The following code is used to create the subscriber. If the TasksLayer is never constructed, and layer never passed to the tracing_subscriber, the code runs as expected:

let (layer, server) = console_subscriber::TasksLayer::new();

let filter = tracing_subscriber::EnvFilter::from_default_env()
    .add_directive(tracing::Level::INFO.into())
    .add_directive("tokio=info".parse().unwrap());

tracing_subscriber::registry()
    .with(tracing_subscriber::fmt::layer())
    .with(filter)
    .with(layer)
    .init();

let serve = tokio::spawn(async move { server.serve().await });

// ----------------

let _ = tokio::try_join!(tokio__spawn(node.run()), serve);

Fixes #373.

Due to a change in the unstable task builder APIs, this no longer compiles with the latest version of Tokio.

Fortunately, it's a simple fix.

Motivation

Currently, there are some rather bad issues that occur when the event buffer is at capacity and events are dropped.

Completely losing data due to buffer capacity is relatively okay: if we set a bound on how much memory the console can use, and we don't record new things that occur when we've reached that limit, this is correct and acceptable behavior. However, the current design can result in incorrect data when events are lost due to the buffer being at capacity.

This is because we currently record things like starting to poll a task/resource, ending a poll, dropping a task/resource/async op, and waker operations, as individual events in the buffer. This means that we can have a situation where the creation of a task was recorded, because there was buffer capacity at the time, but then when the task ended, the buffer was full, so we never recorded its termination. That results in the tasks appearing to run forever and never terminate --- see issue #230. Similarly, if we record the beginning of a poll, but drop the end-of-poll event because we're at capacity, this means we will (incorrectly) record a poll that goes on forever, which is obviously incorrect. I think this may also be the cause of the false positives with the lost waker lint (#149), if we record a waker drop but missed a waker clone that previously occurred.

The change in #212 fixed one category of issue that occurs due to event buffer capacity --- when a task, resource, or async op's creation event is dropped due to buffer capacity, we skip any subsequent events related to that task/resource/op. However, this doesn't fix issues where the subsequent events are the ones that are dropped.

Solution

This branch proposes a solution to this whole category of event buffer capacity related issues. Unfortunately, this requires rewriting a lot of console-subscriber's internals.

In the new approach, we now only send events over the channel when creating a new task, resource, or async op. Those events now contain an Arc holding the stats for that entity. Another clone of the Arc is stored in the tracing_subscriber::Registry's span extensions for the span corresponding to that entity. When the ConsoleLayer records subsequent events for a particular entity, such as starting/ending a poll, it looks up the span by ID, and updates the stats type stored in its extensions. The aggregator stores its clone of the Arc in a map of entities, just like it does currently, but no longer handles actually updating the stats; just building wire format updates from any tracked entities whose data was updated by the layer.

This should fix all issues where dropping something due to event buffer capacity results in incorrect data. Once we have successfully recorded the creation of a task, resource, or async op, any subsequent updates to its stats are guaranteed to be reliable. If the channel is at capacity and we fail to record a new resource/task/op, we never create a stats extension for it, and we won't record anything for it at all. Otherwise, it will always have correct data recorded.

When possible, the stats in the Arced stats are updated atomically. In some cases, this isn't easily possible, and some fields of the stats types are stored in a mutex. In particualr, this is required for storing timestamps. I don't really love that, but these mutices should be contented very infrequently. Stats aren't marked as having unset updates until after the stats inside the mutices have been updated, so the aggregator will not try to lock the mutex if the layer is currently updating it; instead, it will simply be included in the next update once the layer is no longer touching it. Mutices here will only be contended when multiple threads are updating a task's stats at the same time, which should occur very rarely...and in most cases, they still won't have to contend a mutex, since access to most of the mutices are guarded by an atomic variable for e.g. determining which thread actually was the last to complete a concurrent poll. The biggest performance downside of the mutices is probably not actually contention, but the additional heap allocation required when using std::sync::Mutex. However, since we have conditional parking_lot support, parking_lot can be used to avoid requiring additional allocations.

In the future, it's probably possible to make more of this atomic by converting timestamps into integers and storing them in atomic variables. I haven't done this yet because both the protobuf timestamps and std::time timestamps are larger than a single 64-bit number and it might take a little extra work to ensure we can nicely fit them in an AtomicUsize...but we can probably do that later.

Thanks for this great tool, that I'm using to have insights on a large app that spawns many tasks.

When I run the console long enough, it eventually displays busy tasks that run forever.

However, I'm quite positive all these tasks are finished. Indeed, these tasks are spawned via

tokio::task::Builder::new().name(some_name).spawn(some_async_function)

and they all have reached the last line of some_async_function, where I added a println!("Finished task {}", some_task_id) that actually got displayed.

So that looks either like a tokio bug that did not joined the task after it reached its last line, or a bug in the console-subscriber that misses some "task is finished" events (or in tokio-console that does not process them).

Ideas to create a minimal reproducer

Have a function that spams tasks, that all complete after some time (let's say after a random (sync or async) sleep between 1 and 40s). I could try to write it myself if that could be helpful to you. I am building and running on Win10 if that matters

The console subscriber's server generates a lot of async activity, introspecting or logging that drowns out the activity the program has outside of instrumentation.

Set a thread-local subscriber that drops events coming from the server thread.

Implementation requires a simple wrapper for NoSubscriber, because the dispatch implementation uses it as a sentinel value (https://github.com/tokio-rs/tracing/pull/2001 explains the history) and logs through the global dispatcher when a thread-local NoSubscriber is set.

I work with a large monorepo that cargo vendor's all third-party code. We use tokio quite a bit, and want to experiment with tokio/console

When vendoring console-api the ../proto directory is lost, and the crate is unbuildable. I understand that keeping proto/ as a top-level directory is probably desirable, so this change symlinks that directory into that sub-crate itself.

My understanding is that this change may also be required once console is put on crates.io?

cargo vendor before this change:

Cargo.toml build.rs   src

after:

Cargo.toml
build.rs
proto
src

This is basically copying what https://github.com/dtolnay/cxx does with symlinks

A first step to address #70. You can now press the spacebar to "pause" the console. The subscriber will continue to process events, but as along as the client is "paused", it won't send any task updates. Resuming will bring the client back to "live", getting all updates again.

I've tried a few different UI things, from making the whole background of the top red, to just making the word red... It's fine if others feel there's a better or prettier way to show this, but to keep moving forward, I just picked something that seemed good enough.

Closes #85

What crate(s) in this repo are involved in the problem?

tokio-console

What is the issue?

impl Default for ViewOptions {
    fn default() -> Self {
        Self {
            no_colors: false,
            lang: Some("en_us.UTF8".to_string()),  // 👈
            ascii_only: Some(false),
            truecolor: Some(true),
            palette: Some(Palette::All),
            toggles: ColorToggles {
                color_durations: Some(true),
                color_terminated: Some(true),
            },
        }
    }
}

https://github.com/tokio-rs/console/blob/70fc2c5d694b76499a68eca271ce4e337a313cfd/tokio-console/src/config.rs#L501

"en_us.UTF-8" is probably correct ? (with - between UTF and 8)

then

impl ViewOptions {
    pub fn is_utf8(&self) -> bool {
        if self.ascii_only.unwrap_or(false) {
            return false;
        }
        self.lang.as_deref().unwrap_or_default().ends_with("UTF-8") // 👈
    }
    //...
}

https://github.com/tokio-rs/console/blob/70fc2c5d694b76499a68eca271ce4e337a313cfd/tokio-console/src/config.rs#L423

in ViewOptions::is_utf8(), lang is assumed to be UTF-8

How can the bug be reproduced?

tokio-console gen-config > ./console.toml

bat console.toml | rg lang
lang = 'en_us.UTF8'

Logs, error output, etc

No response

Versions

tokio-console 0.1.7

Possible solution

set "en_us.UTF-8" to lang in Default::default in ViewOptions

Additional context

No response

Would you like to work on fixing this bug?

yes

What crate(s) in this repo are involved in the problem?

console-subscriber

What is the issue?

with this in my Cargo.toml

tokio = { version = "=1.17.0", features = ["tracing"] }
console-subscriber = "=0.1.8"

and tokio_unstable in my RUSTFLAGS

Something refuses to build (even after cargo clean), with this error:

error[E0599]: no method named `unwrap` found for struct `tokio::task::JoinHandle` in the current scope
    --> /home/arif/.cargo/registry/src/github.com-1ecc6299db9ec823/console-subscriber-0.1.8/src/lib.rs:1066:64
     |
1066 |     return tokio::task::Builder::new().name(_name).spawn(task).unwrap();
     |                                                                ^^^^^^ method not found in `tokio::task::JoinHandle<T>`

For more information about this error, try `rustc --explain E0599`.
error: could not compile `console-subscriber` due to previous error

This was resolved when i bumped tokio to =1.21.2

This is what the documentation says:

How can the bug be reproduced?

.

Logs, error output, etc

.

Versions

.

Possible solution

.

Additional context

.

Would you like to work on fixing this bug?

maybe

What crate(s) in this repo are involved in the problem?

tokio-console, console-subscriber

What is the issue?

I have a service which creates two long-running tasks as part of its initialization. They end up with task ids 1 & 2 as expected. The service creates a task per request, and I see those show up as expected.

initial state

after running some requests

However, when I reconnect, I see the task ids have scrambled - the long running tasks no longer have ids 1 & 2 (in this case 2 is preserved, but associated with the other long-running task). immediately disconnect and reconnect

I'd really like task ids to be stable so that I can use them for reference. Ideally they'd be monotonically increasing in order of task spawns, so they can also be used to understand when things are spawned in relation to each other.

How can the bug be reproduced?

1. Have service which creates some long-running tasks. Start it.
2. Attach tokio-console
3. Run some activity, including transient tasks. Note long-running task ids
4. Disconnect and reconnect tokio-console. Expect to see task ids unchanged, but they won't be.

Logs, error output, etc

No response

Versions

tokio-console 0.1.7
console-subscriber 0.1.8

Possible solution

No response

Additional context

No response

Would you like to work on fixing this bug?

maybe

This branch updates tokio-console's dependency on Clap from v3 to v4, tracking the breaking changes. This shouldn't result in any change in behavior besides changes in CLI help text formatting, except that we switched from using a tracing_subscriber::EnvFilter to a tracing_subscriber::filter::Targets for filtering the console's internal log messages. This is because clap requires that all arg values be Clone in v4, and we weren't using EnvFilter span filtering anyway, so I felt like this was the simplest option.