Lock file not cleaned up when used with 'unbuffer'

[SoftwareMarc]

Summary

Note:
This issue was originally filed as ansible/ansible#84429 but was closed there due to the argument that I should create an issue in this repository.

When ansible-playbook is executed together with unbuffer (see https://linux.die.net/man/1/unbuffer ), The lock file in /tmp/ of viczem.keepass.keepass is not cleaned up after execution of ansible-playbook finishes.

My whole setup:
Ansible is used in a docker container. I use docker version 20.10.3, build 48d30b5. The Dockerfile looks like this:

FROM ubuntu:20.04

ARG MA_ANSIBLE_PASSWORD
ENV DEBIAN_FRONTEND=noninteractive

RUN apt-get update && \
    apt-get install -y expect-dev \
                       gcc \
                       git-all \
                       libkrb5-dev \
                       krb5-user \
                       openssh-server \
                       python3 \
                       python3-dev \
                       python3-pip \
                       unzip \
                       vim \
                       && \
    apt-get clean all && \
    rm -rf /var/lib/apt/lists/*


RUN pip3 install --upgrade pip && \
    pip3 install --upgrade virtualenv && \
    pip3 install pywinrm[kerberos] && \
    pip3 install pywinrm && \
    pip3 install "pykeepass==4.0.3" && \
    pip3 install ansible && \
    pip3 install ansible-lint

RUN useradd -m -s /bin/bash ansible && usermod -aG sudo ansible
RUN echo "ansible:$MA_ANSIBLE_PASSWORD" | chpasswd

EXPOSE 22

COPY ./config/krb5.conf /etc/
COPY ./config/initialize.sh /root/
COPY ./galaxy /galaxy

RUN chmod +x /root/initialize.sh

CMD /root/initialize.sh && sleep infinity

The image is built on one host, then pushed into a private registry and pulled from another host and also started (and running) there. Inside the container I have a bash script doing the following:

#!/bin/bash
...
    unbuffer ansible-playbook -i inventories/10_Site_Common.yml \
                     -i inventories/20a_Site_WRN_Test.yml \
                     -i inventories/20a_Site_WRN_ProdTest.yml \
                     -i inventories/20a_Site_WRN_ProdTest_291.yml \
                     -i inventories/20a_Site_WRN_ProdTest_292.yml \
                     -i inventories/20z_Development.yml \
                     --limit $LIMIT \
                     $PLAYBOOK \
                     --check -vvvvv \
                     | tee >(sed -r 's/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]//g' > $LOGFILENAME)
...

When I enter the freshly started container by ssh-ing into it through the exposed ssh port (which is redirected to port 2222) and executing the above bash-script through the following command:

./deploy.sh --limit somemachine.EXAMPLE.COM --playbook playbooks/notepadplusplus.yml

... I get my expected behavior. This means that the playbook does what it is supposed to to: It fetches passwords from the keepass file (*.kdbx), gathers facts through authenticating as the correct user through credentials obtained from keepass, performs tasks successfully and exits.

BUT: Any subsequent execution of my script fails nearly instant at the beginning with the following error:

ansible-playbook [core 2.13.13]
  config file = /opt/ansible/ansible.cfg
  configured module search path = ['/home/ansible/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.8/dist-packages/ansible
  ansible collection location = /home/ansible/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/local/bin/ansible-playbook
  python version = 3.8.10 (default, Nov  7 2024, 13:10:47) [GCC 9.4.0]
  jinja version = 3.1.4
  libyaml = True
Using /opt/ansible/ansible.cfg as config file
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/10_Site_Common.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/10_Site_Common.yml as it did not pass its verify_file() method
Skipping empty key (hosts) in group (somegroup_1)
Parsed /opt/ansible/inventories/10_Site_Common.yml inventory source with yaml plugin
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/20a_Site_WRN_Test.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/20a_Site_WRN_Test.yml as it did not pass its verify_file() method
Skipping empty key (hosts) in group (somegroup_2)
Parsed /opt/ansible/inventories/20a_Site_WRN_Test.yml inventory source with yaml plugin
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest.yml as it did not pass its verify_file() method
Parsed /opt/ansible/inventories/20a_Site_WRN_ProdTest.yml inventory source with yaml plugin
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest_291.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest_291.yml as it did not pass its verify_file() method
Parsed /opt/ansible/inventories/20a_Site_WRN_ProdTest_291.yml inventory source with yaml plugin
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest_292.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/20a_Site_WRN_ProdTest_292.yml as it did not pass its verify_file() method
Parsed /opt/ansible/inventories/20a_Site_WRN_ProdTest_292.yml inventory source with yaml plugin
setting up inventory plugins
host_list declined parsing /opt/ansible/inventories/20z_Development.yml as it did not pass its verify_file() method
script declined parsing /opt/ansible/inventories/20z_Development.yml as it did not pass its verify_file() method
Skipping empty key (hosts) in group (somegroup_3)
Parsed /opt/ansible/inventories/20z_Development.yml inventory source with yaml plugin
Loading collection chocolatey.chocolatey from /usr/local/lib/python3.8/dist-packages/ansible_collections/chocolatey/chocolatey
Loading callback plugin default of type stdout, v2.0 from /usr/local/lib/python3.8/dist-packages/ansible/plugins/callback/default.py
Loading collection ansible.posix from /usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/posix
Attempting to use 'default' callback.
Skipping callback 'default', as we already have a stdout callback.
Attempting to use 'junit' callback.
Attempting to use 'minimal' callback.
Skipping callback 'minimal', as we already have a stdout callback.
Attempting to use 'oneline' callback.
Skipping callback 'oneline', as we already have a stdout callback.
Attempting to use 'tree' callback.
Attempting to use 'ansible.posix.profile_tasks' callback.
Loading callback plugin ansible.posix.profile_tasks of type aggregate, v2.0 from /usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/posix/plugins/callback/profile_tasks.py

PLAYBOOK: notepadplusplus.yml ***********************************************************************************************************************************************************************************************
Positional arguments: playbooks/notepadplusplus.yml
verbosity: 5
connection: smart
timeout: 10
become_method: sudo
tags: ('all',)
check: True
inventory: ('/opt/ansible/inventories/10_Site_Common.yml', '/opt/ansible/inventories/20a_Site_WRN_Test.yml', '/opt/ansible/inventories/20a_Site_WRN_ProdTest.yml', '/opt/ansible/inventories/20a_Site_WRN_ProdTest_291.yml', '/opt/ansible/inventories/20a_Site_WRN_ProdTest_292.yml', '/opt/ansible/inventories/20z_Development.yml')
subset: somemachine.EXAMPLE.COM
forks: 5
1 plays in playbooks/notepadplusplus.yml

PLAY [Deploy Notepad++] *****************************************************************************************************************************************************************************************************

TASK [Gathering Facts] ******************************************************************************************************************************************************************************************************
task path: /opt/ansible/playbooks/notepadplusplus.yml:3
Thursday 05 December 2024  05:53:45 +0000 (0:00:00.029)       0:00:00.029 ***** 
Loading collection viczem.keepass from /home/ansible/.ansible/collections/ansible_collections/viczem/keepass
KeePass: connect to '/tmp/ansible-keepass-9e61ddcf.sock'
exception during Jinja2 execution: Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/ansible/template/__init__.py", line 984, in _lookup
    ran = instance.run(loop_terms, variables=self._available_variables, **kwargs)
  File "/home/ansible/.ansible/collections/ansible_collections/viczem/keepass/plugins/lookup/keepass.py", line 154, in run
    return self._send(socket_path, "fetch", terms)
  File "/home/ansible/.ansible/collections/ansible_collections/viczem/keepass/plugins/lookup/keepass.py", line 161, in _send
    sock.connect(kp_soc)
ConnectionRefusedError: [Errno 111] Connection refused
fatal: [somemachine.EXAMPLE.COM]: FAILED! => {
    "msg": "An unhandled exception occurred while running the lookup plugin 'viczem.keepass.keepass'. Error was a <class 'ConnectionRefusedError'>, original message: [Errno 111] Connection refused. [Errno 111] Connection refused"
}

PLAY RECAP ******************************************************************************************************************************************************************************************************************
somemachine.EXAMPLE.COM : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    ignored=0   

Thursday 05 December 2024  05:53:46 +0000 (0:00:00.252)       0:00:00.282 ***** 
=============================================================================== 
Gathering Facts ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 0.25s
/opt/ansible/playbooks/notepadplusplus.yml:3 -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

The reason for the error:

An unhandled exception occurred while running the lookup plugin 'viczem.keepass.keepass'. Error was a <class 'ConnectionRefusedError'>, original message: [Errno 111] Connection refused. [Errno 111] Connection refused

could be tracked down to the use of unbuffer in my script. If I remove the "unbuffer" from the script, the playbook works correctly if called repeatedly. My investigations have shown that a lock file and the socket file of viczem.keepass.keepass are not cleaned up properly after execution of the playbook. To be precise: After ansible-playbook finishes. The following command shows what remains in the /tmp/ directory:

ansible@7c4670e0329b:/opt/ansible$ ls -la /tmp/
total 8
drwxrwxrwt 1 root    root    4096 Dec  5 05:53 .
drwxr-xr-x 1 root    root    4096 Dec  5 05:17 ..
srw------- 1 ansible ansible    0 Dec  5 05:25 ansible-keepass-9e61ddcf.sock
-rw------- 1 ansible ansible    0 Dec  5 05:25 ansible-keepass-9e61ddcf.sock.lock
srwxrwxr-x 1 ansible ansible    0 Dec  5 05:17 vscode-git-5449f56b2c.sock
srwxrwxr-x 1 ansible ansible    0 Dec  5 05:18 vscode-git-69fe405b86.sock
srwxrwxr-x 1 ansible ansible    0 Dec  5 05:18 vscode-ipc-7c3ccf14-f69d-45e3-84d5-7aca870cdf76.sock
srwxrwxr-x 1 ansible ansible    0 Dec  5 05:18 vscode-ipc-7c5270a5-5651-4f79-936d-ccfa3d41d6e7.sock
srwxrwxr-x 1 ansible ansible    0 Dec  5 05:17 vscode-ipc-9a116bb8-19ba-4764-a674-7670abc33495.sock
ansible@7c4670e0329b:/opt/ansible$ 

More explanation to the call to ansible-playbook as it is done in the script:

    unbuffer ansible-playbook -i inventories/10_Site_Common.yml \
                     -i inventories/20a_Site_WRN_Test.yml \
                     -i inventories/20a_Site_WRN_ProdTest.yml \
                     -i inventories/20a_Site_WRN_ProdTest_291.yml \
                     -i inventories/20a_Site_WRN_ProdTest_292.yml \
                     -i inventories/20z_Development.yml \
                     --limit $LIMIT \
                     $PLAYBOOK \
                     --check -vvvvv \
                     | tee >(sed -r 's/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]//g' > $LOGFILENAME)

• I split the inventory into multiple files for better handling of target hosts
• The variables $LIMIT, $LOGFILENAME and $PLAYBOOK are populated with (for me) meaningful values in the script before
• We always limit execution to not by accident execute the playbook on all target hosts
• The --check and -vvvvv are only there to provide input to this issue here and are not part of regular executions.
• unbuffer, tee and sed are used for the purpose of:
  • getting a log file of the ansible-playbook execution
  • retaining the console output for the user to see what happens
  • retaining the colors in the console output for the user to better judge on the outcome of the execution
  • having the logfile without escape characters that are responsible for coloring the UI
• The password of the keepass database file is provided through the environment variable ANSIBLE_KEEPASS_PSW before execution of the script

If I manually rm /tmp/ansible-keepass-* after execution of the above script, the issue is gone.

Also, if I call a modified bash script with the following content, the issue does not occur:

    ansible-playbook -i inventories/10_Site_Common.yml \
                     -i inventories/20a_Site_WRN_Test.yml \
                     -i inventories/20a_Site_WRN_ProdTest.yml \
                     -i inventories/20a_Site_WRN_ProdTest_291.yml \
                     -i inventories/20a_Site_WRN_ProdTest_292.yml \
                     -i inventories/20z_Development.yml \
                     --limit $LIMIT \
                     $PLAYBOOK \
                     --check -vvvvv \
                     | tee >(sed -r 's/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]//g' > $LOGFILENAME)

I suspect the handling of the lock file (creation and cleanup) to have problems with unbuffer.

For the time being I will just cleanup after ansible-playbook has run by removing the lock file and socket file manually, but maybe there is a way to fix it directly in ansible or the plugin?

Issue Type

Bug Report

Component Name

viczem.keepass.keepass

Ansible Version

$ ansible --version
ansible [core 2.13.13]
  config file = /opt/ansible/ansible.cfg
  configured module search path = ['/home/ansible/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.8/dist-packages/ansible
  ansible collection location = /home/ansible/.ansible/collections:/usr/share/ansible/collections
  executable location = /usr/local/bin/ansible
  python version = 3.8.10 (default, Nov  7 2024, 13:10:47) [GCC 9.4.0]
  jinja version = 3.1.4
  libyaml = True

Configuration

# if using a version older than ansible-core 2.12 you should omit the '-t all'
$ ansible-config dump --only-changed -t all
CALLBACKS_ENABLED(/opt/ansible/ansible.cfg) = ['ansible.posix.profile_tasks']

OS / Environment

$ cat /etc/os-release
NAME="Ubuntu"
VERSION="20.04.6 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 20.04.6 LTS"
VERSION_ID="20.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal

Steps to Reproduce

playbooks/notepadplusplus.yml

---

- name: Deploy Notepad++
  hosts:
  - npp
  roles:
  - { name: "notepadplusplus", tags: "notepadplusplus", when: not (done_role_notepadplusplus | default(false)) }
  tags:
  - notepadplusplus

playbooks/roles/tasks/notepadplusplus.yml

---

- name: Deploy Notepad++
  chocolatey.chocolatey.win_chocolatey:
    name: notepadplusplus
    version: "{{ notepadplusplus_version }}"
    state: present

- name: Mark role as visited
  set_fact: done_role_notepadplusplus=true

inventories/20a_Site_WRN_Test.yml

---

npp:
  hosts:
    somemachine.EXAMPLE.COM

... other inventory files' content is not relevant to reproduce.

ansible.cfg

[defaults]
callbacks_enabled=ansible.posix.profile_tasks

inventories/group_vars/all/common.yml

---

ansible_connection: winrm
ansible_port: 5985
ansible_winrm_kinit_mode: managed
ansible_winrm_transport: kerberos
ansible_winrm_realm: EXAMPLE.COM

keepass_dbx: "ansible.kdbx"
ansible_user: "{{ lookup('viczem.keepass.keepass', 'ansible.svc', 'username') }}"
ansible_username: "{{ lookup('viczem.keepass.keepass', 'ansible.svc', 'username') }}"
ansible_password: "{{ lookup('viczem.keepass.keepass', 'ansible.svc', 'password') }}"

notepadplusplus_version: '8.6.0'

Expected Results

The expectation is that ansible-playbook can be run multiple times in sequence through the above script, even if used together with unbuffer, tee and sed to get a log file, colored console output, etc. (see description for the whole list).

Actual Results

The first execution works, but subsequent executions fail with the error:

An unhandled exception occurred while running the lookup plugin 'viczem.keepass.keepass'. Error was a <class 'ConnectionRefusedError'>, original message: [Errno 111] Connection refused. [Errno 111] Connection refused

[viczem]

Sorry, I'm busy now and I'll get back to the issue later. Did you try running the KeePass socket before executing the ansible-playbook as described in the README?

export ANSIBLE_KEEPASS_PSW=mySecret
export ANSIBLE_KEEPASS_SOCKET=/home/build/.my-ansible-sock.${CI_JOB_ID}
export ANSIBLE_TTL=600 # 10 Minutes

/home/build/ansible-pyenv/bin/python3 /home/build/.ansible/roles/ansible_collections/viczem/keepass/plugins/lookup/keepass.py /path-to/my-keepass.kdbx &
ansible-playbook -v playbook1.yml
ansible-playbook -v playbook2.yml

For example, you can close the socket after playbook done by the command:
echo close | socat - UNIX-CONNECT:/home/build/.my-ansible-sock.${CI_JOB_ID}