include_role handlers bug fix

[willthames]

SUMMARY

Ensure handlers fire correctly when using include_role

When including roles, the handlers need to be added to the TaskQueueManager _notified_handlers and listening_handlers lists. They also need to be added to the uuid cache

A separate commit adds tests for this that fail before the change and succeed after the change.

Fixes #18411

ISSUE TYPE

• Bugfix Pull Request

COMPONENT NAME

include_role

ANSIBLE VERSION

ansible 2.4.0 (devel 483346d94b) last updated 2017/07/03 09:52:26 (GMT +1000)
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/home/will/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /home/will/src/ansible/lib/ansible
  executable location = /home/will/src/ansible/bin/ansible
  python version = 2.7.13 (default, May 10 2017, 20:04:28) [GCC 6.3.1 20161221 (Red Hat 6.3.1-1)]

ADDITIONAL INFORMATION

In addition to the KeyError issue associated with #18411, if you fix that by updating _notified_handlers and _listening_handlers, and add some of the extra uuid debug statements in this PR, you get this instead:

<127.0.0.1> EXEC /bin/sh -c '/usr/bin/python /home/will/.ansible/tmp/ansible-tmp-1499048621.83-88801615818650/command.py; rm -rf "/home/will/.ansible/tmp/ansible-tmp-1499048621.83-88801615818650/" > /dev/null 2>&1 && sleep 0'
 24783 1499048621.96776: opening command with Popen()
 24783 1499048621.98646: done running command with Popen()
 24783 1499048621.98772: getting output with communicate()
 24783 1499048622.63462: done communicating
 24783 1499048622.63526: done with local.exec_command()
 24783 1499048622.63585: _low_level_execute_command() done: rc=0, stdout=
{"changed": true, "end": "2017-07-03 12:23:42.573293", "stdout": "handler", "cmd": ["echo", "handler"], "start": "2017-07-03 12:23:42.562968", "delta": "0:00:00.010325", "stderr": "", "rc": 0, "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": false, "_raw_params": "echo handler", "removes": null, "creates": null, "chdir": null}}, "warnings": []}
, stderr=
 24783 1499048622.63711: done with _execute_module (command, {'_ansible_version': '2.4.0', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'echo handler', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_diff': False, '_ansible_debug': True, '_ansible_check_mode': False})
 24783 1499048622.63771: handler run complete
 24783 1499048622.63816: attempt loop complete, returning result
 24783 1499048622.63849: _execute() done
 24783 1499048622.63867: dumping result to json
 24783 1499048622.63909: done dumping result, returning
 24783 1499048622.63964: done running TaskExecutor() for localhost/HANDLER: handlertest : Running handler [9cb6d012-9901-7bcf-cf94-000000000024]
 24783 1499048622.64048: sending task result for task 9cb6d012-9901-7bcf-cf94-000000000024
 24783 1499048622.64272: done sending task result for task 9cb6d012-9901-7bcf-cf94-000000000024
 24783 1499048622.64324: WORKER PROCESS EXITING
 24733 1499048622.64828: RUNNING CLEANUP
ERROR! Unexpected Exception, this is probably a bug: 'NoneType' object has no attribute 'copy'
the full traceback was:

Traceback (most recent call last):
  File "/home/will/src/ansible/bin/ansible-playbook", line 106, in <module>
    exit_code = cli.run()
  File "/home/will/src/ansible/lib/ansible/cli/playbook.py", line 130, in run
    results = pbex.run()
  File "/home/will/src/ansible/lib/ansible/executor/playbook_executor.py", line 153, in run
    result = self._tqm.run(play=play)
  File "/home/will/src/ansible/lib/ansible/executor/task_queue_manager.py", line 289, in run
    play_return = strategy.run(iterator, play_context)
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/linear.py", line 235, in run
    results.extend(self._execute_meta(task, play_context, iterator, host))
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/__init__.py", line 865, in _execute_meta
    self.run_handlers(iterator, play_context)
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/__init__.py", line 733, in run_handlers
    result = self._do_handler_run(handler, handler.get_name(), iterator=iterator, play_context=play_context)
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/__init__.py", line 768, in _do_handler_run
    task_vars = self._variable_manager.get_vars(play=iterator._play, host=host, task=handler)
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/__init__.py", line 584, in _wait_on_pending_results
    results = self._process_pending_results(iterator)
  File "/home/will/src/ansible/lib/ansible/plugins/strategy/__init__.py", line 339, in _process_pending_results
    original_task = found_task.copy(exclude_parent=True, exclude_tasks=True)
AttributeError: 'NoneType' object has no attribute 'copy'

The above is because the handler that just ran (9cb6d012-9901-7bcf-cf94-000000000024) is not in the uuid cache.

[ansibot]

The test ansible-test sanity --test pep8 failed with the following error:

lib/ansible/playbook/role_include.py:95:5: E303 too many blank lines (2)

click here for bot help

[sunshine69]

I can confirm that this fixes the test case #18411

[willthames]

Closing and reopening, don't understand the shippable failure (from run 27349) at all, suspect nothing to do with this change.

[willthames]

Another shippable timeout (27356). Closing and reopening

[smemsh]

are these timeouts normal? maybe that should be fixed, instead of closing and reopening?

[willthames]

@smemsh it's completely unrelated to this code (the two timeouts were in completely different systems). I could look into the timeouts, but I really spent far more time on this issue than I would have liked already.

[willthames]

!needs_revision

[willthames]

Candidate for cherry-picking onto stable-2.3 at the very least (there is one conflict but it's a fairly minor one)

[resmo]

LGTM

[jimi-c]

Merged.

[jimi-c]

@willthames if we cherry-pick this to stable-2.3, it will need to go in the holding branch. I'm actually overdue for releasing 2.3.3 and need to do it this week, so this won't have time to burn in there.