search

quinot / ansible-plugin-lookup_ldap

Ansible LDAP lookup plugin
50 stars 16 forks source link

Getting "Unexpected failure during module execution" #27

Closed cfiske closed 5 years ago

cfiske commented 5 years ago

I am using Ansible 2.6.2 (can you confirm 2.x is supported?) and no matter how I configure my vars I get "Unexpected failure during module execution". Debug output shows nothing useful (in my opinion) before or after the error.

Looking at packet capture, it never even attempts to connect to the LDAP server.

Playbook:

---
- hosts: localhost

  vars:
    # Default context
    ldap_lookup_config:
      url: ldap://my.ldap.server
      base: dc=domain,dc=com
      binddn: ou=People,dc=domain,dc=com
      bindpw: my_password

    # List group members as plain values (no key)
    group_members:
      base: ou=Groups,dc=domain,dc=com
      value: memberUid
      filter: '(cn={{ term }})'

    # A regular list of users
    users:
      - johndoe
      - marktwain

  tasks:
    - name: test task
      debug: msg="hello world"
      with_ldap:
        - context: group_members
        - my_ldap_group

  roles:
    - quinot.lookup_ldap

Output:

>ansible-playbook playbooks/test/test.yml -i hosts.test -vvvv
ansible-playbook 2.6.2
  config file = /Users/clay_fiske/git/ansible/ansible.cfg
  configured module search path = [u'/etc/ansible/modules']
  ansible python module location = /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible
  executable location = /usr/local/bin/ansible-playbook
  python version = 2.7.15 (default, Jul 23 2018, 21:27:06) [GCC 4.2.1 Compatible Apple LLVM 9.1.0 (clang-902.0.39.2)]
Using /Users/clay_fiske/git/ansible/ansible.cfg as config file
setting up inventory plugins
Set default localhost to localhost
Parsed /Users/clay_fiske/git/ansible/hosts.test inventory source with ini plugin
Loading callback plugin default of type stdout, v2.0 from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/callback/default.pyc

PLAYBOOK: test.yml *************************************************************************************************************************************************************************************
1 plays in playbooks/tacplus/test.yml

PLAY [localhost] ***************************************************************************************************************************************************************************************

TASK [Gathering Facts] *********************************************************************************************************************************************************************************
task path: /Users/clay_fiske/git/ansible/playbooks/tacplus/test.yml:2
Using module file /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/modules/system/setup.py
<localhost> ESTABLISH LOCAL CONNECTION FOR USER: clay_fiske
<localhost> EXEC /bin/sh -c '/usr/bin/python && sleep 0'
ok: [localhost]
META: ran handlers

TASK [test task] ***************************************************************************************************************************************************************************************
task path: /Users/clay_fiske/git/ansible/playbooks/tacplus/test.yml:27
fatal: [localhost]: FAILED! => {
    "msg": "Unexpected failure during module execution."
}
    to retry, use: --limit @/Users/clay_fiske/git/ansible/playbooks/tacplus/test.retry

PLAY RECAP *********************************************************************************************************************************************************************************************
localhost                  : ok=1    changed=0    unreachable=0    failed=1

For some reason it won't let me attach the debug log, so here's the section where it gets to that task:

