hmm.....I had initially considered abstracting my attempts to standardize some of the tool management code flow in something like InstallableToolMixIn.....so the presentation of actions on these tools to the user always appears similar. #756 is reinforcing that may actually be worthwhile....at least so people don't have to keep recreating the same code flow :)

The more I think about it, the more I realize that "when and for what do i use a wait bar?" is really a sub-question to "what is the policy for communicating with the user?". (Through yet another monologue of my mine :)) I propose some shifts in how logging should work.

A digression first though...
One of the outcomes I've noticed about the Wait Bar is that because it is dynamically kept at the bottom of the terminal even if the awaited process produces output, the Wait Bar message is always the last thing printed regarding a specific task. Now, this is fairly obvious from the semantics of the Wait Bar we've designed....but the final state of the contents of the terminal can create a misleading chronology; insofar as the output from the awaited process appears to have occurred before the process began...or perhaps more so, that the preceding task may have produced that output. This is especially true for Wait Bars (I put in this PR) that don't last very long. (See the Windows MSI packaging example.)

I say this because I think it should have important implications for how the Wait Bar is used. And furthermore, how regular logging occurs. In this PR, I initially just replaced every log that contained ellipsis with a Wait Bar...since that log was apparently indicating that something was about to happen (and it may even take some time). However, with the revelation above about "final state" of a screen for users, I think the better approach is considering when to tell the user about something.

Therefore, I propose:

• For regular logging, don't tell the user you're about to do something; do it and report success to the user...or log an error if it fails.
• For Wait Bars, a few scenarios:
  • Wrapping a command with no output (even in its failure mode)
    • Use a Wait Bar without concern
  • Wrapping a command that always has output
    • Always print a regular log first stating what the command will do ending with an ellipsis
    • Then start the command in a Wait Bar
      • It may make sense to leave message="" so it isn't just reiterating the same thing.
      • In the case message="", I think making the Wait Bar 40 characters again would be nice.
      • The Wait Bar implementation would also be updated to print the done_message at the end even if message=""
  • Wrapping a command that could have output
    • Depending on the circumstance, I think it's rational to fallback to either one of the scenarios above.
    • For instance, if the command fails and an Exception is raised, just using a Wait normally Bar is probably fine.
    • Alternatively, if the command fails, some stuff about what happened is printed, and execution continues....I think it'd be better to use the other scenario so when the user scrolls back up to it for review, it would all likely be clearer for them.

Now, as for a broad logging policy:

• Start significant tasks with a "prefix log"

  • This establishes a "context" to complete a task/outcome and communicate about subsequent "subtasks".
  • In this way, practically all logging is either a "context" or a "subtask".
  • Any subtask should be logged within a context.
  • (Taking this further, contexts are really just subtasks for the overall command.)

• Logging subtasks within a context

  • Generally, any "meaningful" step should be logged as a subtask.
    • Soo, as for what's meaningful....I guess like goldilocks, find the middle ground of what makes sense to log.
    • If a command could potentially fail the entire context, it should almost certainly be logged as subtask for the user.
  • Use a Progress Bar for an enumerable subtask that's likely to take appreciable time
    • E.g. downloading a file or applying the same function against every item in an iterable.
    • A regular log call (or at least intervening log calls for each iteration of progress) should always proceed a Progress Bar to explain it.
  • Use a Wait Bar for a subtask with indeterminate but likely appreciable length.
    • Follow rules above for how to use the Wait Bar.
  • Otherwise, report the success or failure of a subtask after it runs with a regular log.

Notes:

• I've tried to boil down the answer to "when should a Wait Bar be used?" to basically be "use a Wait Bar when the user is likely to be waiting for a command to finish". Otherwise, just run the command and then tell the user what happened.
• So, I'm definitely with you at this point on my backing off of using the Wait Bar so much.

Please let me know what I didn't explain very well. If we like this plan, I still need to implement it in this PR....I can probably do that tomorrow.

The more I think about it, the more I realize that "when and for what do i use a wait bar?" is really a sub-question to "what is the policy for communicating with the user?". (Through yet another monologue of my mine :)) I propose some shifts in how logging should work.

+1 for the issues you're thinking about here - you've definitely got the right concerns in mind.

Therefore, I propose:

• For regular logging, don't tell the user you're about to do something; do it and report success to the user...or log an error if it fails.

A qualified maybe on this one.

The concern I have is how the log reads when an error occurs. The advantage to telling someone you're about to do something is that when something breaks, the last "info" line in the logs is the thing that you were trying to do:

Doing thing 1...
Doing thing 2...
Doing thing 3...
Error!

If log messages are "post event", the error message needs to encompass what was being done.

Thing 1 done
Thing 2 done
Error doing thing 3!

I have a mild preference for the former, mostly because in the latter form, the error on thing 3 comes as a surprise - I didn't even know thing 3 was being done, and now it's failed!

