Progress.Wait() exits without waiting for Progress.Write() to complete

[fisherzrj]

Implemented a reproduction, the code is as follows

package main

import (
    "log"

    "github.com/vbauerster/mpb/v8"
    "github.com/vbauerster/mpb/v8/decor"
)

func main() {
    p := mpb.New()

    log.SetOutput(p)

    bar := p.AddBar(int64(100),
        mpb.PrependDecorators(
            decor.Name("Bar"),
            decor.Percentage(decor.WCSyncSpace),
        ),
        mpb.AppendDecorators(
            decor.OnComplete(
                decor.EwmaETA(decor.ET_STYLE_GO, 30, decor.WCSyncWidth), "done",
            ),
        ),
    )
    bar.Abort(true)
    log.Println("log")
    p.Wait()
}

Output as follows

Sometimes, can see that the output is missing

[vbauerster]

I couldn't reproduce with v8.7.0. What version did you test against? Try check error by replacing log.Println("log") with:

_, err := fmt.Fprintln(p, "log")
if err != nil {
    fmt.Println(err)
}

[fisherzrj]

I'm also using version v8.7.0. After replacing log.Println("log") with fmt.Fprintln(p, "log"), the issue disappeared. I executed it in a loop 1000 times and there was no occurrence of missing output.

When using log.Println("log"), I looped it 100 times with the following shell command, and there were 9 instances of missing output.

for i in {1..100};do echo $i;./test;done

The output is as follows:

I'm not quite sure why there is such a significant difference when using these two methods. I'm somewhat suspicious that this might be related to terminal output buffering, but I'm not sure how to test it.

I switched to several operating systems for testing and found that this issue only occurs on Linux and macOS. It ran 10,000 times on Windows without any problems.

[vbauerster]

Most probably you're hitting this case:

https://github.com/vbauerster/mpb/blob/da3162c67234f427ab06328c116bf8ef5a24e777/_examples/progressAsWriter/main.go#L64-L65

[vbauerster]

Another guess is that standard logger is buffering its write, so it may happen after p.Wait().

[fisherzrj]

Your response reminded me to add some output under Progress.Write() to identify the stages where the issue occurs.

After executing the loop with the modifications, I found that the additional 'print' statements were displaying correctly even when the output was missing. This indicates that it probably isn't a caching issue with the log standard library.

Later, upon reviewing the implementation of 'Write,' I discovered that cwriter.Writer is a terminal writer with buffering, so I suspect the issue might be related to this buffering.

Then I checked the execution conditions of Flush() and found that it defaults to refreshing every 150 milliseconds. I believe this could be the issue with the refresh rate. If the program is terminated within two 150-millisecond intervals, the data between them will be lost

After attempting to execute a refresh when the progress terminates, the issue disappeared once I added the following line at line 300 in the progress.go file.

case <-p.done:
    update := make(chan bool)
    for s.autoRefresh && err == nil {
        s.hm.state(update)
        if <-update {
            err = s.render(cw)
        } else {
            p.cw.Flush(0) // this is my add
            break
        }
    }
    if err != nil {
        _, _ = fmt.Fprintln(s.debugOut, err.Error())
    }
    s.hm.end(s.shutdownNotifier)
    return
}

After adding it, I conducted 1000 output tests and didn't observe any missing output. I believe this change likely resolved the issue.

However, my modification is clearly not elegant, and I haven't tested it for potential other impacts. I'm not familiar with this project; there are many steps I don't understand their specific purposes. Do you have any better suggestions or solutions to fix this issue?

What confuses me is that even after removing 'p.cw.Flush(0),' the problem persists even when I modify the refresh time to 1 Nanosecond. Therefore, adjusting the refresh frequency cannot resolve this issue; there needs to be a way to execute a cache flush upon thread closure.

[vbauerster]

I was able to reproduce by increasing refresh time to 1 sec. Your observation is correct. I've pushed commit which should fix this. If you can test against latest master branch, please do.

[fisherzrj]

Indeed, this fix has resolved my issue. I have retried it on multiple programs, and the problem hasn't occurred again. Thank you for your help.