github.com/ActiveState/cli@v0.0.0-20240508170324-6801f60cd051/internal/runbits/runtime/progress/progress.go (about) 1 package progress 2 3 import ( 4 "fmt" 5 "io" 6 "strings" 7 "sync" 8 "time" 9 10 "github.com/ActiveState/cli/internal/multilog" 11 "github.com/ActiveState/cli/internal/sliceutils" 12 "github.com/go-openapi/strfmt" 13 "github.com/vbauerster/mpb/v7" 14 "golang.org/x/net/context" 15 16 "github.com/ActiveState/cli/internal/errs" 17 "github.com/ActiveState/cli/internal/locale" 18 "github.com/ActiveState/cli/internal/logging" 19 "github.com/ActiveState/cli/internal/output" 20 "github.com/ActiveState/cli/pkg/platform/runtime/setup/events" 21 ) 22 23 type step struct { 24 name string 25 verb string 26 priority int 27 } 28 29 func (s step) String() string { 30 return s.name 31 } 32 33 var ( 34 StepBuild = step{"build", locale.T("building"), 10000} // the priority is high because the artifact progress bars need to fit in between the steps 35 StepDownload = step{"download", locale.T("downloading"), 20000} 36 StepInstall = step{"install", locale.T("installing"), 30000} 37 ) 38 39 type artifactStepID string 40 41 type artifactStep struct { 42 artifactID strfmt.UUID 43 step step 44 } 45 46 func (a artifactStep) ID() artifactStepID { 47 return artifactStepID(a.artifactID.String() + a.step.String()) 48 } 49 50 type ProgressDigester struct { 51 // The max width to use for the name entries of progress bars 52 maxNameWidth int 53 54 // Progress bars and spinners 55 mainProgress *mpb.Progress 56 buildBar *bar 57 downloadBar *bar 58 installBar *bar 59 solveSpinner *output.Spinner 60 artifactBars map[artifactStepID]*bar 61 62 // Artifact name lookup map 63 artifacts map[strfmt.UUID]string 64 65 // Recipe that we're performing progress for 66 recipeID strfmt.UUID 67 68 // Track the totals required as the bars for these are only initialized for the first artifact received, at which 69 // time we won't have the totals unless we previously recorded them. 70 buildsExpected map[strfmt.UUID]struct{} 71 downloadsExpected map[strfmt.UUID]struct{} 72 installsExpected map[strfmt.UUID]struct{} 73 74 // Debug properties used to reduce the number of log entries generated 75 dbgEventLog []string 76 77 out output.Outputer 78 79 // We use a mutex because whilst this package itself doesn't do any threading; its consumers do. 80 mutex *sync.Mutex 81 82 // The cancel function for the mpb package 83 cancelMpb context.CancelFunc 84 85 // Record whether changes were made 86 changesMade bool 87 // Record whether the runtime install was successful 88 success bool 89 } 90 91 func NewProgressIndicator(w io.Writer, out output.Outputer) *ProgressDigester { 92 ctx, cancel := context.WithCancel(context.Background()) 93 return &ProgressDigester{ 94 mainProgress: mpb.NewWithContext( 95 ctx, 96 mpb.WithWidth(progressBarWidth), 97 mpb.WithOutput(w), 98 mpb.WithRefreshRate(refreshRate), 99 ), 100 101 artifacts: map[strfmt.UUID]string{}, 102 artifactBars: map[artifactStepID]*bar{}, 103 104 cancelMpb: cancel, 105 maxNameWidth: MaxNameWidth(), 106 107 out: out, 108 109 mutex: &sync.Mutex{}, 110 } 111 } 112 113 func (p *ProgressDigester) Handle(ev events.Eventer) error { 114 p.dbgEventLog = append(p.dbgEventLog, fmt.Sprintf("%T", ev)) 115 116 p.mutex.Lock() 117 defer p.mutex.Unlock() 118 119 initDownloadBar := func() { 120 if p.downloadBar == nil { 121 p.downloadBar = p.addTotalBar(locale.Tl("progress_building", "Downloading"), int64(len(p.downloadsExpected)), mpb.BarPriority(StepDownload.priority)) 122 } 123 } 124 125 switch v := ev.(type) { 126 127 case events.Start: 128 logging.Debug("Initialize Event: %#v", v) 129 130 // Ensure Start event is first.. because otherwise the prints below will cause output to be malformed. 131 if p.buildBar != nil || p.downloadBar != nil || p.installBar != nil || p.solveSpinner != nil { 132 return errs.New("Received Start event after bars were already initialized, event log: %v", p.dbgEventLog) 133 } 134 135 // Report the log file we'll be using. This has to happen here and not in the BuildStarted even as there's no 136 // guarantee that no downloads or installs might have triggered before BuildStarted, in which case there's 137 // already progressbars being displayed which won't play nice with newly printed output. 138 if v.RequiresBuild { 139 p.out.Notice(locale.Tr("progress_build_log", v.LogFilePath)) 140 } 141 142 p.recipeID = v.RecipeID 143 p.artifacts = v.Artifacts 144 145 p.buildsExpected = sliceutils.ToLookupMap(v.ArtifactsToBuild) 146 p.downloadsExpected = sliceutils.ToLookupMap(v.ArtifactsToDownload) 147 p.installsExpected = sliceutils.ToLookupMap(v.ArtifactsToInstall) 148 149 if len(v.ArtifactsToBuild)+len(v.ArtifactsToDownload)+len(v.ArtifactsToInstall) == 0 { 150 p.out.Notice(locale.T("progress_nothing_to_do")) 151 } else { 152 p.changesMade = true 153 } 154 155 case events.Success: 156 p.success = true 157 158 case events.SolveStart: 159 p.out.Notice(locale.T("setup_runtime")) 160 p.solveSpinner = output.StartSpinner(p.out, locale.T("progress_solve"), refreshRate) 161 162 case events.SolveError: 163 if p.solveSpinner == nil { 164 return errs.New("SolveError called before solveBar was initialized") 165 } 166 p.solveSpinner.Stop(locale.T("progress_fail")) 167 p.solveSpinner = nil 168 169 case events.SolveSuccess: 170 if p.solveSpinner == nil { 171 return errs.New("SolveSuccess called before solveBar was initialized") 172 } 173 p.solveSpinner.Stop(locale.T("progress_success")) 174 p.solveSpinner = nil 175 176 case events.BuildSkipped: 177 if p.buildBar != nil { 178 return errs.New("BuildSkipped called, but buildBar was initialized.. this should not happen as they should be mutually exclusive") 179 } 180 181 case events.BuildStarted: 182 if p.buildBar != nil { 183 return errs.New("BuildStarted called after buildbar was already initialized") 184 } 185 p.buildBar = p.addTotalBar(locale.Tl("progress_building", "Building"), int64(len(p.buildsExpected)), mpb.BarPriority(StepBuild.priority)) 186 187 case events.BuildSuccess: 188 if p.buildBar == nil { 189 return errs.New("BuildSuccess called before buildbar was initialized") 190 } 191 192 case events.BuildFailure: 193 if p.buildBar == nil { 194 return errs.New("BuildFailure called before buildbar was initialized") 195 } 196 logging.Debug("BuildFailure called, aborting bars") 197 p.buildBar.Abort(false) // mpb has been known to stick around after it was told not to 198 if p.downloadBar != nil { 199 p.downloadBar.Abort(false) 200 } 201 if p.installBar != nil { 202 p.installBar.Abort(false) 203 } 204 205 case events.ArtifactBuildStarted: 206 if p.buildBar == nil { 207 return errs.New("ArtifactBuildStarted called before buildbar was initialized") 208 } 209 if _, ok := p.buildsExpected[v.ArtifactID]; !ok { 210 // This should ideally be a returned error, but because buildlogstreamer still speaks recipes there is a missmatch 211 // and we can receive events for artifacts we're not interested in as a result. 212 logging.Debug("ArtifactBuildStarted called for an artifact that was not expected: %s", v.ArtifactID.String()) 213 } 214 215 case events.ArtifactBuildSuccess: 216 if p.buildBar == nil { 217 return errs.New("ArtifactBuildSuccess called before buildbar was initialized") 218 } 219 if _, ok := p.buildsExpected[v.ArtifactID]; !ok { 220 // This should ideally be a returned error, but because buildlogstreamer still speaks recipes there is a missmatch 221 // and we can receive events for artifacts we're not interested in as a result. 222 logging.Debug("ArtifactBuildSuccess called for an artifact that was not expected: %s", v.ArtifactID.String()) 223 return nil 224 } 225 if p.buildBar.Current() == p.buildBar.total { 226 return errs.New("Build bar is already complete, this should not happen") 227 } 228 delete(p.buildsExpected, v.ArtifactID) 229 p.buildBar.Increment() 230 231 case events.ArtifactDownloadStarted: 232 initDownloadBar() 233 if _, ok := p.downloadsExpected[v.ArtifactID]; !ok { 234 return errs.New("ArtifactDownloadStarted called for an artifact that was not expected: %s", v.ArtifactID.String()) 235 } 236 237 if err := p.addArtifactBar(v.ArtifactID, StepDownload, int64(v.TotalSize), true); err != nil { 238 return errs.Wrap(err, "Failed to add or update artifact bar") 239 } 240 241 case events.ArtifactDownloadProgress: 242 if err := p.updateArtifactBar(v.ArtifactID, StepDownload, v.IncrementBySize); err != nil { 243 return errs.Wrap(err, "Failed to add or update artifact bar") 244 } 245 246 case events.ArtifactDownloadSkipped: 247 initDownloadBar() 248 delete(p.downloadsExpected, v.ArtifactID) 249 p.downloadBar.Increment() 250 251 case events.ArtifactDownloadSuccess: 252 if p.downloadBar == nil { 253 return errs.New("ArtifactDownloadSuccess called before downloadBar was initialized") 254 } 255 if _, ok := p.downloadsExpected[v.ArtifactID]; !ok { 256 return errs.New("ArtifactDownloadSuccess called for an artifact that was not expected: %s", v.ArtifactID.String()) 257 } 258 if err := p.dropArtifactBar(v.ArtifactID, StepDownload); err != nil { 259 return errs.Wrap(err, "Failed to drop install bar") 260 } 261 if p.downloadBar.Current() == p.downloadBar.total { 262 return errs.New("Download bar is already complete, this should not happen") 263 } 264 delete(p.downloadsExpected, v.ArtifactID) 265 p.downloadBar.Increment() 266 267 case events.ArtifactInstallStarted: 268 if p.installBar == nil { 269 p.installBar = p.addTotalBar(locale.Tl("progress_building", "Installing"), int64(len(p.installsExpected)), mpb.BarPriority(StepInstall.priority)) 270 } 271 if _, ok := p.installsExpected[v.ArtifactID]; !ok { 272 return errs.New("ArtifactInstallStarted called for an artifact that was not expected: %s", v.ArtifactID.String()) 273 } 274 if err := p.addArtifactBar(v.ArtifactID, StepInstall, int64(v.TotalSize), true); err != nil { 275 return errs.Wrap(err, "Failed to add or update artifact bar") 276 } 277 278 case events.ArtifactInstallSkipped: 279 if p.installBar == nil { 280 return errs.New("ArtifactInstallSkipped called before installBar was initialized, artifact ID: %s", v.ArtifactID.String()) 281 } 282 delete(p.installsExpected, v.ArtifactID) 283 p.installBar.Increment() 284 285 case events.ArtifactInstallSuccess: 286 if p.installBar == nil { 287 return errs.New("ArtifactInstall[Skipped|Success] called before installBar was initialized") 288 } 289 if _, ok := p.installsExpected[v.ArtifactID]; !ok { 290 return errs.New("ArtifactInstallSuccess called for an artifact that was not expected: %s", v.ArtifactID.String()) 291 } 292 if err := p.dropArtifactBar(v.ArtifactID, StepInstall); err != nil { 293 return errs.Wrap(err, "Failed to drop install bar") 294 } 295 if p.installBar.Current() == p.installBar.total { 296 return errs.New("Install bar is already complete, this should not happen") 297 } 298 delete(p.installsExpected, v.ArtifactID) 299 p.installBar.Increment() 300 301 case events.ArtifactInstallProgress: 302 if err := p.updateArtifactBar(v.ArtifactID, StepInstall, v.IncrementBySize); err != nil { 303 return errs.Wrap(err, "Failed to add or update artifact bar") 304 } 305 306 } 307 308 return nil 309 } 310 311 func (p *ProgressDigester) Close() error { 312 mainProgressDone := make(chan struct{}, 1) 313 go func() { 314 p.mainProgress.Wait() 315 mainProgressDone <- struct{}{} 316 }() 317 318 select { 319 case <-mainProgressDone: 320 break 321 322 // Wait one second, which should be plenty as we're really just waiting for the last frame to render 323 // If it's not done after 1 second it's unlikely it will ever be and it means it did not receive events in a way 324 // that we can make sense of. 325 case <-time.After(time.Second): 326 p.cancelMpb() // mpb doesn't have a Close, just a Wait. We force it as we don't want to give it the opportunity to block. 327 328 // Only if the installation was successful do we want to verify that our progress indication was successful. 329 // There's no point in doing this if it failed as due to the multithreaded nature the failure can bubble up 330 // in different ways that are difficult to predict and thus verify. 331 if p.success { 332 bars := map[string]*bar{ 333 "build bar": p.buildBar, 334 "download bar": p.downloadBar, 335 "install bar": p.installBar, 336 } 337 338 pending := 0 339 debugMsg := []string{} 340 for name, bar := range bars { 341 debugMsg = append(debugMsg, fmt.Sprintf("%s is at %v", name, func() string { 342 if bar == nil { 343 return "nil" 344 } 345 if !bar.Completed() { 346 pending++ 347 } 348 return fmt.Sprintf("%d out of %d", bar.Current(), bar.total) 349 }())) 350 } 351 352 multilog.Error(` 353 Timed out waiting for progress bars to close. Recipe: %s 354 Progress bars status: 355 %s 356 Still expecting: 357 - Builds: %v 358 - Downloads: %v 359 - Installs: %v`, 360 p.recipeID.String(), 361 strings.Join(debugMsg, "\n"), 362 p.buildsExpected, p.downloadsExpected, p.installsExpected, 363 ) 364 365 /* https://activestatef.atlassian.net/browse/DX-1831 366 if pending > 0 { 367 // We only error out if we determine the issue is down to one of our bars not completing. 368 // Otherwise this is an issue with the mpb package which is currently a known limitation, end goal is to get rid of mpb. 369 return locale.NewError("err_rtprogress_outofsync", "", constants.BugTrackerURL, logging.FilePath()) 370 } 371 */ 372 } 373 } 374 375 // Success message. Can't happen in event loop as progressbar lib clears new lines when it closes. 376 if p.success && p.changesMade { 377 p.out.Notice(locale.T("progress_completed")) 378 } 379 380 // Blank line to separate progress from rest of output 381 p.out.Notice("") 382 383 return nil 384 }