We also need to differentiate between "interstitial" logs about specific tasks, and the "significant task with a prefix that define a context" - these definitely need to be "pre" not "post".

• For Wait Bars, a few scenarios:

  • Wrapping a command with no output (even in its failure mode)

    • Use a Wait Bar without concern

+1; and the message should encompass the thing being done (i.e., `message="Doing thing...") so that the in-progress output is:

XXXXX-----XXXXX Doing thing...

And the final output is:

Doing thing... done.

• Wrapping a command that always has output

  • Always print a regular log first stating what the command will do ending with an ellipsis

  • Then start the command in a Wait Bar

    • It may make sense to leave message="" so it isn't just reiterating the same thing.
    • In the case message="", I think making the Wait Bar 40 characters again would be nice.
    • The Wait Bar implementation would also be updated to print the done_message at the end even if message=""

I'd tweak this slightly:

• A pre-logging "about to X.." message
• a during/post logging message that the thing will be done (i.e., "X")

I'd also keep the smaller size of the wait bar; this accommodates for longer "X" descriptions, and also means there is only one "throb" pulsing at any one time.

If you had a command that produces 2 lines of output, this would yield the following as in-progress output (after 1 line had been generated):

Doing thing...
frobbing the widget
XXXXX-----XXXXX thing

And final output of:

Doing thing...
frobbing the widget
twiddled the gadget
thing done.

• Wrapping a command that could have output

  • Depending on the circumstance, I think it's rational to fallback to either one of the scenarios above.
  • For instance, if the command fails and an Exception is raised, just using a Wait normally Bar is probably fine.
  • Alternatively, if the command fails, some stuff about what happened is printed, and execution continues....I think it'd be better to use the other scenario so when the user scrolls back up to it for review, it would all likely be clearer for them.

Agreed that "it depends" is the best guidance; if possible, it would be desirable to avoid:

Doing thing...
frobbing the widget
thing done.
Error twiddling the gadget!

or worse:

Doing thing...
frobbing the widget
Error twiddling the gadget!
thing done.

i.e., Ideally the "thing done" line wouldn't be output at all in the case of an error.

Also - "error" in this sense is only "unrecoverable error"; there's a couple of situations where an error is expected, and can be handled in a way that allows processing to continue.

Now, as for a broad logging policy:

• Start significant tasks with a "prefix log"

  • This establishes a "context" to complete a task/outcome and communicate about subsequent "subtasks".
  • In this way, practically all logging is either a "context" or a "subtask".
  • Any subtask should be logged within a context.
  • (Taking this further, contexts are really just subtasks for the overall command.)

+1

• Logging subtasks within a context

  • Generally, any "meaningful" step should be logged as a subtask.

    • Soo, as for what's meaningful....I guess like goldilocks, find the middle ground of what makes sense to log.
    • If a command could potentially fail the entire context, it should almost certainly be logged as subtask for the user.

+1

• Use a Progress Bar for an enumerable subtask that's likely to take appreciable time

  • E.g. downloading a file or applying the same function against every item in an iterable.
  • A regular log call (or at least intervening log calls for each iteration of progress) should always proceed a Progress Bar to explain it.

• Use a Wait Bar for a subtask with indeterminate but likely appreciable length.

  • Follow rules above for how to use the Wait Bar.

• Otherwise, report the success or failure of a subtask after it runs with a regular log.

+1 except for the discussion points I've raised above.

Notes:

• I've tried to boil down the answer to "when should a Wait Bar be used?" to basically be "use a Wait Bar when the user is likely to be waiting for a command to finish". Otherwise, just run the command and then tell the user what happened.
• So, I'm definitely with you at this point on my backing off of using the Wait Bar so much.

+1; although, it's worth noting that in some cases, the fix here may be wrapping N micro-waitbars into a single waitbar. For example, Linuxdeploy post processing involves a bunch of small operations that almost never fail, produce no output except in case of a very rare error, and take almost no time. Wrapping all those operations into a single waitbar with a "post-processing binary..." message seems totally appropriate. In that type of situation, a waitbar effectively becomes a good way to decompose individual, largely reliable single operations into a "subtask" inside a context.

Interestingly, if we take this approach of grouping reliable minor tasks into waitbars, the question about what to do with standalone info() lines almost becomes moot, because there's almost no use case for a standalone info().

Please let me know what I didn't explain very well. If we like this plan, I still need to implement it in this PR....I can probably do that tomorrow.

Definitely clear. Also - please consider the opinions I've voiced here "strong opinions, weakly held"; if you think what I've described is either technically infeasible, or will result in a bad user experience, I'm more than happy to reconsider.

If log messages are "post event", the error message needs to encompass what was being done.

Yeah...this is a bit my concern as well since by the time we're logging something, we're already in an error state, so we need to explain what we were doing and how/why it failed. However, given how much logging will be encompassed in "prefix logs" and Wait Bars, I expect this really just leaves pretty straight-forward tasks....and I expect nearly all of them end up as caught exceptions when they fail. So, my expectation is these tasks can pretty simply be refactored from:

print("about to do thing...")
try:
    perform task
except:
    raise Fail

to:

try:
    perform task
    print("Did thing successfully")
except:
    print("Failed attempting thing")
    raise Fail

In this way, the original message saying something is about to happens becomes a success message....or a failure message and then the explanation for why it failed.

Nonetheless, I don't really want to force this.....so, I'll play around with it and see what makes sense....and just how many "subtasks" would be affected by this strategy.

We also need to differentiate between "interstitial" logs about specific tasks, and the "significant task with a prefix that define a context" - these definitely need to be "pre" not "post".

Absolutely. This also helps ensures there is already context to what's going on when/if a subtask fails.

i.e., Ideally the "thing done" line wouldn't be output at all in the case of an error.

If the error manifests as an Exception, then the Wait Bar itself, at least, will not print a "done" message. But agreed...we should limit the "done" messages to subtasks that complete successfully.

The fix here may be wrapping N micro-waitbars into a single waitbar.[...] In that type of situation, a waitbar effectively becomes a good way to decompose individual, largely reliable single operations into a "subtask" inside a context. [...] The question about what to do with standalone info() lines almost becomes moot, because there's almost no use case for a standalone info().

Agreed. That linuxdeploy example is a good one since it could have output but is very unlikely to since its unlikely to fail....so just wrapping it all in a simple Wait Bar definitely makes sense.

I think we're largely on the same page, though....unless you have particular reservations about my post-event logging for the more trivial subtasks. I will pursue a commit tomorrow so our discussion can get a bit more concrete.

Agreed that we seem to be on the same page; Any reservations I have about post-event logging will be a lot more productive to discuss as specific examples rather than in the abstract.

So, after reviewing all the calls to info() and wait_bar() with my previous post with mind, I didn't really find a lot that needed to be changed to comply.

Perspective
My ultimate goal is to make it easier for the logging to inherently be consistent and coherent. By moving the empty info() call in to Log, that eliminates nearly all of the need to make empty info() calls (outside of prompting the user). Therefore, future devs can simply do logging without the overhead of considering how it shows on the screen. By and large now, as long as you're using info() with and without prefix appropriately and ensuring that uses of a Wait Bar provide understandable chronology after the fact, the UI should keep itself consistent without devs needed to worry too much.

Pre/Post-Event Logging
As far as pre/post-event logging, I didn't really make any changes for this. One, there simply isn't a lot of it going on anymore with the use of Wait Bars. Two, the situation mostly dictates which is appropriate. For instance, post-event logging works quite well for patching the linuxdeploy ELF headers. However, pre-event logging makes much more sense for Apple app signing (in sign_file()) given it makes use of falling back and would require "backtrack logging" as it were to keep track.

Wait Bar Use Semantics
As for Wait Bar logging chronology....I maintain that this is something that deserves cognitive overhead with the current implementation.
For the most part, Wait Bars are wrapping things that rarely/never fail or fail & abort the entire briefcase command. Just wrapping these commands with a Wait Bar should be fine since while any command output will technically come before the Wait Bar's message on the screen, the fact that one thing was taking place and it failed should help prevent confusion about the ordering on the screen.
There are cases, though, where several Wait Bars are chained one after the other and each command could have its own output. This is where I think it will be important to implement initial info() calls to say what's happening and then enter a Wait Bar. This is most pronounced from my changes for the build command. Each target platform (except Android) now uses this approach. It's slightly repetitive.....but I think this approach provides more clarity...especially in situations where things go wrong.

Finally, all of my intended code changes are in....however, I have to run today and cannot run through more thorough manual testing; I'll do that this weekend. You're welcome to comment on the code, though, before then.

Codecov Report

Merging #755 (bde0524) into main (d7e9aa7) will decrease coverage by 0.01%.
The diff coverage is 100.00%.

This is ready for final review now.

As a P.S.....one idea I kept coming back to to handle output chronology in a Wait Bar is changing the output semantics of the Wait Bar. Currently the Wait Bar will pin itself to the bottom of the terminal until the Wait Bar exits. Anything that's printed while it is active will inherently appear above the "message" and its "done" indication.

Alternatively, the Wait Bar could print the "message" statically and then pin the pulsing bar to the bottom of the terminal. When the Wait Bar exits, a "done" message would be printed underneath the "message". In this way, any intervening output would be sandwiched between the "message" and "done". This is basically what I did manually for the build command code flows....although, I haven't been able to convince myself it's what's best for all Wait Bars. (A more extravagant version of this idea would convert a Wait Bar from its current implementation in to one that can sandwich any printed content....although, this would probably be overly complex to create....and probably unnecessary given our use-case.)