search

geerlingguy / ansible-role-ntp

Ansible Role - NTP
https://galaxy.ansible.com/geerlingguy/ntp/
MIT License
318 stars 241 forks source link

Issues with Malformed output discovered from systemd #99

Closed jeliasson closed 3 years ago

jeliasson commented 3 years ago

Hi @geerlingguy,

First off, thanks for some amazing roles.

I'm having issues running this role on Ubuntu 20.04 hosts with Malformed output discovered from systemd list-unit-files: accounts-daemon.service enabled enabled being the error.

Not sure what that would be, but the time and timezone seems to be correct anyway 😀. Thoughts?

Thanks!

PLAY [linux.ubuntu] ****************************************************************************************************

TASK [Gathering Facts] *************************************************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]

TASK [geerlingguy.ntp : Include OS-specific variables.] ****************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Include OS-Release specific variables on RHEL 6.] **********************************************
skipping: [ansible-master.corp.nasa.gov]
skipping: [worker1.corp.nasa.gov]
skipping: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Set the ntp_driftfile variable.] ***************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Set the ntp_package variable.] *****************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Set the ntp_config_file variable.] *************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Set the ntp_daemon variable.] ******************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Ensure NTP package is installed.] **************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]

TASK [geerlingguy.ntp : Ensure tzdata package is installed (Linux).] ***************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : include_tasks] *********************************************************************************
skipping: [ansible-master.corp.nasa.gov]
skipping: [worker1.corp.nasa.gov]
skipping: [worker2.corp.nasa.gov]

TASK [geerlingguy.ntp : Set timezone.] *********************************************************************************
ok: [ansible-master.corp.nasa.gov]
ok: [worker2.corp.nasa.gov]
ok: [worker1.corp.nasa.gov]

TASK [geerlingguy.ntp : Populate service facts.] ***********************************************************************
fatal: [ansible-master.corp.nasa.gov]: FAILED! => {"changed": false, "msg": "Malformed output discovered from systemd list-unit-files: accounts-daemon.service                enabled         enabled      "}
fatal: [worker2.corp.nasa.gov]: FAILED! => {"changed": false, "msg": "Malformed output discovered from systemd list-unit-files: accounts-daemon.service                enabled         enabled      "}
fatal: [worker1.corp.nasa.gov]: FAILED! => {"changed": false, "msg": "Malformed output discovered from systemd list-unit-files: accounts-daemon.service                enabled         enabled      "}

PLAY RECAP *************************************************************************************************************
ansible-master.corp.nasa.gov        : ok=13   changed=1    unreachable=0    failed=1    skipped=3    rescued=0    ignored=0
worker1.corp.nasa.gov        : ok=13   changed=1    unreachable=0    failed=1    skipped=3    rescued=0    ignored=0
worker2.corp.nasa.gov          : ok=13   changed=1    unreachable=0    failed=1    skipped=3    rescued=0    ignored=0
geerlingguy commented 3 years ago

That's... interesting. I found this issue (https://github.com/ansible/ansible/issues/68536), which seems to have been fixed at some point last year. Are you running the latest version of Ansible 2.9 or 3.x?

jeliasson commented 3 years ago

