Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

dnf: successful etckeeper commit causes successful package install to fail #54949

Open
westurner opened this issue Apr 6, 2019 · 21 comments · May be fixed by #58408
Open

dnf: successful etckeeper commit causes successful package install to fail #54949

westurner opened this issue Apr 6, 2019 · 21 comments · May be fixed by #58408
Assignees
Labels
affects_2.7 This issue/PR affects Ansible v2.7 bug This issue/PR relates to a bug. has_pr This issue has an associated PR. module This issue/PR relates to a module. P3 Priority 3 - Approved, No Time Limitation packaging Packaging category python3 support:core This issue/PR relates to code supported by the Ansible Engineering Team. verified This issue has been verified/reproduced by maintainer

Comments

@westurner
Copy link

westurner commented Apr 6, 2019

SUMMARY

When etckeeper commits, dnf package installs (that are successfully installed) fail.
It may be due to the etckeeper output preceding dnf output?

Workarounds:

  1. in /etc/etckeeper/etckeeper.conf, set GIT_OPTIONS="-q"
    • This is suboptimal, because I generally want to see the git output when running etckeeper commit (and in the ansible logs, TBH)
ISSUE TYPE
  • Bug Report
COMPONENT NAME

dnf module

ANSIBLE VERSION
ansible 2.7.9
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['~/.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)]

CONFIGURATION
.
OS / ENVIRONMENT
  • Fedora 29
  • dnf: 4.2.2
  • etckeeper: 1.18.8
STEPS TO REPRODUCE
  • Install etckeeper: package: name=etckeeper
  • Modify a file in /etc: echo "TestTest" | sudo tee /etc/README.md
  • Install a package: package: name=ctags-etags
  • Error:
- package: name=etckeeper
- command: etckeeper init
- command: etckeeper commit "Initial etckeeper commit by ansible"
echo "TestTest" | sudo tee /etc/README.md
- package: name=ctags-etags
EXPECTED RESULTS
  • package: name=ctags-etags installs successfully
ACTUAL RESULTS
  • package: name=ctags-etags does not install
fatal: [node1]: FAILED! => {"changed": false,

 "module_stderr":
 "~/.ansible/tmp/ansible-tmp-1554590827.5738285-108733131594711/AnsiballZ_dnf.py:17:
 DeprecationWarning: the imp module is deprecated in favour of
 importlib; see the module's documentation for alternative uses\n
 import imp\n",

 "module_stdout": "[master 2151996] saving uncommitted changes in /etc
 prior to dnf run\n Author: Wes Turner <~>\n 1 file changed, 1
 insertion(+)\n\n{\"msg\": \"Nothing to do\", \"changed\": false,
 \"results\": [\"Installed: libX11-xcb\", \"Installed: which\"], \"rc\":
 0, \"invocation\": {\"module_args\": {\"name\": [\"libX11-xcb\",
 \"which\"], \"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}

@westurner
Copy link
Author

westurner commented Apr 6, 2019

Here's all this, which isnt really necessary:

---
# playbook.yml
- hosts: all
  name: Install etckeeper
  tags: ['etckeeper']
  become: true
  roles:
  - role: etckeeper
    tags: ['etckeeper']
---
# etckeeper/tasks/main.yml
# tasks file for etckeeper

- name: Load etckeeper-pre-task and etckeeper-post-task action_plugins
  import_role:
    name: hlovdal.etckeeper_actions
  tags: ['etckeeper']

- name: Install etckeeper
  tags: [etckeeper]
  become: true
  block:

  - name: Check for /etc/.git and etckeeper
    shell: test -d "/etc/.git" && test -e /usr/bin/etckeeper
    ignore_errors: true
    failed_when: etckeeper.rc > 1
    changed_when: etckeeper.rc > 1
    register: etckeeper

  - etckeeper-pre-task:
    when:
    - etckeeper.rc == 0

  - name: Install etckeeper package
    package:
      name: etckeeper

  # See: https://github.com/ansible/ansible/issues/54949
  - name: Configure etckeeper.conf
    lineinfile:
      path: /etc/etckeeper/etckeeper.conf
      regexp: '^GIT_COMMIT_OPTIONS=.*'
      line: 'GIT_COMMIT_OPTIONS="-q"'

  - name: Run etckeeper init
    command: etckeeper init
    args:
      creates: "/etc/.git"
    register: etckinit

  - name: Check git user
    command: git config --local --get user.name
    args:
      chdir: /etc
    failed_when: gituser.rc > 1
    changed_when: gituser.rc > 1
    register: gituser

  - name: Check git email
    command: git config --local --get user.email
    args:
      chdir: /etc
    failed_when: gitemail.rc > 1
    changed_when: gitemail.rc > 1
    register: gitemail

  - name: Set git user if not set
    command: git config --add user.name Root
    args:
      chdir: /etc
    when: gituser.rc != 0

  - name: Set git email if not set
    command: git config --add user.email root@localhost
    args:
      chdir: /etc
    when: gitemail.rc != 0

  #- name: Check whether there are uncommited etckeeper entries
  #  command: etckeeper unclean
  #  failed_when: etck.rc > 1
  #  changed_when: etck.rc == 0
  #  register: etck

  - name: Create initial etckeeper commit
    command: etckeeper commit "Initial commit by ansible"
    when: etckinit.changed == true

  #- name: Commit uncommited changes in /etc with etckeeper
  #  command: etckeeper commit "Commit uncommitted by ansible"
  #  when:
  #  - etck.rc == 0
  #  - etckinit.changed == false

  - etckeeper-post-task:

@ansibot
Copy link
Contributor

ansibot commented Apr 6, 2019

@ansibot ansibot added affects_2.7 This issue/PR affects Ansible v2.7 bug This issue/PR relates to a bug. module This issue/PR relates to a module. needs_triage Needs a first human triage before being processed. packaging Packaging category python3 support:core This issue/PR relates to code supported by the Ansible Engineering Team. labels Apr 6, 2019
@bcoca bcoca added needs_verified This issue needs to be verified/reproduced by maintainer P3 Priority 3 - Approved, No Time Limitation and removed needs_triage Needs a first human triage before being processed. labels Apr 9, 2019
@mkrizek
Copy link
Contributor

mkrizek commented Apr 11, 2019

This appears to be related to how Ansible parses module's result as identified here:
https://unix.stackexchange.com/questions/511210/ansible-dnf-module-module-failure

@webknjaz
Copy link
Member

webknjaz commented Jun 3, 2019

I think the reproducer should use dnf module directly to narrow down the call which produces that stdout output: https://github.com/ansible/ansible/blob/7b40b56/lib/ansible/modules/packaging/os/dnf.py#L1148

We may need to temporary patch stdout to catch that...

@webknjaz webknjaz added verified This issue has been verified/reproduced by maintainer and removed needs_verified This issue needs to be verified/reproduced by maintainer labels Jun 5, 2019
@webknjaz
Copy link
Member

webknjaz commented Jun 5, 2019

Clean Docker-based reproducers (at the time of writing installs Ansible 2.8.0-2 in all cases), crashes in all cases:

  1. package:

    $ docker run -it --rm --name fedora-29 fedora:29 bash -c 'yum install -y ansible && ansible localhost -m package -a name=etckeeper && etckeeper init etckeeper commit "Initial etckeeper commit by ansible" && echo TestTest > /etc/README.md && ansible localhost -m package -a name=ctags-etags'
  2. pure dnf:

    $ docker run -it --rm --name fedora-29 fedora:29 bash -c 'yum install -y ansible && ansible localhost -m dnf -a name=etckeeper && etckeeper init etckeeper commit "Initial etckeeper commit by ansible" && echo TestTest > /etc/README.md && ansible localhost -m dnf -a name=ctags-etags'
  3. Fedora 30:

    $ docker run -it --rm --name fedora-30 fedora:30 bash -c 'yum install -y ansible && ansible localhost -m dnf -a name=etckeeper && etckeeper init etckeeper commit "Initial etckeeper commit by ansible" && echo TestTest > /etc/README.md && ansible localhost -m dnf -a name=ctags-etags'

@webknjaz webknjaz self-assigned this Jun 5, 2019
@webknjaz
Copy link
Member

webknjaz commented Jun 6, 2019

So the root of the issue is that etckeeper-dnf has a call os.system('etc-keeper pre-install') which isn't caught by Python. So its output (e.g. [master 0213769] saving uncommitted changes in /etc prior to dnf run 1 file changed, 1 insertion(+), 1 deletion(-)) bypasses the code in dnf module and goes straight to the calling ansible process on the controller.

Ref: https://git.joeyh.name/index.cgi/etckeeper.git/tree/etckeeper-dnf/etckeeper.py?id=b357f48e78decd93cc66a35d75f92d9c959c6da4#n26

class Etckeeper(dnf.Plugin):
    ...

    def resolved(self):
        ...
Oops -->command = '%s %s' % ('etckeeper', " pre-install")
        ret = os.system(command)  <-- Oops!
        ...

    def transaction(self):
        ...
Oops -->command = '%s %s > /dev/null' % ('etckeeper', "post-install")
        os.system(command)  <-- Oops!

webknjaz referenced this issue in sourcejedi/etckeeper Jun 6, 2019
The Ansible dnf module uses the python dnf bindings.  In contexts like
these, stdout/stderr is owned by the host app (Ansible).  dnf should not
mess with stdout/stderr, unless the host app asks it to log there.

Specifically, it was breaking the JSON output of the Ansible module.
This was only noticeable when the etckeeper message began with a "["
character.  Ansible has a mechanism to try and skip header messages like
login banners.  However, "[" is a valid character to start a JSON document.

https://unix.stackexchange.com/questions/511210/ansible-dnf-module-module-failure/

This requires decoding the etckeeper messages into unicode.  For gory
details, see the code comment.

Also enable unicode string literals.  This reduces differences between py2
and py3 semantics; it is universal inside the dnf code.

Also when I tested the failure case, I noticed the exit code was not
printed correctly.  Fix it.
@webknjaz
Copy link
Member

webknjaz commented Jun 6, 2019

So I've found out that @sourcejedi posted a patch @ sourcejedi/etckeeper@afbdce2 but it's not clear when it gets accepted by the upstream.

@webknjaz
Copy link
Member

webknjaz commented Jun 6, 2019

Call stack FTR:

  File "/root/.ansible/tmp/ansible-tmp-1559833967.9878116-163794092439180/AnsiballZ_dnf.py", line 114, in <module>
    _ansiballz_main()
  File "/root/.ansible/tmp/ansible-tmp-1559833967.9878116-163794092439180/AnsiballZ_dnf.py", line 106, in _ansiballz_main
    invoke_module(zipped_mod, temp_path, ANSIBALLZ_PARAMS)
  File "/root/.ansible/tmp/ansible-tmp-1559833967.9878116-163794092439180/AnsiballZ_dnf.py", line 49, in invoke_module
    imp.load_module('__main__', mod, module, MOD_DESC)
  File "/usr/lib64/python3.7/imp.py", line 234, in load_module
    return load_source(name, filename, file)
  File "/usr/lib64/python3.7/imp.py", line 169, in load_source
    module = _exec(spec, sys.modules[name])
  File "<frozen importlib._bootstrap>", line 630, in _exec
  File "<frozen importlib._bootstrap_external>", line 728, in exec_module
  File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  File "/tmp/ansible_dnf_payload_r65mifyv/__main__.py", line 1303, in <module>
    main()
  File "/tmp/ansible_dnf_payload_r65mifyv/__main__.py", line 1287, in main
    module_implementation.run()
  File "/tmp/ansible_dnf_payload_r65mifyv/__main__.py", line 1265, in run
    self.ensure()
  File "/tmp/ansible_dnf_payload_r65mifyv/__main__.py", line 1144, in ensure
    if not self.base.resolve(allow_erasing=allow_erasing):
  File "/usr/lib/python3.7/site-packages/dnf/base.py", line 785, in resolve
    self._plugins.run_resolved()
  File "/usr/lib/python3.7/site-packages/dnf/plugin.py", line 156, in run_resolved
    self._caller('resolved')
  File "/usr/lib/python3.7/site-packages/dnf/plugin.py", line 104, in _caller
    getattr(plugin, method)()
  File "/usr/lib/python3.7/site-packages/dnf-plugins/etckeeper.py", line 40, in resolved
    set_trace()

@nitzmahone
Copy link
Member

Hrm, the module junk filter would normally take care of this, but because it has support for JSON arrays in addition to dicts (though not sure why, module results should always be a dict IIRC), that first line that starts with [ is slipping past it. I suspect that if the array case in https://github.com/ansible/ansible/blob/devel/lib/ansible/module_utils/json_utils.py#L50-L52 were removed, this would magically start working...

@abadger
Copy link
Contributor

abadger commented Jun 7, 2019

Have to be careful because update_json will need to deliver a stream of dicts. A list is once way to represent that. But @sivel discovered an RFC which used a specific single unicode character. to represent a stream of json. If we used that, we might be able to remove list checking from the junk filter (but might have to add handling for the separator instead).

@webknjaz
Copy link
Member

webknjaz commented Jun 7, 2019

@abadger there's also JSON-L which is basically LF delimited lines with JSON objects...

@webknjaz
Copy link
Member

webknjaz commented Jun 7, 2019

I'm curious whether we could put some magic byte (sequence) in front of the emitted JSON result to make it explicit where it starts...

@sivel
Copy link
Member

sivel commented Jun 7, 2019

Here is what I had previously linked to: https://en.wikipedia.org/wiki/JSON_streaming#Record_separator-delimited_JSON

Which is formally described by https://tools.ietf.org/html/rfc7464

@webknjaz
Copy link
Member

webknjaz commented Jun 7, 2019

@sivel It's similar to what I had in mind: RS could be a protocol version..

@westurner
Copy link
Author

westurner commented Jun 7, 2019 via email

@westurner
Copy link
Author

westurner commented Jun 7, 2019 via email

@webknjaz
Copy link
Member

webknjaz commented Jun 7, 2019

I think that'd be not good from a design perspective.

@sivel
Copy link
Member

sivel commented Jun 7, 2019

Is it written somewhere in the docs that output should not start with a JSON control character if it's not JSON? { [

Modules communicate their results back as JSON responses. If something else outputs data, regardless of it being JSON can cause parsing issues. Due to misconfigurations of bash profiles and other configurations, we try to strip out non JSON lines, but in the case of etckeeper it is printing out lines that look like JSON, so we don't strip those lines, which then breaks our ability to parse the module responses.

So in general, nothing other than the module JSON response should be printed to stdout during a module execution. We just do a best effort, to make our JSON consumption more robust.

@webknjaz
Copy link
Member

webknjaz commented Jun 26, 2019

I assume @abadger meant #13620 when talking about update_json.

I've implemented RFC 7464 stream reader (PoC: #58408) and it seems like we even should be able to throw away _filter_non_json_lines for good…

@sourcejedi
Copy link

sourcejedi commented Jun 26, 2019

it seems like we even should be able to throw away _filter_non_json_lines for good...

IDGI. Isn't _filter_non_json_lines on the receive side? Doesn't Ansible let you write modules in any language, without a specific library? So for "old" modules, you will still need a way to filter out login banners from SSH / whatever / "misconfigurations of bash profiles and other configurations"?

EDIT: if the "old" module doesn't use the python Ansible library code.

@webknjaz
Copy link
Member

Right. For backward compat, yes.

@ansibot ansibot added the has_pr This issue has an associated PR. label Jul 28, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
affects_2.7 This issue/PR affects Ansible v2.7 bug This issue/PR relates to a bug. has_pr This issue has an associated PR. module This issue/PR relates to a module. P3 Priority 3 - Approved, No Time Limitation packaging Packaging category python3 support:core This issue/PR relates to code supported by the Ansible Engineering Team. verified This issue has been verified/reproduced by maintainer
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants