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

using println sometimes causes a "zombie" bar to appear #474

Open
arifd opened this issue Aug 28, 2022 · 18 comments
Open

using println sometimes causes a "zombie" bar to appear #474

arifd opened this issue Aug 28, 2022 · 18 comments

Comments

@arifd
Copy link

arifd commented Aug 28, 2022

the zombie bar is just an uncleared bar that has been replaced on a newline by the correct, active version.

But it's jarring because i'm using MultiProgress and now It often makes me think another task/bar has been created.

To be clear, I have programmed all my bars to .finish_and_clear(). When they are not visible, i know my program is not working... Yet I scroll up in my history and I see bars. (if logs came in during a bar) and sometimes there isn't even a log in between the zombie bars and the active bars.

The content of the "println" are the pretty formated logs from tracing if that makes a difference, they can be long,and typically have about 3 or 4 newlines.

Is this a known issue, is it a feature and not a bug? is there some way to switch off this behavior?

It's unfortunate, because I want progress bars and logs, at the same time! :D

@arifd arifd changed the title using printn sometimes causes a "zombie" bar to appear using println sometimes causes a "zombie" bar to appear Aug 28, 2022
@djc
Copy link
Collaborator

djc commented Aug 28, 2022

Try With #460?

@arifd
Copy link
Author

arifd commented Aug 29, 2022

Unfortunately zombies appear to be equally as present running that commit...

indicatif = { git = "https://github.com/chris-laplante/indicatif.git", rev = "32a0cd7761e0ce91fe057b8873fcfa565afbd7c4" }

...in my Cargo.toml.

@chris-laplante
Copy link
Collaborator

Can you share the code you are trying?

@chris-laplante
Copy link
Collaborator

You mention the messages to println contain newlines. I think this is probably what is tripping up the MultiProgress. It doesn't currently attempt to count how many lines are actually displayed. #460 doesn't change that situation.

As a temporary workaround, can you try using MultiProgress::suspend to print the messages? E.g.

mp.suspend(|| eprintln!("messages\nmessages")));

@arifd
Copy link
Author

arifd commented Aug 29, 2022

I am creating the logs via tracing like this fmt::Layer::default().pretty() I take the &[u8] buffer from tracing and plug it directly into MultiProgress, like this mp.println(String::from_utf8_lossy(buffer))

an example of the zombies (on your commit) looks like this: (they are all zombies)
image

with the suspend trick mb.suspend(|| std::io::stderr().lock().write_all(buffer)); (using stderr().lock() so that I don't have to parse the bytes as a String) I am still getting zombies:
image

@chris-laplante
Copy link
Collaborator

Two other questions:

  1. How are you adding the bars to MultiProgress? Are you using add or one of the insert_ methods?
  2. Can you confirm that the zombie issue disappears when you don't print logs to the screen, whether via println or suspend?

@arifd
Copy link
Author

arifd commented Aug 30, 2022

  1. I am using mb.add()
  2. when no logs are being printed.... I am STILL getting zombies!!

In fact, this minimal example (on your commit) works! (haven't tested it on the crates.io release):

// cargo add tracing
// cargo add tracing-subscriber
// cargo add indicatif
// cargo add once_cell

use indicatif::{MultiProgress, ProgressBar};
use once_cell::sync::Lazy;
use std::{io::Write, time::Duration};
use tracing::{info, subscriber::set_global_default};
use tracing_subscriber::{
    fmt::{Layer, MakeWriter},
    prelude::__tracing_subscriber_SubscriberExt,
    Registry,
};

static MB: Lazy<MultiProgress> = Lazy::new(|| MultiProgress::new());

fn main() {
    let mb = MB.clone();

    let logs = Layer::default()
        .pretty()
        .with_writer(RedirectedWriter::new(|buffer: &[u8]| {
            MB.println(String::from_utf8_lossy(buffer))
        }));
    let subscriber = Registry::default().with(logs);
    set_global_default(subscriber).unwrap();

    std::thread::spawn(move || loop {
        let pb = ProgressBar::new_spinner();
        pb.enable_steady_tick(Duration::from_millis(250));
        let pb = mb.add(pb);
        std::thread::sleep(Duration::from_secs(1));
        pb.finish_and_clear();
    });

    std::thread::spawn(move || loop {
        info!("hello world");
        std::thread::sleep(Duration::from_millis(250));
    })
    .join()
    .unwrap();
}

// tracing boilerplate

#[derive(Clone)]
pub struct RedirectedWriter {
    f: fn(&[u8]) -> std::io::Result<()>,
}

impl RedirectedWriter {
    pub fn new(f: fn(&[u8]) -> std::io::Result<()>) -> Self {
        Self { f }
    }
}

impl Write for RedirectedWriter {
    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
        (self.f)(buf)?;
        Ok(buf.len())
    }

    fn flush(&mut self) -> std::io::Result<()> {
        Ok(())
    }
}
impl MakeWriter<'_> for RedirectedWriter {
    type Writer = Self;

    fn make_writer(&self) -> Self::Writer {
        self.clone()
    }
}

Maybe the only other interesting thing I am doing to the progressbars, is every time a stage of processing progresses. I clone the pb (I clone because I can't move it out of the struct which impls Drop... I guess I could std::mem::swap with a fresh pb ( (that I will never .tick() nor .add() to the mb because I don't actually ever want to see it) if you would like me to)

then I .set_style() on the cloned pb to update the progress bar with new a template. I don't interact with the mb. i don't add it again or anything.

@arifd
Copy link
Author

arifd commented Aug 30, 2022

Look! Run this code for a while, you will see zombies:

use indicatif::{MultiProgress, ProgressBar, ProgressStyle};
use once_cell::sync::Lazy;
use std::time::Duration;

static MB: Lazy<MultiProgress> = Lazy::new(|| MultiProgress::new());

fn create_bar() {
    std::thread::spawn(move || loop {
        let pb = ProgressBar::new_spinner();
        pb.enable_steady_tick(Duration::from_millis(100));
        let _pb = MB.add(pb);
        let __pb = _pb.clone();
        std::thread::spawn(move || {
            let mut i = 0;
            loop {
                i += 1;
                let pb = _pb.clone();
                pb.set_style(ProgressStyle::with_template(&i.to_string()).unwrap());
                std::thread::sleep(Duration::from_millis(123));
            }
        });
        std::thread::sleep(Duration::from_secs(5));
        __pb.finish_and_clear();
    });
}

fn main() {
    loop {
        create_bar();
        std::thread::sleep(Duration::from_secs(2));
    }
}

@chris-laplante
Copy link
Collaborator

I think the issue is that you are starting the ticker before adding the progress bar to the MultiProgress. When I run your example I do indeed get zombies, but when I tweak it as follows I don't:

use indicatif::{MultiProgress, ProgressBar, ProgressStyle};
use once_cell::sync::Lazy;
use std::time::Duration;

static MB: Lazy<MultiProgress> = Lazy::new(|| MultiProgress::new());

fn create_bar() {
    std::thread::spawn(move || loop {
        let pb = ProgressBar::new_spinner();
        let _pb = MB.add(pb);
        _pb.enable_steady_tick(Duration::from_millis(100));
        let __pb = _pb.clone();
        std::thread::spawn(move || {
            let mut i = 0;
            loop {
                i += 1;
                let pb = _pb.clone();
                pb.set_style(ProgressStyle::with_template(&i.to_string()).unwrap());
                std::thread::sleep(Duration::from_millis(123));
            }
        });
        std::thread::sleep(Duration::from_secs(5));
        __pb.finish_and_clear();
    });
}

fn main() {
    loop {
        create_bar();
        std::thread::sleep(Duration::from_secs(2));
    }
}

@arifd
Copy link
Author

arifd commented Aug 30, 2022

That's frustrating because in my actual code, the only place where i mb.add() I do so, and then set .enable_steady_tick()

The other interesting moments happen during state changes, I clone the pb then .set_style() and give it a new style. But there is no more interaction with mb since it has been already added, the only behaviours I need are to change the style and kill it when done

@arifd
Copy link
Author

arifd commented Aug 30, 2022

@chris-laplante here is the entirety of my interaction with indicatif. (minus the PROGRESS.println(String::from_utf8_lossy(buffer)) logs which happens in another mod) (it's not too much) if you're curious as to the cause of the bug:
https://gist.github.com/arifd/51499d11b19ef3be7409ce1c49820ed9

@chris-laplante
Copy link
Collaborator

That's frustrating because in my actual code, the only place where i mb.add() I do so, and then set .enable_steady_tick()

The other interesting moments happen during state changes, I clone the pb then .set_style() and give it a new style. But there is no more interaction with mb since it has been already added, the only behaviours I need are to change the style and kill it when done

Does your output end up going into scrollback? In order words, are you trying to display more lines than there are rows in your terminal?

@chris-laplante
Copy link
Collaborator

@chris-laplante here is the entirety of my interaction with indicatif. (minus the PROGRESS.println(String::from_utf8_lossy(buffer)) logs which happens in another mod) (it's not too much) if you're curious as to the cause of the bug: https://gist.github.com/arifd/51499d11b19ef3be7409ce1c49820ed9

I don't see any reason why this shouldn't work :(.

@arifd
Copy link
Author

arifd commented Aug 30, 2022

That's frustrating because in my actual code, the only place where i mb.add() I do so, and then set .enable_steady_tick()
The other interesting moments happen during state changes, I clone the pb then .set_style() and give it a new style. But there is no more interaction with mb since it has been already added, the only behaviours I need are to change the style and kill it when done

Does your output end up going into scrollback? In order words, are you trying to display more lines than there are rows in your terminal?
It's hard for me to provide you a good screenshot unfortunately, but yes, i will get zombies, even before all the rows have been filled up with content, and even without any logs being printed.
In this screenshot there did happen to be a couple logs but then I got zombies anyway.
The zombies in this screen shot are the lines beginning with [645, 664, 688, 645, 664, 645, 664, 645, 664, 688]. In fact, we can know they are zombies, because we never work the same ID at the same time. Apart from that, in real life you can see the spinner is stuck.
image

@chris-laplante
Copy link
Collaborator

Without code that I can run myself it's hard to say :/. The best chance of getting this fixed is if you can come up with a self-contained reproducer. I know that's easier said than done but for inspiration you can look at the render tests: https://github.com/console-rs/indicatif/blob/main/tests/render.rs. If you could implement your reproducer as a render test, that'd be even better.

Besides that, looks like you're using Visual Studio Code? Can you try running your program in a different terminal emulator? This is to rule out issues with vscode's escape sequence processing.

@arifd
Copy link
Author

arifd commented Aug 31, 2022

Okay sure, I'll try to get at it over the weekend. Cheers.

@Bragolgirith
Copy link

Bragolgirith commented Jan 8, 2023

I get what I think is a similar issue with the following code:

fn main() {
    let multi_progress = MultiProgress::new();
    let style = ProgressStyle::with_template("[{elapsed_precise}] {bar:40.cyan/blue} {pos:>7}/{len:7} {msg}")
        .unwrap()
        .progress_chars("##-");

    let threads_count: u64 = 10;
    let operations_count: u64 = 100;

    // Start 10 threads
    let threads = (0..threads_count)
        .map(|thread_index| {
            // Add a progress bar for each thread
            let pb = multi_progress.add(ProgressBar::new(operations_count));
            pb.set_style(style.clone());
            pb.set_message(format!("Thread #{}: running", thread_index));

            thread::spawn(move || {
                // Start 100 operations in each thread
                for operation_index in 0..operations_count {
                    // Print a single line anywhere (e.g. on thread 5, operation 50).
                    // The printed line is not visible (which I assume is expected)
                    // and a few zombie bars are spawned instead.
                    if thread_index == 5 && operation_index == 50 {
                        println!("Hello, World!");
                        pb.set_message(format!("Thread #{}: running (println was here)", thread_index));
                    }

                    // Simulate 20ms of work
                    thread::sleep(Duration::from_millis(20));

                    // Update the progress bar
                    pb.inc(1);
                }
            })
        })
        .collect::<Vec<_>>();

    for thread in threads {
        thread.join().unwrap();
    }
    println!("All threads finished");
}

multibar_println

(Tested on Windows 11, with both PowerShell and Command Prompt. indicatif = "0.17.2")

@chris-laplante
Copy link
Collaborator

multibar_println

(Tested on Windows 11, with both PowerShell and Command Prompt. indicatif = "0.17.2")

This is expected - a bare println! bypasses all the MultiProgress machinery and throws off the line counts. To fix your code, just replace the println!("Hello, World!"); with pb.println("Hello, World!"); 🙂

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

4 participants