[...[ Are you running the latest version of Ansible 2.9 or 3.x?

I seem to be on 2.9.3

user@ansible:~/ansible$ ansible --version
ansible 2.9.6
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/home/user/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3/dist-packages/ansible
  executable location = /usr/bin/ansible
  python version = 3.8.5 (default, Jan 27 2021, 15:41:15) [GCC 9.3.0]
user@ansible:~/ansible$ python3 --version
Python 3.8.5
sfuerte commented 3 years ago

Same here, running with ANSIBLE_DEBUG doesn't produce any meaningful details:

Friday 23 April 2021  19:34:48 +0000 (0:00:00.408)       0:00:12.645 **********
  4853 1619206488.50478: sending task start callback
  4853 1619206488.50483: entering _queue_task() for localhost/service_facts
  4853 1619206488.50486: Creating lock for service_facts
  4853 1619206488.50727: worker is 1 (out of 1 available)
  4853 1619206488.50769: exiting _queue_task() for localhost/service_facts
  4853 1619206488.50850: done queuing things up, now waiting for results queue to drain
  4853 1619206488.50855: waiting for pending results...
  5296 1619206488.51132: running TaskExecutor() for localhost/TASK: geerlingguy.ntp : Populate service facts.
  5296 1619206488.51235: in run() - task 2f8e8a20-319c-0ac8-de89-000000000257
  5296 1619206488.51334: calling self._execute()
  5296 1619206488.51548: Loading FilterModule 'core' from /usr/lib/python3/dist-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
  5296 1619206488.51559: Loading FilterModule 'gcp_kms_filters' from /usr/lib/python3/dist-packages/ansible/plugins/filter/gcp_kms_filters.py (found_in_cache=True, class_only=False)
  5296 1619206488.51565: Loading FilterModule 'ipaddr' from /usr/lib/python3/dist-packages/ansible/plugins/filter/ipaddr.py (found_in_cache=True, class_only=False)
  5296 1619206488.51574: Loading FilterModule 'json_query' from /usr/lib/python3/dist-packages/ansible/plugins/filter/json_query.py (found_in_cache=True, class_only=False)
  5296 1619206488.51587: Loading FilterModule 'k8s' from /usr/lib/python3/dist-packages/ansible/plugins/filter/k8s.py (found_in_cache=True, class_only=False)
  5296 1619206488.51605: Loading FilterModule 'mathstuff' from /usr/lib/python3/dist-packages/ansible/plugins/filter/mathstuff.py (found_in_cache=True, class_only=False)
  5296 1619206488.51617: Loading FilterModule 'network' from /usr/lib/python3/dist-packages/ansible/plugins/filter/network.py (found_in_cache=True, class_only=False)
  5296 1619206488.51657: Loading FilterModule 'urls' from /usr/lib/python3/dist-packages/ansible/plugins/filter/urls.py (found_in_cache=True, class_only=False)
  5296 1619206488.51672: Loading FilterModule 'urlsplit' from /usr/lib/python3/dist-packages/ansible/plugins/filter/urlsplit.py (found_in_cache=True, class_only=False)
  5296 1619206488.51729: Loading TestModule 'core' from /usr/lib/python3/dist-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
  5296 1619206488.51740: Loading TestModule 'files' from /usr/lib/python3/dist-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
  5296 1619206488.51745: Loading TestModule 'mathstuff' from /usr/lib/python3/dist-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
  5296 1619206488.52155: Loaded config def from plugin (lookup/env)
  5296 1619206488.52163: Loading LookupModule 'env' from /usr/lib/python3/dist-packages/ansible/plugins/lookup/env.py
  5296 1619206488.52562: trying /usr/lib/python3/dist-packages/ansible/plugins/connection
  5296 1619206488.52645: Loading Connection 'local' from /usr/lib/python3/dist-packages/ansible/plugins/connection/local.py (found_in_cache=True, class_only=False)
  5296 1619206488.52676: trying /usr/lib/python3/dist-packages/ansible/plugins/shell
  5296 1619206488.52692: Loading ShellModule 'sh' from /usr/lib/python3/dist-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
  5296 1619206488.52722: Loading ShellModule 'sh' from /usr/lib/python3/dist-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
  5296 1619206488.52743: trying /usr/lib/python3/dist-packages/ansible/plugins/become
  5296 1619206488.52786: Loading BecomeModule 'sudo' from /usr/lib/python3/dist-packages/ansible/plugins/become/sudo.py (found_in_cache=True, class_only=False)
  5296 1619206488.52958: Loading ActionModule 'normal' from /usr/lib/python3/dist-packages/ansible/plugins/action/normal.py (searched paths: /usr/lib/python3/dist-packages/ansible/plugins/action/__pycache__:/usr/lib/python3/dist-packages/ansible/plugins/action)
  5296 1619206488.52973: starting attempt loop
  5296 1619206488.52983: running the handler
  5296 1619206488.53091: ANSIBALLZ: Using lock for service_facts
  5296 1619206488.53095: ANSIBALLZ: Acquiring lock
  5296 1619206488.53099: ANSIBALLZ: Lock acquired: 124622757409792
  5296 1619206488.53102: ANSIBALLZ: Creating module
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/basic.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/_collections_compat.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/six/__init__.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/parameters.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/parsing/__init__.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/_utils.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/_json_compat.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/__init__.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/process.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/pycompat24.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/text/converters.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/sys_info.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/parsing/convert_bool.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/validation.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/text/__init__.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/text/formatters.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/_text.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/file.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/common/collections.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/distro/__init__.py
Using module_utils file /usr/lib/python3/dist-packages/ansible/module_utils/distro/_distro.py
  5296 1619206488.62994: ANSIBALLZ: Writing module into payload
  5296 1619206488.63104: ANSIBALLZ: Writing module
  5296 1619206488.63123: ANSIBALLZ: Renaming module
  5296 1619206488.63131: ANSIBALLZ: Done creating module
Using module file /usr/lib/python3/dist-packages/ansible/modules/system/service_facts.py
Pipelining is enabled.
  5296 1619206488.63196: _low_level_execute_command(): starting
  5296 1619206488.63204: _low_level_execute_command(): using become for this command
  5296 1619206488.63218: _low_level_execute_command(): executing: /bin/sh -c 'sudo -H -S -n  -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-keultovunyapwinvvfdutbymduvpqdpp ; /usr/bin/python3'"'"' && sleep 0'
<localhost> ESTABLISH LOCAL CONNECTION FOR USER: <user>
  5296 1619206488.63237: in local.exec_command()
<localhost> EXEC /bin/sh -c 'sudo -H -S -n  -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-keultovunyapwinvvfdutbymduvpqdpp ; /usr/bin/python3'"'"' && sleep 0'
  5296 1619206488.63272: opening command with Popen()
  5296 1619206488.63632: done running command with Popen()
  5296 1619206488.63651: getting output with communicate()
  5296 1619206489.99717: done communicating
  5296 1619206489.99723: done with local.exec_command()
  5296 1619206489.99779: _low_level_execute_command() done: rc=1, stdout=
{"msg": "Malformed output discovered from systemd list-unit-files: accounts-daemon.service                enabled         enabled      ", "failed": true, "exception": "  File \"/tmp/ansible_service_facts_payload_q4_a6_zd/ansible_service_facts_payload.zip/ansible/modules/system/service_facts.py\", line 216, in gather_services\n", "invocation": {"module_args": {}}}
, stderr=
  5296 1619206489.99864: done with _execute_module (service_facts, {'_ansible_check_mode': False, '_ansible_no_log': False, '_ansible_debug': True, '_ansible_diff': False, '_ansible_verbosity': 5, '_ansible_version': '2.9.6', '_ansible_module_name': 'service_facts', '_ansible_syslog_facility': 'LOG_USER', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p', 'vfat'], '_ansible_string_conversion_action': 'warn', '_ansible_socket': None, '_ansible_shell_executable': '/bin/sh', '_ansible_keep_remote_files': False, '_ansible_tmpdir': None, '_ansible_remote_tmp': '~/.ansible/tmp'})
  5296 1619206489.99877: handler run complete
  5296 1619206489.99883: attempt loop complete, returning result
  5296 1619206489.99912: _execute() done
  5296 1619206489.99916: dumping result to json
  5296 1619206489.99918: done dumping result, returning
  5296 1619206489.99941: done running TaskExecutor() for localhost/TASK: geerlingguy.ntp : Populate service facts. [2f8e8a20-319c-0ac8-de89-000000000257]
  5296 1619206489.99961: sending task result for task 2f8e8a20-319c-0ac8-de89-000000000257
  5296 1619206490.00044: done sending task result for task 2f8e8a20-319c-0ac8-de89-000000000257
  5296 1619206490.00095: WORKER PROCESS EXITING
  4853 1619206490.00220: marking localhost as failed
  4853 1619206490.00233: marking host localhost failed, current state: HOST STATE: block=2, task=6, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=9, 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), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
  4853 1619206490.00239: ^ failed state is now: HOST STATE: block=2, task=6, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (HOST STATE: block=0, task=9, 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), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
  4853 1619206490.00242: getting the next task for host localhost
  4853 1619206490.00246: done getting next task for host localhost
  4853 1619206490.00247:  ^ task is: None
  4853 1619206490.00249:  ^ state is: HOST STATE: block=2, task=6, 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

TASK [geerlingguy.ntp : Populate service facts.] *****************************************************************************************************************************************************************
task path: /<home dir>/.ansible/roles/geerlingguy.ntp/tasks/main.yml:41
The full traceback is:
  File "/tmp/ansible_service_facts_payload_q4_a6_zd/ansible_service_facts_payload.zip/ansible/modules/system/service_facts.py", line 216, in gather_services
fatal: [localhost]: FAILED! => {
    "changed": false,
    "invocation": {
        "module_args": {}
    },
    "msg": "Malformed output discovered from systemd list-unit-files: accounts-daemon.service                enabled         enabled      "
}
  4853 1619206490.00300: no more pending results, returning what we have
  4853 1619206490.00309: results queue empty
  4853 1619206490.00314: checking for any_errors_fatal
  4853 1619206490.00321: done checking for any_errors_fatal
  4853 1619206490.00324: checking for max_fail_percentage
  4853 1619206490.00326: done checking for max_fail_percentage
  4853 1619206490.00338: checking to see if all hosts have failed and the running result is not ok
  4853 1619206490.00341: done checking to see if all hosts have failed
  4853 1619206490.00342: getting the remaining hosts for this loop
  4853 1619206490.00344: done getting the remaining hosts for this loop
  4853 1619206490.00352: building list of next tasks for hosts
  4853 1619206490.00355: getting the next task for host localhost
  4853 1619206490.00358: done getting next task for host localhost
  4853 1619206490.00359:  ^ task is: None
  4853 1619206490.00361:  ^ state is: HOST STATE: block=2, task=6, 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
  4853 1619206490.00363: done building task lists
  4853 1619206490.00366: counting tasks in each state of execution
  4853 1619206490.00369: done counting tasks in each state of execution:
    num_setups: 0
    num_tasks: 0
    num_rescue: 0
    num_always: 0
  4853 1619206490.00372: all hosts are done, so returning None's for all hosts
  4853 1619206490.00375: done queuing things up, now waiting for results queue to drain
  4853 1619206490.00379: results queue empty
  4853 1619206490.00382: checking for any_errors_fatal
  4853 1619206490.00385: done checking for any_errors_fatal
  4853 1619206490.00387: checking for max_fail_percentage
  4853 1619206490.00389: done checking for max_fail_percentage
  4853 1619206490.00390: checking to see if all hosts have failed and the running result is not ok
  4853 1619206490.00392: done checking to see if all hosts have failed
  4853 1619206490.00395: getting the next task for host localhost
  4853 1619206490.00402: done getting next task for host localhost
  4853 1619206490.00404:  ^ task is: None
  4853 1619206490.00406:  ^ state is: HOST STATE: block=2, task=6, 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
  4853 1619206490.00409: running handlers

OS & Ansible:

$ ansible --version
ansible 2.9.6
  config file = /<project folder>/ansible.cfg
  configured module search path = ['/<homedir>/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3/dist-packages/ansible
  executable location = /usr/bin/ansible
  python version = 3.8.5 (default, Jan 27 2021, 15:41:15) [GCC 9.3.0]

$ lsb_release -d
Description:    Ubuntu 20.04.2 LTS
sfuerte commented 3 years ago

@jeliasson, as Ubuntu's version of Ansible is quite ancient, manual installation via pip3 works like a charm:

$  sudo apt purge ansible && sudo apt autoremove --purge
...

# switched to Python 3.9 along the way but should be fine under 3.8 also
$ sudo ln -fs /usr/bin/python3.9 /usr/bin/python3

$ sudo pip3 install ansible
...
# you might need to add your user to `staff` group as someone decided to be creative here
$ ls -l /usr/local/lib/python3.9/dist-packages/
total 1208
drwxr-s--- 20 root staff   4096 Apr 23 19:59 ansible
drwxr-s---  2 root staff   4096 Apr 23 19:59 ansible-3.3.0.dist-info
drwxr-s---  2 root staff   4096 Apr 23 19:59 ansible_base-2.10.8.dist-info
drwxr-s--- 43 root staff   4096 Apr 23 19:59 ansible_collections
drwxr-s---  6 root staff   4096 Apr 23 19:59 ansible_test
...

$ ansible --version
ansible 2.10.8
  config file = /<project dir>/ansible.cfg
  configured module search path = ['/<homedir>/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.9/dist-packages/ansible
  executable location = /usr/local/bin/ansible
  python version = 3.9.0+ (default, Oct 20 2020, 08:43:38) [GCC 9.3.0]

$ ansible -m service_facts localhost
[WARNING]: No inventory was parsed, only implicit localhost is available
localhost | SUCCESS => {
    "ansible_facts": {
        "services": {
            "*": {
                "name": "*",
                "source": "systemd",
                "state": "stopped",
                "status": "unknown"
            },
# ----- output truncated -------

UPDATE: it's actually better to stick with system default Python 3.8, otherwise the following error requires some manual overrides:

ModuleNotFoundError: No module named 'apt_pkg'
jeliasson commented 3 years ago

@sfuerte

as Ubuntu's version of Ansible is quite ancient, manual installation via pip3 works like a charm:

I did not realize 2.9.3 was that old to be honest. Might bring in a more recent one, but would prefer it from aptitude.

it's actually better to stick with system default Python 3.8, otherwise the following error requires some manual overrides:

Just to confirm, is this a non issue in version 2.10.8 using Python 3.8?

Thanks!

sfuerte commented 3 years ago

Just to confirm, is this a non issue in version 2.10.8 using Python 3.8?

that's correct.