mount - Masked shell errors in integration tests: tests succeed when it should fail

[NeodymiumFerBore]

SUMMARY

TLDR: This bug is not critical, but might be inconvenient in the future. The remounted state does work, but the integration tests succeed instead of failing due to syntax errors, masked errors and unreliable tests.

Integration tests for state remounted are bogus :

• the dumpe2fs commands to get last write time of the test filesystem are piped into a grep command with unquoted parameters: "cmd": "dumpe2fs /tmp/myfs.img 2>/dev/null | grep -i last write time: |cut -d: -f2-" instead of: "cmd": "dumpe2fs /tmp/myfs.img 2>/dev/null | grep -i 'last write time:' |cut -d: -f2-"

• The fail condition is also bogus. It fails when:

  • last_write is defined and
  • last_write_time2 is defined and
  • last_write_time.stdout == last_write_time2.stdout

The thing is, last_write is never defined. Defined variables are: last_write_time and last_write_time2. The first condition being never true, the fail is never triggered.

last_write_time.stdout == last_write_time2.stdout would be always true, because as we saw before, the dumpe2fs line fails. Therefore, their stdout is always "", and "" == "" is true.

Also, the shell error is ignored because the failed command (grep) is piped into cut. Which is at the end of the pipe chain. And it returns 0. So Ansible does not see the error.

Finally, using dumpe2fs is not a reliable way to check if the FS has been remounted (see the additional information section below). All these tests should be replaced, or future changes might break the module without notice. Honestly, I'm not sure what a good check would be. Maybe just switch between ro and rw options, and assert the diff from mount -v.

ISSUE TYPE

• Bug Report

COMPONENT NAME

mount

ANSIBLE VERSION

ansible [core 2.12.3]
  config file = None
  configured module search path = ['/home/ndfeb/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /DATA/venv/ansible-latest/lib/python3.8/site-packages/ansible
  ansible collection location = /home/ndfeb/.ansible/collections:/usr/share/ansible/collections
  executable location = /DATA/venv/ansible-latest/bin/ansible
  python version = 3.8.10 (default, Jun  2 2021, 10:49:15) [GCC 9.4.0]
  jinja version = 3.0.3
  libyaml = True

COLLECTION VERSION

# /DATA/venv/ansible-latest/lib/python3.8/site-packages/ansible_collections
Collection    Version
------------- -------
ansible.posix 1.3.0

This bug is also present in mainstream: in this code.

CONFIGURATION

(Default configuration from a fresh venv)

OS / ENVIRONMENT

$ lsb_release -a
Distributor ID:	Linuxmint
Description:	Linux Mint 20
Release:	20
Codename:	ulyana

$ docker --version
Docker version 20.10.8, build 3967b7d

STEPS TO REPRODUCE

$ python3 -m venv /tmp/test_ansible
$ source /tmp/test_ansible/bin/activate
$ python3 -m pip install --upgrade pip
$ python3 -m pip install ansible
$ # Grab a coffee

$ # ansible-test requires to be at the root dir of the collection
$ cd /tmp/test_ansible/lib/python3.8/site-packages/ansible_collections/ansible/posix
$ ansible-test integration -v mount --docker  ubuntu2004 --docker-privileged

$ # Now, in the output, look for 'No such file or directory'. You will get on several
$ # tasks "Get the last write time". You can see "stdout" being empty, the grep error from "stderr",
$ # and the "rc=0" returned by cut, masking the error to ansible.

EXPECTED RESULTS

• No "masked" errors in the integration tests
• Integration tests fail

ACTUAL RESULTS

• There are "masked" errors in the integration tests
• Integration tests succeed

(...)
TASK [mount : Mount the FS for the first time] *************************************************************************************************************************
changed: [testhost] => {"backup_file": "", "boot": "yes", "changed": true, "dump": "0", "fstab": "/etc/fstab", "fstype": "ext2", "name": "/tmp/myfs", "opts": "defaults", "passno": "0", "src": "/tmp/myfs.img"}

TASK [mount : Get the last write time] *********************************************************************************************************************************
changed: [testhost] => {"changed": true, "cmd": "dumpe2fs /tmp/myfs.img 2>/dev/null | grep -i last write time: |cut -d: -f2-", "delta": "0:00:00.002574", "end": "2022-03-20 17:01:42.437351", "msg": "", "rc": 0, "start": "2022-03-20 17:01:42.434777", "stderr": "grep: write: No such file or directory\ngrep: time:: No such file or directory", "stderr_lines": ["grep: write: No such file or directory", "grep: time:: No such file or directory"], "stdout": "", "stdout_lines": []}

TASK [mount : Wait 2 second] *******************************************************************************************************************************************
Pausing for 2 seconds
(ctrl+C then 'C' = continue early, ctrl+C then 'A' = abort)
ok: [testhost] => {"changed": false, "delta": 2, "echo": true, "rc": 0, "start": "2022-03-20 17:01:42.461207", "stderr": "", "stdout": "Paused for 2.0 seconds", "stop": "2022-03-20 17:01:44.461478", "user_input": ""}

TASK [mount : Test if the FS is remounted] *****************************************************************************************************************************
changed: [testhost] => {"backup_file": "", "boot": "yes", "changed": true, "dump": "0", "fstab": "/etc/fstab", "name": "/tmp/myfs", "opts": "defaults", "passno": "0"}

TASK [mount : Get again the last write time] ***************************************************************************************************************************
changed: [testhost] => {"changed": true, "cmd": "dumpe2fs /tmp/myfs.img 2>/dev/null | grep -i last write time: |cut -d: -f2-", "delta": "0:00:00.002478", "end": "2022-03-20 17:01:49.644824", "msg": "", "rc": 0, "start": "2022-03-20 17:01:49.642346", "stderr": "grep: write: No such file or directory\ngrep: time:: No such file or directory", "stderr_lines": ["grep: write: No such file or directory", "grep: time:: No such file or directory"], "stdout": "", "stdout_lines": []}

TASK [mount : Fail if they are the same] *******************************************************************************************************************************
skipping: [testhost] => {"changed": false, "skip_reason": "Conditional result was False"}
(...)

ADDTIONAL INFORMATION

I ran some tests by modifying the remount function, to show warnings during ansible-test. It appears that the dumpe2fs test is not reliable to test if the module actually remounted the FS. Mount options correctly change after the remount (so the module works), but the returned value from dumpe2fs (with correct quotes around grep parameters) does not change.

I'm a bit confused, as I 've got different results with different FS by trying to mount -o remount some FS on my system. Sometimes, e2dumpfs shows different last write times, sometimes it doesn't. I am not sure why. In the docker container running the tests, the last write time is not changing.

Here are the modifications I did to debug further: link to gist.

• The first "commit" contains mount.py and main.yml as they are shipped with version 1.3.0.
• Revision 2 contains my additions for debug purposes.
• Revision 3 contains the Ansible output with my additions. Relevant output: from line 268 to 299:
  • TASK [mount : Mount the FS for the first time] line 268
  • TASK [mount : DEBUG - Get last write time again] line 299
  • The output of my additions in mount.py can be found by looking for WILL BE EXECUTED in ansible_output. Example: line 280
  • Notice that the date/time gotten from TASK [mount : DEBUG - Get last write time again] matches the date present in the WARNINGS.

(Yes I took some time for this issue. But I struggled a long time debugging my own integration tests, when I realized that the older tests should also be failing. I was a bit upset 😇)

[NeodymiumFerBore]

To Maintainers: Side note: There are a lot of details for such a small bug. I just put the most I could so i can work on it later, without forgetting half the stuff.