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.

marked this issue as related to #456 (closed)

@Qinusty: Please read through this issue while considering further work on #456 (closed)

@juergbi: I think the decision to cause retryable tasks to appear as WARNING instead of FAILURE was rather arbitrary, regardless of the side effects this has in recursive timed activity context managers.

One reason I have for arguing against this is to completely disambiguate the usage of message types; a message type issued from Plugin.warn() cannot be triggered by Plugin.timed_activity(), and vice versa, this disambiguation I think will help users to understand the UI, and also be helpful in scripts which parse the bst output (like the performance analysis tooling).

Another reason is just that I think that really, there is only ever grounds to retry something that failed, it doesnt make sense to retry something that warned.

Do you have any strong objection to this ?

Note: Retries are logged as warnings due to the message handler manipulating the fail messages.

job.py#L152

!765 (merged) handles tidying up the SKIPPED issues.

mentioned in merge request !766 (merged)

I'd say we can close this. The main problem is addressed and solved.

I will place some of the detail into the comments of !670 (closed)

closed

mentioned in merge request !670 (closed)