Bar stucks if the context is canceled during Process Add procedure

[jingxiaolu]

versions:

• vbauerster/mpb: v5.2.2
• containers/image: v5.4.4

background

We're using containers/image to handle container images. And it will use mpb to produce progress bars.

With it, it uses mpb as:

// containers/image/v5/copy/copy.go: newProgressPool()
pool := mpb.NewWithContext(ctx, mpb.WithWidth(40), mpb.WithOutput(c.progressOutput))

// containers/image/v5/copy/copy.go: createProgressBar()
        bar = pool.AddBar(info.Size,
            mpb.BarFillerClearOnComplete(),
            mpb.PrependDecorators(
                decor.OnComplete(decor.Name(prefix), onComplete),
            ),
            mpb.AppendDecorators(
                decor.OnComplete(decor.CountersKibiByte("%.1f / %.1f"), ""),
            ),
        )

We encounter an issue that, if this context is cancel during or before pool.AddBar(), the mpb will be stuck with this stack:

goroutine 48 [select]:
github.com/vbauerster/mpb/v5.(*Progress).serve(0xc0001aa9c0, 0xc00037cd00, 0xc0001d4f00)
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:210 +0x17e
created by github.com/vbauerster/mpb/v5.NewWithContext
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:94 +0x313

goroutine 49 [chan send, 14 minutes]:
github.com/vbauerster/mpb/v5.(*Bar).TraverseDecorators(0xc000323700, 0xc00041ef60)                    // b.operateState <- func(s *bState) {}
    atool/vendor/github.com/vbauerster/mpb/v5/bar.go:142 +0x73
github.com/vbauerster/mpb/v5.(*Bar).subscribeDecorators(0xc000323700)                                 // b.TraverseDecorators()
    atool/vendor/github.com/vbauerster/mpb/v5/bar.go:340 +0xc9