2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52124: building list of next tasks for hosts
2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52136: getting the next task for host localhost
2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52150: done getting next task for host localhost
2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52163:  ^ task is: TASK: test task
2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52174:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-01-07 13:05:47,521 p=68967 u=clay_fiske |   68967 1546895147.52186: done building task lists
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52196: counting tasks in each state of execution
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52207: done counting tasks in each state of execution:
    num_setups: 0
    num_tasks: 1
    num_rescue: 0
    num_always: 0
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52219: advancing hosts in ITERATING_TASKS
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52229: starting to advance hosts
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52239: getting the next task for host localhost
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52252: done getting next task for host localhost
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52263:  ^ task is: TASK: test task
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52274:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-01-07 13:05:47,522 p=68967 u=clay_fiske |   68967 1546895147.52287: done advancing hosts to next task
2019-01-07 13:05:47,524 p=68967 u=clay_fiske |   68967 1546895147.52464: Loading ActionModule 'debug' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/action/debug.py (found_in_cache=False, class_only=True)
2019-01-07 13:05:47,524 p=68967 u=clay_fiske |   68967 1546895147.52492: getting variables
2019-01-07 13:05:47,525 p=68967 u=clay_fiske |   68967 1546895147.52508: in VariableManager get_vars()
2019-01-07 13:05:47,526 p=68967 u=clay_fiske |   68967 1546895147.52616: Loading TestModule 'core' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,526 p=68967 u=clay_fiske |   68967 1546895147.52644: Loading TestModule 'files' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,526 p=68967 u=clay_fiske |   68967 1546895147.52659: Loading TestModule 'mathstuff' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,527 p=68967 u=clay_fiske |   68967 1546895147.52714: Loading FilterModule 'core' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,528 p=68967 u=clay_fiske |   68967 1546895147.52810: Calling all_inventory to load vars for localhost
2019-01-07 13:05:47,528 p=68967 u=clay_fiske |   68967 1546895147.52827: Calling groups_inventory to load vars for localhost
2019-01-07 13:05:47,528 p=68967 u=clay_fiske |   68967 1546895147.52841: Calling all_plugins_inventory to load vars for localhost
2019-01-07 13:05:47,528 p=68967 u=clay_fiske |   68967 1546895147.52868: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,529 p=68967 u=clay_fiske |   68967 1546895147.52897: Calling all_plugins_play to load vars for localhost
2019-01-07 13:05:47,529 p=68967 u=clay_fiske |   68967 1546895147.52922: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,529 p=68967 u=clay_fiske |   68967 1546895147.52967: Loading data from /Users/clay_fiske/git/ansible/group_vars/all
2019-01-07 13:05:47,529 p=68967 u=clay_fiske |   68967 1546895147.52983: Calling groups_plugins_inventory to load vars for localhost
2019-01-07 13:05:47,530 p=68967 u=clay_fiske |   68967 1546895147.53008: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,530 p=68967 u=clay_fiske |   68967 1546895147.53025: Calling groups_plugins_play to load vars for localhost
2019-01-07 13:05:47,530 p=68967 u=clay_fiske |   68967 1546895147.53049: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,530 p=68967 u=clay_fiske |   68967 1546895147.53079: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,531 p=68967 u=clay_fiske |   68967 1546895147.53116: Loading VarsModule 'host_group_vars' from /usr/local/Cellar/ansible/2.6.2/libexec/lib/python2.7/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-01-07 13:05:47,554 p=68967 u=clay_fiske |   68967 1546895147.55422: done with get_vars()
2019-01-07 13:05:47,554 p=68967 u=clay_fiske |   68967 1546895147.55473: done getting variables
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55501: sending task start callback, copying the task so we can template it temporarily
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55517: done copying, going to template now
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55529: done templating
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55540: here goes the callback...
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |  TASK [test task] ***************************************************************************************************************************************************************************************
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |  task path: /Users/clay_fiske/git/ansible/playbooks/tacplus/test.yml:27
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55577: sending task start callback
2019-01-07 13:05:47,555 p=68967 u=clay_fiske |   68967 1546895147.55591: entering _queue_task() for localhost/debug
2019-01-07 13:05:47,556 p=68967 u=clay_fiske |   68967 1546895147.55602: Creating lock for debug
2019-01-07 13:05:47,558 p=68967 u=clay_fiske |   68967 1546895147.55803: worker is 1 (out of 1 available)
2019-01-07 13:05:47,559 p=68967 u=clay_fiske |   68967 1546895147.55955: exiting _queue_task() for localhost/debug
2019-01-07 13:05:47,560 p=68967 u=clay_fiske |   68967 1546895147.55993: done queuing things up, now waiting for results queue to drain
2019-01-07 13:05:47,560 p=68967 u=clay_fiske |   68967 1546895147.56011: waiting for pending results...
2019-01-07 13:05:47,565 p=68967 u=clay_fiske |   68991 1546895147.56511: running TaskExecutor() for localhost/TASK: test task
2019-01-07 13:05:47,567 p=68967 u=clay_fiske |   68991 1546895147.56776: in run() - task 8c8590ab-74aa-0824-9f15-00000000000a
2019-01-07 13:05:47,575 p=68967 u=clay_fiske |   68991 1546895147.57525: done running TaskExecutor() for localhost/TASK: test task [8c8590ab-74aa-0824-9f15-00000000000a]
2019-01-07 13:05:47,576 p=68967 u=clay_fiske |   68991 1546895147.57617: sending task result for task 8c8590ab-74aa-0824-9f15-00000000000a
2019-01-07 13:05:47,577 p=68967 u=clay_fiske |   68991 1546895147.57726: done sending task result for task 8c8590ab-74aa-0824-9f15-00000000000a
2019-01-07 13:05:47,578 p=68967 u=clay_fiske |   68991 1546895147.57798: WORKER PROCESS EXITING
2019-01-07 13:05:47,582 p=68967 u=clay_fiske |   68967 1546895147.58235: marking localhost as failed
2019-01-07 13:05:47,582 p=68967 u=clay_fiske |   68967 1546895147.58274: marking host localhost failed, current state: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-01-07 13:05:47,583 p=68967 u=clay_fiske |   68967 1546895147.58294: ^ failed state is now: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_TASKS, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-01-07 13:05:47,583 p=68967 u=clay_fiske |   68967 1546895147.58312: getting the next task for host localhost
2019-01-07 13:05:47,583 p=68967 u=clay_fiske |   68967 1546895147.58324: host localhost is done iterating, returning
2019-01-07 13:05:47,583 p=68967 u=clay_fiske |  fatal: [localhost]: FAILED! => {
    "msg": "Unexpected failure during module execution."
}
2019-01-07 13:05:47,584 p=68967 u=clay_fiske |   68967 1546895147.58398: no more pending results, returning what we have
cfiske commented 5 years ago

So after debugging further it turns out I had the LDAP URL and the binddn wrong. However I do consider it to be an issue that neither of these things generated an error (either that the URL was unreachable/unresolvable or that the credentials were invalid) and it just silently barfed. I will open a new issue for that.

quinot commented 5 years ago

I agree that this would deserve a more useful trace in the logs, at least. I am looking forward for the new issue. Thanks!