Bugfixes and integration tests for 'default' callback plugin

* display 'changed' tasks when hiding 'ok' tasks
* display proper task title for handlers (fixes #44007)

lib/ansible/plugins/callback/default.py

@@ -54,6 +54,7 @@ class CallbackModule(CallbackBase):
         self._play = None
         self._last_task_banner = None
         self._last_task_name = None
+        self._task_type_cache = {}
         super(CallbackModule, self).__init__()
 
     def set_options(self, task_keys=None, var_options=None, direct=None):
@@ -96,38 +97,42 @@ class CallbackModule(CallbackBase):
 
     def v2_runner_on_ok(self, result):
 
-        if self.display_ok_hosts:
+        delegated_vars = result._result.get('_ansible_delegated_vars', None)
 
-            delegated_vars = result._result.get('_ansible_delegated_vars', None)
+        if isinstance(result._task, TaskInclude):
+            return
+        elif result._result.get('changed', False):
+            if self._last_task_banner != result._task._uuid:
+                self._print_task_banner(result._task)
+
+            if delegated_vars:
+                msg = "changed: [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
+            else:
+                msg = "changed: [%s]" % result._host.get_name()
+            color = C.COLOR_CHANGED
+        else:
+            if not self.display_ok_hosts:
+                return
 
             if self._last_task_banner != result._task._uuid:
                 self._print_task_banner(result._task)
 
-            if isinstance(result._task, TaskInclude):
+            if delegated_vars:
-                return
+                msg = "ok: [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
-            elif result._result.get('changed', False):
-                if delegated_vars:
-                    msg = "changed: [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
-                else:
-                    msg = "changed: [%s]" % result._host.get_name()
-                color = C.COLOR_CHANGED
             else:
-                if delegated_vars:
+                msg = "ok: [%s]" % result._host.get_name()
-                    msg = "ok: [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
+            color = C.COLOR_OK
-                else:
-                    msg = "ok: [%s]" % result._host.get_name()
-                color = C.COLOR_OK
 
-            self._handle_warnings(result._result)
+        self._handle_warnings(result._result)
 
-            if result._task.loop and 'results' in result._result:
+        if result._task.loop and 'results' in result._result:
-                self._process_items(result)
+            self._process_items(result)
-            else:
+        else:
-                self._clean_results(result._result, result._task.action)
+            self._clean_results(result._result, result._task.action)
 
-                if (self._display.verbosity > 0 or '_ansible_verbose_always' in result._result) and '_ansible_verbose_override' not in result._result:
+            if (self._display.verbosity > 0 or '_ansible_verbose_always' in result._result) and '_ansible_verbose_override' not in result._result:
-                    msg += " => %s" % (self._dump_results(result._result),)
+                msg += " => %s" % (self._dump_results(result._result),)
-                self._display.display(msg, color=color)
+            self._display.display(msg, color=color)
 
     def v2_runner_on_skipped(self, result):
 
@@ -165,6 +170,15 @@ class CallbackModule(CallbackBase):
         self._display.banner("NO MORE HOSTS LEFT")
 
     def v2_playbook_on_task_start(self, task, is_conditional):
+        self._task_start(task, prefix='TASK')
+
+    def _task_start(self, task, prefix=None):
+        # Cache output prefix for task if provided
+        # This is needed to properly display 'RUNNING HANDLER' and similar
+        # when hiding skipped/ok task results
+        if prefix is not None:
+            self._task_type_cache[task._uuid] = prefix
+
         # Preserve task name, as all vars may not be available for templating
         # when we need it later
         if self._play.strategy == 'free':
@@ -192,12 +206,14 @@ class CallbackModule(CallbackBase):
             args = u', '.join(u'%s=%s' % a for a in task.args.items())
             args = u' %s' % args
 
+        prefix = self._task_type_cache.get(task._uuid, 'TASK')
+
         # Use cached task name
         task_name = self._last_task_name
         if task_name is None:
             task_name = task.get_name().strip()
 
-        self._display.banner(u"TASK [%s%s]" % (task_name, args))
+        self._display.banner(u"%s [%s%s]" % (prefix, task_name, args))
         if self._display.verbosity >= 2:
             path = task.get_path()
             if path:
@@ -206,10 +222,10 @@ class CallbackModule(CallbackBase):
         self._last_task_banner = task._uuid
 
     def v2_playbook_on_cleanup_task_start(self, task):
-        self._display.banner("CLEANUP TASK [%s]" % task.get_name().strip())
+        self._task_start(task, prefix='CLEANUP TASK')
 
     def v2_playbook_on_handler_task_start(self, task):
-        self._display.banner("RUNNING HANDLER [%s]" % task.get_name().strip())
+        self._task_start(task, prefix='RUNNING HANDLER')
 
     def v2_playbook_on_play_start(self, play):
         name = play.get_name().strip()
@@ -239,31 +255,36 @@ class CallbackModule(CallbackBase):
 
     def v2_runner_item_on_ok(self, result):
 
-        if self.display_ok_hosts:
+        delegated_vars = result._result.get('_ansible_delegated_vars', None)
+        self._clean_results(result._result, result._task.action)
+        if isinstance(result._task, TaskInclude):
+            return
+        elif result._result.get('changed', False):
             if self._last_task_banner != result._task._uuid:
                 self._print_task_banner(result._task)
 
-            delegated_vars = result._result.get('_ansible_delegated_vars', None)
+            msg = 'changed'
-            self._clean_results(result._result, result._task.action)
+            color = C.COLOR_CHANGED
-            if isinstance(result._task, TaskInclude):
+        else:
+            if not self.display_ok_hosts:
                 return
-            elif result._result.get('changed', False):
-                msg = 'changed'
-                color = C.COLOR_CHANGED
-            else:
-                msg = 'ok'
-                color = C.COLOR_OK
 
-            if delegated_vars:
+            if self._last_task_banner != result._task._uuid:
-                msg += ": [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
+                self._print_task_banner(result._task)
-            else:
-                msg += ": [%s]" % result._host.get_name()
 
-            msg += " => (item=%s)" % (self._get_item_label(result._result),)
+            msg = 'ok'
+            color = C.COLOR_OK
 
-            if (self._display.verbosity > 0 or '_ansible_verbose_always' in result._result) and '_ansible_verbose_override' not in result._result:
+        if delegated_vars:
-                msg += " => %s" % self._dump_results(result._result)
+            msg += ": [%s -> %s]" % (result._host.get_name(), delegated_vars['ansible_host'])
-            self._display.display(msg, color=color)
+        else:
+            msg += ": [%s]" % result._host.get_name()
+
+        msg += " => (item=%s)" % (self._get_item_label(result._result),)
+
+        if (self._display.verbosity > 0 or '_ansible_verbose_always' in result._result) and '_ansible_verbose_override' not in result._result:
+            msg += " => %s" % self._dump_results(result._result)
+        self._display.display(msg, color=color)
 
     def v2_runner_item_on_failed(self, result):
         if self._last_task_banner != result._task._uuid:

test/integration/targets/callback_default/aliases

@@ -0,0 +1 @@
+shippable/posix/group3

test/integration/targets/callback_default/callback_default.out.default.stderr

@@ -0,0 +1,2 @@
++ ansible-playbook -i ../../inventory test.yml
+++ set +x

test/integration/targets/callback_default/callback_default.out.default.stdout

@@ -0,0 +1,44 @@
+
+PLAY [testhost] ****************************************************************
+
+TASK [Changed task] ************************************************************
+changed: [testhost]
+
+TASK [Ok task] *****************************************************************
+ok: [testhost]
+
+TASK [Failed task] *************************************************************
+fatal: [testhost]: FAILED! => {"changed": false, "msg": "no reason"}
+...ignoring
+
+TASK [Skipped task] ************************************************************
+skipping: [testhost]
+
+TASK [Task with var in name (foo bar)] *****************************************
+changed: [testhost]
+
+TASK [Loop task] ***************************************************************
+changed: [testhost] => (item=foo-1)
+changed: [testhost] => (item=foo-2)
+changed: [testhost] => (item=foo-3)
+
+RUNNING HANDLER [Test handler 1] ***********************************************
+changed: [testhost]
+
+RUNNING HANDLER [Test handler 2] ***********************************************
+ok: [testhost]
+
+RUNNING HANDLER [Test handler 3] ***********************************************
+changed: [testhost]
+
+PLAY [testhost] ****************************************************************
+
+TASK [First free task] *********************************************************
+changed: [testhost]
+
+TASK [Second free task] ********************************************************
+changed: [testhost]
+
+PLAY RECAP *********************************************************************
+testhost                   : ok=10   changed=7    unreachable=0    failed=0   
+

test/integration/targets/callback_default/callback_default.out.failed_to_stderr.stderr

@@ -0,0 +1,3 @@
++ ansible-playbook -i ../../inventory test.yml
+++ set +x
+fatal: [testhost]: FAILED! => {"changed": false, "msg": "no reason"}

test/integration/targets/callback_default/callback_default.out.failed_to_stderr.stdout

@@ -0,0 +1,43 @@
+
+PLAY [testhost] ****************************************************************
+
+TASK [Changed task] ************************************************************
+changed: [testhost]
+
+TASK [Ok task] *****************************************************************
+ok: [testhost]
+
+TASK [Failed task] *************************************************************
+...ignoring
+
+TASK [Skipped task] ************************************************************
+skipping: [testhost]
+
+TASK [Task with var in name (foo bar)] *****************************************
+changed: [testhost]
+
+TASK [Loop task] ***************************************************************
+changed: [testhost] => (item=foo-1)
+changed: [testhost] => (item=foo-2)
+changed: [testhost] => (item=foo-3)
+
+RUNNING HANDLER [Test handler 1] ***********************************************
+changed: [testhost]
+
+RUNNING HANDLER [Test handler 2] ***********************************************
+ok: [testhost]
+
+RUNNING HANDLER [Test handler 3] ***********************************************
+changed: [testhost]
+
+PLAY [testhost] ****************************************************************
+
+TASK [First free task] *********************************************************
+changed: [testhost]
+
+TASK [Second free task] ********************************************************
+changed: [testhost]
+
+PLAY RECAP *********************************************************************
+testhost                   : ok=10   changed=7    unreachable=0    failed=0   
+

test/integration/targets/callback_default/callback_default.out.hide_ok.stderr

@@ -0,0 +1,2 @@
++ ansible-playbook -i ../../inventory test.yml
+++ set +x

test/integration/targets/callback_default/callback_default.out.hide_ok.stdout

@@ -0,0 +1,38 @@
+
+PLAY [testhost] ****************************************************************
+
+TASK [Changed task] ************************************************************
+changed: [testhost]
+
+TASK [Failed task] *************************************************************
+fatal: [testhost]: FAILED! => {"changed": false, "msg": "no reason"}
+...ignoring
+
+TASK [Skipped task] ************************************************************
+skipping: [testhost]
+
+TASK [Task with var in name (foo bar)] *****************************************
+changed: [testhost]
+
+TASK [Loop task] ***************************************************************
+changed: [testhost] => (item=foo-1)
+changed: [testhost] => (item=foo-2)
+changed: [testhost] => (item=foo-3)
+
+RUNNING HANDLER [Test handler 1] ***********************************************
+changed: [testhost]
+
+RUNNING HANDLER [Test handler 3] ***********************************************
+changed: [testhost]
+
+PLAY [testhost] ****************************************************************
+
+TASK [First free task] *********************************************************
+changed: [testhost]
+
+TASK [Second free task] ********************************************************
+changed: [testhost]
+
+PLAY RECAP *********************************************************************
+testhost                   : ok=10   changed=7    unreachable=0    failed=0   
+

test/integration/targets/callback_default/callback_default.out.hide_skipped.stderr

@@ -0,0 +1,2 @@
++ ansible-playbook -i ../../inventory test.yml
+++ set +x

test/integration/targets/callback_default/callback_default.out.hide_skipped.stdout

@@ -0,0 +1,41 @@
+
+PLAY [testhost] ****************************************************************
+
+TASK [Changed task] ************************************************************
+changed: [testhost]
+
+TASK [Ok task] *****************************************************************
+ok: [testhost]
+
+TASK [Failed task] *************************************************************
+fatal: [testhost]: FAILED! => {"changed": false, "msg": "no reason"}
+...ignoring
+
+TASK [Task with var in name (foo bar)] *****************************************
+changed: [testhost]
+
+TASK [Loop task] ***************************************************************
+changed: [testhost] => (item=foo-1)
+changed: [testhost] => (item=foo-2)
+changed: [testhost] => (item=foo-3)
+
+RUNNING HANDLER [Test handler 1] ***********************************************
+changed: [testhost]
+
+RUNNING HANDLER [Test handler 2] ***********************************************
+ok: [testhost]
+
+RUNNING HANDLER [Test handler 3] ***********************************************
+changed: [testhost]
+
+PLAY [testhost] ****************************************************************
+
+TASK [First free task] *********************************************************
+changed: [testhost]
+
+TASK [Second free task] ********************************************************
+changed: [testhost]
+
+PLAY RECAP *********************************************************************
+testhost                   : ok=10   changed=7    unreachable=0    failed=0   
+

test/integration/targets/callback_default/callback_default.out.hide_skipped_ok.stderr

@@ -0,0 +1,2 @@
++ ansible-playbook -i ../../inventory test.yml
+++ set +x

test/integration/targets/callback_default/callback_default.out.hide_skipped_ok.stdout

@@ -0,0 +1,35 @@
+
+PLAY [testhost] ****************************************************************
+
+TASK [Changed task] ************************************************************
+changed: [testhost]
+
+TASK [Failed task] *************************************************************
+fatal: [testhost]: FAILED! => {"changed": false, "msg": "no reason"}
+...ignoring
+
+TASK [Task with var in name (foo bar)] *****************************************
+changed: [testhost]
+
+TASK [Loop task] ***************************************************************
+changed: [testhost] => (item=foo-1)
+changed: [testhost] => (item=foo-2)
+changed: [testhost] => (item=foo-3)
+
+RUNNING HANDLER [Test handler 1] ***********************************************
+changed: [testhost]
+
+RUNNING HANDLER [Test handler 3] ***********************************************
+changed: [testhost]
+
+PLAY [testhost] ****************************************************************
+
+TASK [First free task] *********************************************************
+changed: [testhost]
+
+TASK [Second free task] ********************************************************
+changed: [testhost]
+
+PLAY RECAP *********************************************************************
+testhost                   : ok=10   changed=7    unreachable=0    failed=0   
+

test/integration/targets/callback_default/runme.sh

@@ -0,0 +1,107 @@
+#!/usr/bin/env bash
+
+# This test compares "known good" output with various settings against output
+# with the current code. It's brittle by nature, but this is probably the
+# "best" approach possible.
+#
+# Notes:
+# * options passed to this script (such as -v) are ignored, as they would change
+#   the output and break the test
+# * the number of asterisks after a "banner" differs depending on the number of
+#   columns on the TTY, so we must adjust the columns for the current session
+#   for consistency
+
+set -eux
+
+run_test() {
+	local testname=$1
+
+	# The shenanigans with redirection and 'tee' are to capture STDOUT and
+	# STDERR separately while still displaying both to the console
+	{ ansible-playbook -i ../../inventory test.yml \
+		> >(set +x; tee "${OUTFILE}.${testname}.stdout"); } \
+		2> >(set +x; tee "${OUTFILE}.${testname}.stderr" >&2)
+	diff -u "${ORIGFILE}.${testname}.stdout" "${OUTFILE}.${testname}.stdout" || diff_failure
+	diff -u "${ORIGFILE}.${testname}.stderr" "${OUTFILE}.${testname}.stderr" || diff_failure
+}
+
+diff_failure() {
+	if [[ $INIT = 0 ]]; then
+		echo "FAILURE...diff mismatch!"
+		exit 1
+	fi
+}
+
+cleanup() {
+	if [[ $INIT = 0 ]]; then
+		rm -rf "${OUTFILE}.*"
+	fi
+	# Restore TTY cols
+	if [[ -n ${TTY_COLS:-} ]]; then
+		stty cols "${TTY_COLS}"
+	fi
+}
+
+adjust_tty_cols() {
+	if [[ -t 1 ]]; then
+		# Preserve existing TTY cols
+		TTY_COLS=$( stty -a | grep -Eo '; columns [0-9]+;' | cut -d';' -f2 | cut -d' ' -f3 )
+		# Override TTY cols to make comparing ansible-playbook output easier
+		# This value matches the default in the code when there is no TTY
+		stty cols 79
+	fi
+}
+
+BASEFILE=callback_default.out
+
+ORIGFILE="${BASEFILE}"
+OUTFILE="${BASEFILE}.new"
+
+trap 'cleanup' EXIT
+
+# The --init flag will (re)generate the "good" output files used by the tests
+INIT=0
+if [[ ${1:-} == "--init" ]]; then
+	shift
+	OUTFILE=$ORIGFILE
+	INIT=1
+fi
+
+adjust_tty_cols
+
+# Force the 'default' callback plugin, since that's what we're testing
+export ANSIBLE_STDOUT_CALLBACK=default
+# Disable color in output for consistency
+export ANSIBLE_FORCE_COLOR=0
+export ANSIBLE_NOCOLOR=1
+
+# Default settings
+export DISPLAY_SKIPPED_HOSTS=1
+export ANSIBLE_DISPLAY_OK_HOSTS=1
+export ANSIBLE_DISPLAY_FAILED_STDERR=0
+
+run_test default
+
+# Hide skipped
+export DISPLAY_SKIPPED_HOSTS=0
+
+run_test hide_skipped
+
+# Hide skipped/ok
+export DISPLAY_SKIPPED_HOSTS=0
+export ANSIBLE_DISPLAY_OK_HOSTS=0
+
+run_test hide_skipped_ok
+
+# Hide ok
+export DISPLAY_SKIPPED_HOSTS=1
+export ANSIBLE_DISPLAY_OK_HOSTS=0
+
+run_test hide_ok
+
+# Failed to stderr
+export DISPLAY_SKIPPED_HOSTS=1
+export ANSIBLE_DISPLAY_OK_HOSTS=1
+export ANSIBLE_DISPLAY_FAILED_STDERR=1
+
+run_test failed_to_stderr

test/integration/targets/callback_default/test.yml

@@ -0,0 +1,60 @@
+---
+- hosts: testhost
+  gather_facts: no
+  vars:
+    foo: foo bar
+  tasks:
+    - name: Changed task
+      command: echo foo
+      changed_when: true
+      notify: test handlers
+
+    - name: Ok task
+      command: echo foo
+      changed_when: false
+
+    - name: Failed task
+      fail:
+        msg: no reason
+      ignore_errors: yes
+
+    - name: Skipped task
+      command: echo foo
+      when: false
+
+    - name: Task with var in name ({{ foo }})
+      command: echo foo
+
+    - name: Loop task
+      command: echo foo
+      loop:
+        - 1
+        - 2
+        - 3
+      loop_control:
+        label: foo-{{ item }}
+  handlers:
+    - name: Test handler 1
+      command: echo foo
+      listen: test handlers
+
+    - name: Test handler 2
+      command: echo foo
+      changed_when: false
+      listen: test handlers
+
+    - name: Test handler 3
+      command: echo foo
+      listen: test handlers
+
+# An issue was found previously for tasks in a play using strategy 'free' after
+# a non-'free' play in the same playbook, so we protect against a regression.
+- hosts: testhost
+  gather_facts: no
+  strategy: free
+  tasks:
+    - name: First free task
+      command: echo foo
+
+    - name: Second free task
+      command: echo foo