github.com/vbauerster/mpb/v5.(*Progress).Add(0xc0001aa9c0, 0x59b400, 0x55eb04c05f80, 0xc0001aaae0, 0xc00041eee0, 0x3, 0x3, 0x20)
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:132 +0x1f3     // bar.subscribeDecorators()
github.com/vbauerster/mpb/v5.(*Progress).AddBar(0xc0001aa9c0, 0x59b400, 0xc00041eee0, 0x3, 0x3, 0x0)
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:100 +0x152
github.com/containers/image/v5/copy.(*copier).createProgressBar(0xc00012a240, 0xc0001aa9c0, 0xc000553d60, 0x47, 0x59b400, 0x0, 0x0, 0x0, 0x0, 0xc0002c4440, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:984 +0x548  // bar = pool.AddBar()
github.com/containers/image/v5/copy.(*imageCopier).copyLayer(0xc0002a2880, 0x55eb04c27a40, 0xc0002f6270, 0xc000553d60, 0x47, 0x59b400, 0x0, 0x0, 0x0, 0x0, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:1061 +0xafb // copyLayer: bar := ic.c.createProgressBar()
github.com/containers/image/v5/copy.(*imageCopier).copyLayers.func1(0x0, 0xc000553d60, 0x47, 0x59b400, 0x0, 0x0, 0x0, 0x0, 0xc0002c4440, 0x31, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:827 +0x443  // copyLayers: ic.copyLayer()
created by github.com/containers/image/v5/copy.(*imageCopier).copyLayers.func2
    atool/vendor/github.com/containers/image/v5/copy/copy.go:864 +0x251

goroutine 71 [select]:
github.com/vbauerster/mpb/v5.(*pState).newTicker.func1(0xc00037cd00, 0xc00053e000, 0xc000092b40)
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:243 +0x149
created by github.com/vbauerster/mpb/v5.(*pState).newTicker
    atool/vendor/github.com/vbauerster/mpb/v5/progress.go:233 +0x7f

goroutine 63 [semacquire, 14 minutes]:
sync.runtime_Semacquire(0xc0001c12f8)
    /usr/lib/golang/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc0001c12f0)
    /usr/lib/golang/src/sync/waitgroup.go:130 +0x64
github.com/containers/image/v5/copy.(*imageCopier).copyLayers.func2.1(0xc0001c12f0, 0xc00041ece0)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:854 +0x2b  // copyLayers: copyGroup.Wait()
github.com/containers/image/v5/copy.(*imageCopier).copyLayers.func2(0xc0002a2880, 0x55eb04c27a40, 0xc0002f6270, 0xc0001c12f0, 0xc00012a480, 0x2, 0x2, 0xc0001d4e10, 0xc0003aae70, 0xc0001d4e60, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:861 +0x2dd
github.com/containers/image/v5/copy.(*imageCopier).copyLayers(0xc0002a2880, 0x55eb04c27a40, 0xc0002f6270, 0x0, 0x0)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:869 +0x46c
github.com/containers/image/v5/copy.(*copier).copyOneImage(0xc00012a240, 0x55eb04c27a40, 0xc0002f6270, 0xc0002a9d00, 0xc0003ab9b8, 0xc0001aa840, 0xc0001aa840, 0x0, 0x55eb04be6b48, 0xc0003ab398, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:638 +0x649
github.com/containers/image/v5/copy.Image(0x55eb04c27a40, 0xc0002f6270, 0xc0002a9d00, 0x55eb04c349c0, 0xc0001aa2a0, 0x55eb04c35080, 0xc00013b500, 0xc0003ab9b8, 0x0, 0x0, ...)
    atool/vendor/github.com/containers/image/v5/copy/copy.go:287 +0xf27
...

Analyze

We checked the code, it is because:

1) during newBar()->bar.serve(), the context is cancel, so this bar.serve() is returned immediately:

    for {
        select {
        case op := <-b.operateState: // but this branch is essential
            op(s)
        case <-ctx.Done():      // meets immediately
            ...
             close(b.done)
             ...
            return
        }
    }

2) so, after this newBar(), bar.subscribeDecorators() -> b.TraverseDecorators is called, and stuck at:

b.operateState <- func(s *bState) { // because the reader of b.operateState is returned...
}

Possible RC

Add a select and case <-b.done to those writing places of b.operateState <- func(s *bState) can fix this issue. Patch:

diff --git a/vendor/github.com/vbauerster/mpb/v5/bar.go b/vendor/github.com/vbauerster/mpb/v5/bar.go
index 9c28a07..56fc86a 100644
--- a/vendor/github.com/vbauerster/mpb/v5/bar.go
+++ b/vendor/github.com/vbauerster/mpb/v5/bar.go
@@ -132,14 +132,18 @@ func (b *Bar) Current() int64 {
 // Given default bar style is "[=>-]<+", refill rune is '+'.
 // To set bar style use mpb.BarStyle(string) BarOption.
 func (b *Bar) SetRefill(amount int64) {
-   b.operateState <- func(s *bState) {
+   select {
+   case b.operateState <- func(s *bState) {
        s.refill = amount
+   }:
+   case <-b.done:
    }
 }

 // TraverseDecorators traverses all available decorators and calls cb func on each.
 func (b *Bar) TraverseDecorators(cb func(decor.Decorator)) {
-   b.operateState <- func(s *bState) {
+   select {
+   case b.operateState <- func(s *bState) {
        for _, decorators := range [...][]decor.Decorator{
            s.pDecorators,
            s.aDecorators,
@@ -148,6 +152,8 @@ func (b *Bar) TraverseDecorators(cb func(decor.Decorator)) {
                cb(extractBaseDecorator(d))
            }
        }
+   }:
+   case <-b.done:
    }
 }

@@ -348,11 +354,15 @@ func (b *Bar) subscribeDecorators() {
            shutdownListeners = append(shutdownListeners, d)
        }
    })
-   b.operateState <- func(s *bState) {
+   select {
+   case b.operateState <- func(s *bState) {
        s.averageDecorators = averageDecorators
        s.ewmaDecorators = ewmaDecorators
        s.shutdownListeners = shutdownListeners
+   }:
+   case <-b.done:
    }
+
    b.hasEwmaDecorators = len(ewmaDecorators) != 0
 }

[vbauerster]

This issue has been fixed, see #73. Bump to v5.2.4

[jingxiaolu]

Thanks @vbauerster I'll bump to v5.2.4 and test again!

[vbauerster]

@jingxiaolu Feel free to reopen or create a new one if you find a bug.

[jingxiaolu]

Thanks @vbauerster testing passed with v5.2.4~