Handle logging ansible python errors properly

If an exception is thrown from ansible, we don't log it properly.

Add a playbook to the functional test of logging that doesn't mask
failures (it lets the tasks report as failed) So that we cover all four
possibilities for ansible module failure exception:

* failed task
* failed task in item
* failed task that reports as success
* failed task in item that reports as success

Change-Id: I9e355350f5ec34251f5030eaaa3f4bb7b4438a6e

4 files changed, 68 insertions, 5 deletions

diff --git a/playbooks/zuul-stream/fixtures/test-stream-failure.yaml b/playbooks/zuul-stream/fixtures/test-stream-failure.yaml
new file mode 100644
index 000000000..272431a9e
--- /dev/null
+++ b/playbooks/zuul-stream/fixtures/test-stream-failure.yaml
@@ -0,0 +1,21 @@
+- name: Run some commands to show that logging works on failed tasks too
+  hosts: node
+  tasks:
+
+    - block:
+
+      - name: Run a shell task with an ansible python exception
+        command: echo foo
+        args:
+          chdir: /somewhere/that/does/not/exist
+
+    - always:
+
+      - name: Loop with items on an ansible python exception
+        command: "echo {{ item }}"
+        with_items:
+          - item1
+          - item2
+          - item3
+        args:
+          chdir: /somewhere/that/does/not/exist
diff --git a/playbooks/zuul-stream/fixtures/test-stream.yaml b/playbooks/zuul-stream/fixtures/test-stream.yaml
index 065e33274..5bffc16ce 100644
--- a/playbooks/zuul-stream/fixtures/test-stream.yaml
+++ b/playbooks/zuul-stream/fixtures/test-stream.yaml
@@ -19,3 +19,19 @@
         - item1
         - item2
         - item3
+
+    - name: Run a shell task with an ansible python exception
+      command: echo foo
+      args:
+        chdir: /somewhere/that/does/not/exist
+      failed_when: false
+
+    - name: Loop with items on an ansible python exception
+      command: "echo {{ item }}"
+      with_items:
+        - item1
+        - item2
+        - item3
+      args:
+        chdir: /somewhere/that/does/not/exist
+      failed_when: false
diff --git a/playbooks/zuul-stream/functional.yaml b/playbooks/zuul-stream/functional.yaml
index 727598ccb..0c7c61741 100644
--- a/playbooks/zuul-stream/functional.yaml
+++ b/playbooks/zuul-stream/functional.yaml
@@ -7,6 +7,14 @@
         ZUUL_JOB_LOG_CONFIG: "{{ ansible_user_dir}}/logging.json"
         ARA_LOG_CONFIG: "{{ ansible_user_dir}}/logging.json"
 
+    - name: Run ansible playbook that should fail
+      command: ansible-playbook -vvv src/git.openstack.org/openstack-infra/zuul/playbooks/zuul-stream/fixtures/test-stream-failure.yaml
+      register: failed_results
+      failed_when: "failed_results.rc != 2"
+      environment:
+        ZUUL_JOB_LOG_CONFIG: "{{ ansible_user_dir}}/logging.json"
+        ARA_LOG_CONFIG: "{{ ansible_user_dir}}/logging.json"
+
     - name: Generate ARA html
       command: ara generate html ara-output
 
diff --git a/zuul/ansible/callback/zuul_stream.py b/zuul/ansible/callback/zuul_stream.py
index 19b11921d..b7b536f89 100644
--- a/zuul/ansible/callback/zuul_stream.py
+++ b/zuul/ansible/callback/zuul_stream.py
@@ -293,6 +293,11 @@ class CallbackModule(default.CallbackModule):
         if result._task.loop and 'results' in result_dict:
             # items have their own events
             pass
+        elif (result_dict.get('msg') == 'MODULE FAILURE' and
+              'module_stdout' in result_dict):
+            self._log_message(
+                result, status='MODULE FAILURE',
+                msg=result_dict['module_stdout'])
         else:
             self._log_message(
                 result=result, status='ERROR', result_dict=result_dict)
@@ -361,6 +366,11 @@ class CallbackModule(default.CallbackModule):
             # items have their own events
             pass
 
+        elif (result_dict.get('msg') == 'MODULE FAILURE' and
+              'module_stdout' in result_dict):
+            self._log_message(
+                result, status='MODULE FAILURE',
+                msg=result_dict['module_stdout'])
         elif result._task.action not in ('command', 'shell'):
             if 'msg' in result_dict:
                 self._log_message(msg=result_dict['msg'],
@@ -393,7 +403,12 @@ class CallbackModule(default.CallbackModule):
         else:
             status = 'ok'
 
-        if result._task.action not in ('command', 'shell'):
+        if (result_dict.get('msg') == 'MODULE FAILURE' and
+                'module_stdout' in result_dict):
+            self._log_message(
+                result, status='MODULE FAILURE',
+                msg="Item: {item}\n{module_stdout}".format(**result_dict))
+        elif result._task.action not in ('command', 'shell'):
             if 'msg' in result_dict:
                 self._log_message(
                     result=result, msg=result_dict['msg'], status=status)
@@ -416,7 +431,12 @@ class CallbackModule(default.CallbackModule):
         result_dict = dict(result._result)
         self._process_result_for_localhost(result, is_task=False)
 
-        if result._task.action not in ('command', 'shell'):
+        if (result_dict.get('msg') == 'MODULE FAILURE' and
+                'module_stdout' in result_dict):
+            self._log_message(
+                result, status='MODULE FAILURE',
+                msg="Item: {item}\n{module_stdout}".format(**result_dict))
+        elif result._task.action not in ('command', 'shell'):
             self._log_message(
                 result=result,
                 msg="Item: {item}".format(item=result_dict['item']),
@@ -424,9 +444,7 @@ class CallbackModule(default.CallbackModule):
                 result_dict=result_dict)
         else:
             self._log_message(
-                result,
-                "Item: {item} Runtime: {delta}"
-                " Start: {start} End: {end}".format(**result_dict))
+                result, "Item: {item} Result: {result}".format(**result_dict))
 
         if self._deferred_result:
             self._process_deferred(result)