fix minor issues with debug and item labels (#41331)

* fix minor issues with debug and item labels

 - no more `item=None`, we always have a label now
 - debug should only show expected information, either msg= or the var in var=
 - also fixed method name, deprecated misleading _get_item

(cherry picked from commit 27c43daab8)

changelogs/fragments/debug_fixes.yml

@@ -0,0 +1,2 @@
+bugfixes:
+    - correct debug display for all cases https://github.com/ansible/ansible/pull/41331

lib/ansible/executor/task_executor.py

@@ -278,14 +278,19 @@ class TaskExecutor:
         label = None
         loop_pause = 0
         templar = Templar(loader=self._loader, shared_loader_obj=self._shared_loader_obj, variables=self._job_vars)
+
+        # FIXME: move this to the object itself to allow post_validate to take care of templating (loop_control.post_validate)
         if self._task.loop_control:
-            # FIXME: move this to the object itself to allow post_validate to take care of templating
             loop_var = templar.template(self._task.loop_control.loop_var)
             index_var = templar.template(self._task.loop_control.index_var)
             loop_pause = templar.template(self._task.loop_control.pause)
-            # the these may be 'None', so we still need to default to something useful
-            # this is tempalted below after an item is assigned
-            label = (self._task.loop_control.label or ('{{' + loop_var + '}}'))
+
+            # This may be 'None',so it is tempalted below after we ensure a value and an item is assigned
+            label = self._task.loop_control.label
+
+        # ensure we always have a label
+        if label is None:
+            label = '{{' + loop_var + '}}'
 
         if loop_var in task_vars:
             display.warning(u"The loop variable '%s' is already in use. "
@@ -339,7 +344,7 @@ class TaskExecutor:
             res['_ansible_item_result'] = True
             res['_ansible_ignore_errors'] = task_fields.get('ignore_errors')
 
-            if label is not None:
+            # gets templated here unlike rest of loop_control fields, depends on loop_var above
             res['_ansible_item_label'] = templar.template(label, cache=False)
 
             self._rslt_q.put(

lib/ansible/plugins/callback/__init__.py

@@ -21,9 +21,12 @@ __metaclass__ = type
 
 import difflib
 import json
+import os
 import sys
 import warnings
+
 from copy import deepcopy
+from collections import MutableMapping
 
 from ansible import constants as C
 from ansible.parsing.ajson import AnsibleJSONEncoder
@@ -78,7 +81,7 @@ class CallbackBase(AnsiblePlugin):
         if options is not None:
             self.set_options(options)
 
-        self._hide_in_debug = ('changed', 'failed', 'skipped', 'invocation')
+        self._hide_in_debug = ('changed', 'failed', 'skipped', 'invocation', 'skip_reason')
 
     ''' helper for callbacks, so they don't all have to include deepcopy '''
     _copy_result = deepcopy
@@ -172,7 +175,7 @@ class CallbackBase(AnsiblePlugin):
                     if 'before' in diff and 'after' in diff:
                         # format complex structures into 'files'
                         for x in ['before', 'after']:
-                            if isinstance(diff[x], dict):
+                            if isinstance(diff[x], MutableMapping):
                                 diff[x] = json.dumps(diff[x], sort_keys=True, indent=4, separators=(',', ': ')) + '\n'
                         if 'before_header' in diff:
                             before_header = "before: %s" % diff['before_header']
@@ -221,27 +224,38 @@ class CallbackBase(AnsiblePlugin):
                 ret.append(">> the files are different, but the diff library cannot compare unicode strings\n\n")
         return u''.join(ret)
 
-    def _get_item(self, result):
+    def _get_item_label(self, result):
+        ''' retrieves the value to be displayed as a label for an item entry from a result object'''
         if result.get('_ansible_no_log', False):
             item = "(censored due to no_log)"
-        elif result.get('_ansible_item_label', False):
-            item = result.get('_ansible_item_label')
         else:
-            item = result.get('item', None)
-
+            item = result.get('_ansible_item_label', result.get('item'))
         return item
 
+    def _get_item(self, result):
+        ''' here for backwards compat, really should have always been named: _get_item_label'''
+        cback = getattr(self, 'NAME', os.path.basename(__file__))
+        self._display.deprecated("The %s callback plugin should be updated to use the _get_item_label method instead" % cback, version="2.11")
+        return self._get_item_label(result)
+
     def _process_items(self, result):
         # just remove them as now they get handled by individual callbacks
         del result._result['results']
 
     def _clean_results(self, result, task_name):
         ''' removes data from results for display '''
+
+        # mostly controls that debug only outputs what it was meant to
         if task_name in ['debug']:
-            for hideme in self._hide_in_debug:
-                result.pop(hideme, None)
             if 'msg' in result:
-                    result.pop('item', None)
+                # msg should be alone
+                for key in list(result.keys()):
+                    if key != 'msg' and not key.startswith('_'):
+                        result.pop(key)
+            else:
+                # 'var' value as field, so eliminate others and what is left should be varname
+                for hidme in self._hide_in_debug:
+                    result.pop(hidme, None)
 
     def set_play_context(self, play_context):
         pass
@@ -324,7 +338,7 @@ class CallbackBase(AnsiblePlugin):
     def v2_runner_on_skipped(self, result):
         if C.DISPLAY_SKIPPED_HOSTS:
             host = result._host.get_name()
-            self.runner_on_skipped(host, self._get_item(getattr(result._result, 'results', {})))
+            self.runner_on_skipped(host, self._get_item_label(getattr(result._result, 'results', {})))
 
     def v2_runner_on_unreachable(self, result):
         host = result._host.get_name()

lib/ansible/plugins/callback/default.py

@@ -205,7 +205,7 @@ class CallbackModule(CallbackBase):
         else:
             msg += ": [%s]" % result._host.get_name()
 
-        msg += " => (item=%s)" % (self._get_item(result._result),)
+        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)
@@ -224,12 +224,12 @@ class CallbackModule(CallbackBase):
             msg += "[%s]" % (result._host.get_name())
 
         self._handle_warnings(result._result)
-        self._display.display(msg + " (item=%s) => %s" % (self._get_item(result._result), self._dump_results(result._result)), color=C.COLOR_ERROR)
+        self._display.display(msg + " (item=%s) => %s" % (self._get_item_label(result._result), self._dump_results(result._result)), color=C.COLOR_ERROR)
 
     def v2_runner_item_on_skipped(self, result):
         if self._plugin_options.get('show_skipped_hosts', C.DISPLAY_SKIPPED_HOSTS):  # fallback on constants for inherited plugins missing docs
             self._clean_results(result._result, result._task.action)
-            msg = "skipping: [%s] => (item=%s) " % (result._host.get_name(), self._get_item(result._result))
+            msg = "skipping: [%s] => (item=%s) " % (result._host.get_name(), 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=C.COLOR_SKIP)

test/units/plugins/callback/test_callback.py

@@ -51,6 +51,7 @@ class TestCallback(unittest.TestCase):
 
 
 class TestCallbackResults(unittest.TestCase):
+
     def test_get_item(self):
         cb = CallbackBase()
         results = {'item': 'some_item'}
@@ -67,6 +68,22 @@ class TestCallbackResults(unittest.TestCase):
         res = cb._get_item(results)
         self.assertEquals(res, "some_item")
 
+    def test_get_item_label(self):
+        cb = CallbackBase()
+        results = {'item': 'some_item'}
+        res = cb._get_item_label(results)
+        self.assertEquals(res, 'some_item')
+
+    def test_get_item_label_no_log(self):
+        cb = CallbackBase()
+        results = {'item': 'some_item', '_ansible_no_log': True}
+        res = cb._get_item_label(results)
+        self.assertEquals(res, "(censored due to no_log)")
+
+        results = {'item': 'some_item', '_ansible_no_log': False}
+        res = cb._get_item_label(results)
+        self.assertEquals(res, "some_item")
+
     def test_clean_results_debug_task(self):
         cb = CallbackBase()
         result = {'item': 'some_item',