vbauerster / mpb

multi progress bar for Go cli applications
The Unlicense
2.29k stars 123 forks source link

Deadlock in Bar.serve-> Progress.dropBar vs. Progress.serve -> Bar.* #100

Closed mtrmac closed 2 years ago

mtrmac commented 2 years ago

(Just filing to have a link destination for now; more research to come.)

With MPB 7.1.3, we see occasional, but fairly easy to reproduce, deadlocks, where Progress.serve and Bar.serve wait for each other, e.g. with

goroutine 54 [select]: # Progress.serve blocks on Bar[0xc0008e4060].{operateState,done}
    github.com/vbauerster/mpb/v7.(*Bar).Completed(0xc0008e4060, 0xc000571d01)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/bar.go:304 +0x107
    github.com/vbauerster/mpb/v7.(*Bar).forceRefreshIfLastUncompleted.func1(0xc0008e4060, 0xc000077f01)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/bar.go:393 +0x49
    github.com/vbauerster/mpb/v7.(*Progress).traverseBars.func1(0xc0001dbce0)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/progress.go:166 +0x66
    github.com/vbauerster/mpb/v7.(*Progress).serve(0xc0000884e0, 0xc0001dbce0, 0xc0000938b0)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/progress.go:232 +0x166
    created by github.com/vbauerster/mpb/v7.NewWithContext
        /root/podman/vendor/github.com/vbauerster/mpb/v7/progress.go:98 +0x30b

vs.

goroutine 68 [select]: # Bar[0xc0008e4060] blocks on Progress.{operateState,done}
    github.com/vbauerster/mpb/v7.(*Progress).dropBar(0xc0000884e0, 0xc0008e4060)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/progress.go:148 +0xe5
    github.com/vbauerster/mpb/v7.(*Bar).Abort.func1(0xc0001f87e0)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/bar.go:277 +0x4f
    github.com/vbauerster/mpb/v7.(*Bar).serve(0xc0008e4060, 0x1eac2e0, 0xc0000bb540, 0xc0001f87e0)
        /root/podman/vendor/github.com/vbauerster/mpb/v7/bar.go:317 +0x83
    created by github.com/vbauerster/mpb/v7.newBar
        /root/podman/vendor/github.com/vbauerster/mpb/v7/bar.go:98 +0x305

Alternative reproducer (wait for the output to stop without a shell prompt, press Ctrl-\ to trigger a backtrace):

package main

import (
    "log"
    "os"
    "os/signal"
    "runtime"
    "syscall"

    "github.com/vbauerster/mpb/v7"
)

func main() {
    go func() {
        sigs := make(chan os.Signal, 1)
        signal.Notify(sigs, syscall.SIGQUIT)
        buf := make([]byte, 1<<20)
        for {
            <-sigs
            stacklen := runtime.Stack(buf, true)
            log.Fatalf("=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end\n", buf[:stacklen])
        }
    }()

    p := mpb.New(mpb.WithWidth(64))
    for tries := 0; tries < 100; tries++ {
        for i := 0; i < 30; i++ {
            switch i % 3 {
            case 0:
                // Managed to completely avoid the operation: declare success
                bar := p.AddBar(2)
                bar.SetTotal(0, true)
                bar.Abort(false)
            case 1:
                // Try doing the operation quickly, buy fail; discard the progress bar
                bar := p.AddBar(2)
                bar.SetTotal(2, false)
                bar.Abort(true)
            case 2:
                // Do the operation the hard way, succeed
                bar := p.AddBar(2)
                bar.SetTotal(2, true)
                bar.Abort(false)

            }
        }
    }
    p.Wait()
}

with backtrace like

^\2021/08/31 14:15:03 === received SIGQUIT ===
*** goroutine dump...
goroutine 6 [running]:
main.main.func1()
    /Users/mitr/Go/src/github.com/containers/libpod/foo.go:20 +0xe8
created by main.main
    /Users/mitr/Go/src/github.com/containers/libpod/foo.go:14 +0x26

goroutine 1 [chan receive]:
github.com/vbauerster/mpb/v7.(*Bar).Abort(0xc000582960, 0x1)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/bar.go:296 +0xe5
main.main()
    /Users/mitr/Go/src/github.com/containers/libpod/foo.go:38 +0x16d

goroutine 7 [select]:
github.com/vbauerster/mpb/v7.(*Bar).wSyncTable(0xc000582960)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/bar.go:412 +0xe5
github.com/vbauerster/mpb/v7.(*pState).updateSyncMatrix(0xc00012c0b0)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:360 +0xb7
github.com/vbauerster/mpb/v7.(*pState).render(0xc00012c0b0, 0xc000068190)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:288 +0x2d
github.com/vbauerster/mpb/v7.(*Progress).serve(0xc0000222a0, 0xc00012c0b0, 0x0)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:234 +0x187
created by github.com/vbauerster/mpb/v7.NewWithContext
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:98 +0x38f

goroutine 8 [chan send]:
github.com/vbauerster/mpb/v7.(*pState).newTicker.func1()
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:270 +0x2f1
created by github.com/vbauerster/mpb/v7.(*pState).newTicker
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:253 +0xef

goroutine 33 [syscall]:
os/signal.signal_recv()
    /usr/local/go/src/runtime/sigqueue.go:166 +0x28
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:24 +0x19
created by os/signal.Notify.func1.1
    /usr/local/go/src/os/signal/signal.go:151 +0x2c

goroutine 290482 [select]:
github.com/vbauerster/mpb/v7.(*Progress).dropBar(0xc0000222a0, 0xc000582960)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/progress.go:148 +0xc5
github.com/vbauerster/mpb/v7.(*Bar).Abort.func1(0xc00039b778)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/bar.go:277 +0x85
github.com/vbauerster/mpb/v7.(*Bar).serve(0xc000582960, {0x11030d8, 0xc000103f00}, 0xc000724480)
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/bar.go:317 +0x9f
created by github.com/vbauerster/mpb/v7.newBar
    /Users/mitr/Go/pkg/mod/github.com/vbauerster/mpb/v7@v7.1.3/bar.go:98 +0x327

*** end
exit status 1
vbauerster commented 2 years ago

Thanks for reporting. This is interesting bug. I'll review your related PR.