timed activities sometimes balanced with WARNING in place of FAILURE, when task retries are enabled

This appears to be intentional since the introduction of retryable tasks in bfd822b3, but introduces a very strange behavior for the balancing of a START message in a timed activity.

A timed activity usually prints the name of the activity along with the name of the task, e.g. "Doing something":

• [--:--:--][deadbeef][ task:element.bst] START Doing something

  This indicates that "Doing something" started

• [00:00:10][deadbeef][ task:element.bst] SUCCESS Doing something

  This indicates that "Doing something" was successful

• [00:00:10][deadbeef][ task:element.bst] FAILURE Doing something

  This indicates that "Doing something" failed

• [00:00:10][deadbeef][ task:element.bst] WARNING Doing something

  This doesn't indicate anything comprehensive at all

  Rather, it seems to communicate that you should be worried that we were "Doing something" in the first place

If retries are enabled, they should retry things which have failed, they should not retry things which issued warnings; a warning is not the basis to perform a retry, rather a failure is.

Consistency of message type usages

Something I want us to ensure that we make very clear as a part of #456 (closed) is also clarity of what message types can happen for what reason. There are basically three classes of messaging:

• The timed activities / tasks

  These include only:

  • START - Activity started
  • SUCCESS - Activity succeeded
  • FAILURE - Activity failed
  • SKIPPED - Activity was found to be skipped while processing - this is currently not properly implemented, the CasCache issues SKIPPED messages directly, which might be helpful to the user, but rather it should be issuing an INFO message if this is the case, and allowing SKIPPED to only reflect the overall task status.

• Messages which can be explicitly emitted by plugins

  These include only:

  • LOG - A message targeted only to the task specific log file, avoiding sending it to the main log
  • DEBUG - A debugging message (this needs work, we need to provide better filtering of debug messages on a per plugin or domain basis for these messages to be useful, currently we only have a dumb --debug boolean switch)
  • STATUS - A message about what a plugin is currently doing, hidden from the main log if verbose mode is disabled
  • INFO - A message about something interesting to the user, will be printed unconditionally
  • WARNING - A message that the user should be worried about something,

  A plugin can only trigger the timed activity related message types by calling Plugin.timed_activity()

• Additional messages from the core

  • BUG - A unhandled exception occurred
  • ERROR - A fatal error occurred in post processing of a task, outside of the regular timed activity

More weird behavior from source mirroring

Note that in addition to the already incorrect logging behavior, when trying multiple source mirrors we also see this out of place WARNING, this can be observed by running ./setup.py test --addopts '-s tests/frontend/mirror.py::test_mirror_track_upstream_absent[git]':

[--:--:--][????????][track:test.bst                      ] START   test/test/????????-track.30020.log
[--:--:--][????????][track:test.bst                      ] START   Tracking master from http://www.example.com/repo
[00:00:00][????????][track:test.bst                      ] WARNING Tracking master from http://www.example.com/repo
[--:--:--][????????][track:test.bst                      ] START   Tracking master from file:///codethink/GNOME/buildstream/tmp/test_mirror_track_upstream_abs0/mirror/repo
[00:00:00][????????][track:test.bst                      ] SUCCESS Tracking master from file:///codethink/GNOME/buildstream/tmp/test_mirror_track_upstream_abs0/mirror/repo
[--:--:--][????????][track:test.bst                      ] INFO    Found new revision: 41a3f675f212a87ef3352b20a54393ca5a335537
[00:00:00][????????][track:test.bst                      ] SUCCESS test/test/????????-track.30020.log

This happens because the git source times it's track activity, and Source goes ahead and handles BstError and tries the next mirror if the previous one fails. Because a track activity at the main Job level is considered a retryable, all invocations of Context.timed_activity() will result in issuing a WARNING instead of the appropriate FAILURE, this applies recursively to all timed activities within a task.