1

I am seeing the Ansible dnf module fail. But not reliably. When it does fail, it seems to succeed if I run Ansible again.

My system is Fedora 29 Workstation. (More version information is shown below).

I run Ansible from a script. It uses a local connection: sudo ansible-playbook -c local ...

$ ./localhost alan-laptop playbooks/alan-laptop.yml 
[sudo] password for alan-sysop:
[DEPRECATION WARNING]: The use of 'static' has been deprecated. Use 
'import_tasks' for static inclusion, or 'include_tasks' for dynamic inclusion. 
This feature will be removed in version 2.12. Deprecation warnings can be 
disabled by setting deprecation_warnings=False in ansible.cfg.

PLAY [alan-laptop] *************************************************************

TASK [Gathering Facts] *********************************************************
ok: [alan-laptop]

TASK [repos-fedora : Check OS is Fedora] ***************************************
ok: [alan-laptop] => {
    "changed": false,
    "msg": "All assertions passed"
}

TASK [repos-fedora : Configure Fedora repos using local cache] *****************
changed: [alan-laptop]

TASK [repos-fedora : Test "dnf check-update"] **********************************
changed: [alan-laptop]

TASK [sourcejedi.etckeeper : Install epel repo (needed for Centos)] ************
skipping: [alan-laptop]

TASK [sourcejedi.etckeeper : Install etckeeper] ********************************

fatal: [alan-laptop]: FAILED! => {"changed": false, "module_stderr": "<stdin>:17: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses\n", "module_stdout": "[master df9553e] saving uncommitted changes in /etc prior to dnf run\n Author: Alan Jenkins <alan.christopher.jenkins@gmail.com>\n 5 files changed, 79 insertions(+), 48 deletions(-)\n\n{\"msg\": \"Nothing to do\", \"changed\": false, \"results\": [\"Installed: etckeeper\"], \"rc\": 0, \"invocation\": {\"module_args\": {\"name\": [\"etckeeper\"], \"state\": \"present\", \"allow_downgrade\": false, \"autoremove\": false, \"bugfix\": false, \"disable_gpg_check\": false, \"disable_plugin\": [], \"disablerepo\": [], \"download_only\": false, \"enable_plugin\": [], \"enablerepo\": [], \"exclude\": [], \"installroot\": \"/\", \"install_repoquery\": true, \"security\": false, \"skip_broken\": false, \"update_cache\": false, \"update_only\": false, \"validate_certs\": true, \"conf_file\": null, \"disable_excludes\": null, \"list\": null, \"releasever\": null}}}\n", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 0}

[...]

I feel the "changed" tasks could be significant - these install (and verify) my dnf repo files. I.e. when I run Ansible again, those tasks are naturally not "changed". I tried clearing the repo files, to force the tasks to "changed". The first time, this seemed to reproduce the failure of the dnf module. But I have tried it several times now, and it does not always reproduce the failure.

  1. The message "MODULE FAILURE\nSee stdout/stderr for the exact error" is saying that there should be a real error message somewhere, but I don't know what it is! Is there a bug in the Ansible dnf module, that means it is not reporting the real error? Surely the deprecation warning is not the real error - surely that happens regardless, but is only being shown when there is a real error?

  2. Why is it failing?

    Is it relevant that module_stdout looks like it is supposed to be valid JSON, but it has been mixed up with Git messages from etckeeper? I don't think this is it what causes it though, because sometimes the dnf module does not fail, even if there were uncommitted changes e.g. as shown by sudo etckeeper vcs diff.

    I also thought it might be a conflict with PackageKit, but...

    I checked and pkcon refresh force does not seem to conflict with any of sudo dnf check-update --refresh, sudo dnf install etckeeper, sudo ansible localhost -m dnf -a "name=etckeeper state=present", or my full Ansible playbook. The two even appear to run in parallel.

    Also, I can still see this failure after systemctl mask --now --runtime packagekit.service. (I double-checked, and the service was not running when the error happened).


$ ansible --version
ansible 2.7.9
  config file = /home/alan-sysop/ansible/ansible.cfg
  configured module search path = ['/home/alan-sysop/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python3.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 3.7.2 (default, Mar 21 2019, 10:09:12) [GCC 8.3.1 20190223 (Red Hat 8.3.1-2)]
$ rpm -q ansible
ansible-2.7.9-1.fc29.noarch
1

Q. Is it relevant that module_stdout looks like it is supposed to be valid JSON, but it has been mixed up with Git messages from etckeeper?

A. Yes, it is.

Ansible modules [...] return information to ansible by printing a JSON string to stdout before exiting.

The problem is specifically due to the message from etckeeper which starts with an opening square bracket.

[master df9553e] saving uncommitted changes in /etc prior to dnf run
 Author: Alan Jenkins <alan.christopher.jenkins@gmail.com>
 5 files changed, 79 insertions(+), 48 deletions(-)

Ansible is designed to hack around similar problems by silently skipping non-json header lines. But the [ is a valid character to start a JSON document. See lib/ansible/module_utils/json_utils.py:

def _filter_non_json_lines(data):
    '''
    Used to filter unrelated output around module JSON output, like messages from
    tcagetattr, or where dropbear spews MOTD on every single command (which is nuts).

    Filters leading lines before first line-starting occurrence of '{' or '[', and filter all
    trailing lines after matching close character (working from the bottom of output).
    '''

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.